Fix jellyfin edge case scrobbling mess

Finally get to resolve scrobbling music from Jellyfin. This may lead to
other issues, in fact now videos seem to sometimes create duplicate
scrobbles. But music can be scrobbled now from Jellyfin web or Finamp
successfully.

vrobbler/apps/scrobbles/mixins.py

@@ -7,6 +7,8 @@ BNULL = {"blank": True, "null": True}
 
 
 class ScrobblableMixin(TimeStampedModel):
+    SECONDS_TO_STALE = 1600
+
     uuid = models.UUIDField(default=uuid4, editable=False, **BNULL)
     title = models.CharField(max_length=255, **BNULL)
     run_time = models.CharField(max_length=8, **BNULL)

vrobbler/apps/scrobbles/models.py

@@ -11,6 +11,7 @@ from podcasts.models import Episode
 from scrobbles.utils import check_scrobble_for_finish
 from sports.models import SportEvent
 from videos.models import Series, Video
+from vrobbler.apps.profiles.utils import now_user_timezone
 
 logger = logging.getLogger(__name__)
 User = get_user_model()
@@ -146,6 +147,8 @@ class ChartRecord(TimeStampedModel):
 
 
 class Scrobble(TimeStampedModel):
+    """A scrobble tracks played media items by a user."""
+
     uuid = models.UUIDField(editable=False, **BNULL)
     video = models.ForeignKey(Video, on_delete=models.DO_NOTHING, **BNULL)
     track = models.ForeignKey(Track, on_delete=models.DO_NOTHING, **BNULL)
@@ -184,24 +187,44 @@ class Scrobble(TimeStampedModel):
             return 'in-progress'
         return 'zombie'
 
+    @property
+    def is_stale(self) -> bool:
+        """Mark scrobble as stale if it's been more than an hour since it was updated"""
+        is_stale = False
+        now = timezone.now()
+        seconds_since_last_update = (now - self.modified).seconds
+        if seconds_since_last_update >= self.media_obj.SECONDS_TO_STALE:
+            is_stale = True
+        return is_stale
+
     @property
     def percent_played(self) -> int:
         if not self.media_obj.run_time_ticks:
-            logger.warning(
-                f"{self} has no run_time_ticks value, cannot show percent played"
-            )
+            return 100
+
+        if not self.playback_position_ticks and self.played_to_completion:
             return 100
 
         playback_ticks = self.playback_position_ticks
         if not playback_ticks:
             playback_ticks = (timezone.now() - self.timestamp).seconds * 1000
 
-            if self.played_to_completion:
-                return 100
-
         percent = int((playback_ticks / self.media_obj.run_time_ticks) * 100)
+        if percent > 100:
+            percent = 100
         return percent
 
+    @property
+    def can_be_updated(self) -> bool:
+        updatable = True
+        if self.percent_played > 100:
+            logger.info(f"No - 100% played - {self.id} - {self.source}")
+            updatable = False
+        if self.is_stale:
+            logger.info(f"No - stale - {self.id} - {self.source}")
+            updatable = False
+        return updatable
+
     @property
     def media_obj(self):
         media_obj = None
@@ -220,158 +243,71 @@ class Scrobble(TimeStampedModel):
         return f"Scrobble of {self.media_obj} ({timestamp})"
 
     @classmethod
-    def create_or_update_for_video(
-        cls, video: "Video", user_id: int, scrobble_data: dict
+    def create_or_update(
+        cls, media, user_id: int, scrobble_data: dict
     ) -> "Scrobble":
-        scrobble_data['video_id'] = video.id
+
+        if media.__class__.__name__ == 'Track':
+            media_query = models.Q(track=media)
+            scrobble_data['track_id'] = media.id
+        if media.__class__.__name__ == 'Video':
+            media_query = models.Q(video=media)
+            scrobble_data['video_id'] = media.id
+        if media.__class__.__name__ == 'Episode':
+            media_query = models.Q(podcast_episode=media)
+            scrobble_data['podcast_id'] = media.id
+        if media.__class__.__name__ == 'SportEvent':
+            media_query = models.Q(sport_event=media)
+            scrobble_data['sport_event_id'] = media.id
 
         scrobble = (
             cls.objects.filter(
-                video=video,
+                media_query,
                 user_id=user_id,
             )
             .order_by('-modified')
             .first()
         )
-        if scrobble and scrobble.percent_played <= 100:
+        if scrobble and scrobble.can_be_updated:
             logger.info(
-                f"Found existing scrobble for video {video}, updating",
-                {"scrobble_data": scrobble_data},
+                f"Updating {scrobble.id}",
+                {"scrobble_data": scrobble_data, "media": media},
             )
-            return cls.update(scrobble, scrobble_data)
+            return scrobble.update(scrobble_data)
 
-        logger.debug(
-            f"No existing scrobble for video {video}, creating",
-            {"scrobble_data": scrobble_data},
-        )
-        # If creating a new scrobble, we don't need status
-        scrobble_data.pop('jellyfin_status')
-        return cls.create(scrobble_data)
-
-    @classmethod
-    def create_or_update_for_track(
-        cls, track: "Track", user_id: int, scrobble_data: dict
-    ) -> "Scrobble":
-        """Look up any existing scrobbles for a track and compare
-        the appropriate backoff time for music tracks to the setting
-        so we can avoid duplicating scrobbles."""
-        scrobble_data['track_id'] = track.id
-
-        scrobble = (
-            cls.objects.filter(
-                track=track,
-                user_id=user_id,
-                played_to_completion=False,
-            )
-            .order_by('-modified')
-            .first()
-        )
-        if scrobble:
-            logger.debug(
-                f"Found existing scrobble for track {track}, updating",
-                {"scrobble_data": scrobble_data},
-            )
-            return cls.update(scrobble, scrobble_data)
-
-        if 'jellyfin_status' in scrobble_data.keys():
-            last_scrobble = Scrobble.objects.last()
-            if (
-                scrobble_data['timestamp'] - last_scrobble.timestamp
-            ).seconds <= 1:
-                logger.warning('Jellyfin spammed us with duplicate updates')
-                return last_scrobble
-
-        logger.debug(
-            f"No existing scrobble for track {track}, creating",
-            {"scrobble_data": scrobble_data},
+        source = scrobble_data['source']
+        logger.info(
+            f"Creating for {media.id} - {source}",
+            {"scrobble_data": scrobble_data, "media": media},
         )
         # If creating a new scrobble, we don't need status
         scrobble_data.pop('mopidy_status', None)
         scrobble_data.pop('jellyfin_status', None)
         return cls.create(scrobble_data)
 
-    @classmethod
-    def create_or_update_for_podcast_episode(
-        cls, episode: "Episode", user_id: int, scrobble_data: dict
-    ) -> "Scrobble":
-        scrobble_data['podcast_episode_id'] = episode.id
-
-        scrobble = (
-            cls.objects.filter(
-                podcast_episode=episode,
-                user_id=user_id,
-                played_to_completion=False,
-            )
-            .order_by('-modified')
-            .first()
-        )
-        if scrobble:
-            logger.debug(
-                f"Found existing scrobble for podcast {episode}, updating",
-                {"scrobble_data": scrobble_data},
-            )
-            return cls.update(scrobble, scrobble_data)
-
-        logger.debug(
-            f"No existing scrobble for podcast epsiode {episode}, creating",
-            {"scrobble_data": scrobble_data},
-        )
-        # If creating a new scrobble, we don't need status
-        scrobble_data.pop('mopidy_status')
-        return cls.create(scrobble_data)
-
-    @classmethod
-    def create_or_update_for_sport_event(
-        cls, event: "SportEvent", user_id: int, scrobble_data: dict
-    ) -> "Scrobble":
-        scrobble_data['sport_event_id'] = event.id
-        scrobble = (
-            cls.objects.filter(
-                sport_event=event,
-                user_id=user_id,
-                played_to_completion=False,
-            )
-            .order_by('-modified')
-            .first()
-        )
-        if scrobble:
-            logger.debug(
-                f"Found existing scrobble for sport event {event}, updating",
-                {"scrobble_data": scrobble_data},
-            )
-            return cls.update(scrobble, scrobble_data)
-
-        logger.debug(
-            f"No existing scrobble for sport event {event}, creating",
-            {"scrobble_data": scrobble_data},
-        )
-        # If creating a new scrobble, we don't need status
-        scrobble_data.pop('jellyfin_status')
-        return cls.create(scrobble_data)
-
-    @classmethod
-    def update(cls, scrobble: "Scrobble", scrobble_data: dict) -> "Scrobble":
+    def update(self, scrobble_data: dict) -> "Scrobble":
         # Status is a field we get from Mopidy, which refuses to poll us
         scrobble_status = scrobble_data.pop('mopidy_status', None)
         if not scrobble_status:
             scrobble_status = scrobble_data.pop('jellyfin_status', None)
 
-        logger.debug(f"Scrobbling to {scrobble} with status {scrobble_status}")
-        scrobble.update_ticks(scrobble_data)
+        if self.percent_played < 100:
+            # Only worry about ticks if we haven't gotten to the end
+            self.update_ticks(scrobble_data)
 
         # On stop, stop progress and send it to the check for completion
         if scrobble_status == "stopped":
-            scrobble.stop()
+            self.stop()
         # On pause, set is_paused and stop scrobbling
         if scrobble_status == "paused":
-            scrobble.pause()
+            self.pause()
         if scrobble_status == "resumed":
-            scrobble.resume()
+            self.resume()
 
         for key, value in scrobble_data.items():
-            setattr(scrobble, key, value)
-        scrobble.save()
-        return scrobble
+            setattr(self, key, value)
+        self.save()
+        return self
 
     @classmethod
     def create(
@@ -386,27 +322,27 @@ class Scrobble(TimeStampedModel):
 
     def stop(self, force_finish=False) -> None:
         if not self.in_progress:
-            logger.warning("Scrobble already stopped")
             return
         self.in_progress = False
         self.save(update_fields=['in_progress'])
+        logger.info(f"{self.id} - {self.source}")
         check_scrobble_for_finish(self, force_finish)
 
     def pause(self) -> None:
-        print('Trying to pause it')
         if self.is_paused:
-            logger.warning("Scrobble already paused")
+            logger.warning(f"{self.id} - already paused - {self.source}")
             return
         self.is_paused = True
         self.save(update_fields=["is_paused"])
+        logger.info(f"{self.id} - pausing - {self.source}")
         check_scrobble_for_finish(self)
 
     def resume(self) -> None:
         if self.is_paused or not self.in_progress:
             self.is_paused = False
             self.in_progress = True
+            logger.info(f"{self.id} - resuming - {self.source}")
             return self.save(update_fields=["is_paused", "in_progress"])
-        logger.warning("Resume called but in progress or not paused")
 
     def cancel(self) -> None:
         check_scrobble_for_finish(self, force_finish=True)
@@ -415,8 +351,8 @@ class Scrobble(TimeStampedModel):
     def update_ticks(self, data) -> None:
         self.playback_position_ticks = data.get("playback_position_ticks")
         self.playback_position = data.get("playback_position")
-        logger.debug(
-            f"Updating scrobble ticks to {self.playback_position_ticks}"
+        logger.info(
+            f"{self.id} - {self.playback_position_ticks} - {self.source}"
         )
         self.save(
             update_fields=['playback_position_ticks', 'playback_position']

vrobbler/apps/scrobbles/scrobblers.py

@@ -50,9 +50,7 @@ def mopidy_scrobble_podcast(
 
     scrobble = None
     if episode:
-        scrobble = Scrobble.create_or_update_for_podcast_episode(
-            episode, user_id, mopidy_data
-        )
+        scrobble = Scrobble.create_or_update(episode, user_id, mopidy_data)
     return scrobble
 
 
@@ -90,23 +88,26 @@ def mopidy_scrobble_track(
     track.musicbrainz_id = data_dict.get("musicbrainz_track_id")
     track.save()
 
-    scrobble = Scrobble.create_or_update_for_track(track, user_id, mopidy_data)
+    scrobble = Scrobble.create_or_update(track, user_id, mopidy_data)
 
     return scrobble
 
 
-def create_jellyfin_scrobble_dict(data_dict: dict, user_id: int) -> dict:
+def build_scrobble_dict(data_dict: dict, user_id: int) -> dict:
     jellyfin_status = "resumed"
     if data_dict.get("IsPaused"):
         jellyfin_status = "paused"
-    if data_dict.get("NotificationType") == 'PlaybackStop':
+    elif data_dict.get("NotificationType") == 'PlaybackStop':
         jellyfin_status = "stopped"
 
+    playback_ticks = data_dict.get("PlaybackPositionTicks", "")
+    if playback_ticks:
+        playback_ticks = playback_ticks // 10000
+
     return {
         "user_id": user_id,
         "timestamp": parse(data_dict.get("UtcTimestamp")),
-        "playback_position_ticks": data_dict.get("PlaybackPositionTicks", "")
-        // 10000,
+        "playback_position_ticks": playback_ticks,
         "playback_position": data_dict.get("PlaybackPosition", ""),
         "source": data_dict.get("ClientName", "Vrobbler"),
         "source_id": data_dict.get('MediaSourceId'),
@@ -119,11 +120,22 @@ def jellyfin_scrobble_track(
 ) -> Optional[Scrobble]:
 
     if not data_dict.get("Provider_musicbrainztrack", None):
+        # TODO we should be able to look up tracks via MB rather than error out
         logger.error(
             "No MBrainz Track ID received. This is likely because all metadata is bad, not scrobbling"
         )
         return
 
+    null_position_on_progress = (
+        data_dict.get("PlaybackPosition") == "00:00:00"
+        and data_dict.get("NotificationType") == "PlaybackProgress"
+    )
+
+    # Jellyfin has some race conditions with it's webhooks, these hacks fix some of them
+    if not data_dict.get("PlaybackPositionTicks") or null_position_on_progress:
+        logger.error("No playback position tick from Jellyfin, aborting")
+        return
+
     artist_dict = {
         'name': data_dict.get(JELLYFIN_POST_KEYS["ARTIST_NAME"], None),
         'musicbrainz_id': data_dict.get(
@@ -157,9 +169,13 @@ def jellyfin_scrobble_track(
         )
         track.save()
 
-    scrobble_dict = create_jellyfin_scrobble_dict(data_dict, user_id)
+    scrobble_dict = build_scrobble_dict(data_dict, user_id)
 
-    return Scrobble.create_or_update_for_track(track, user_id, scrobble_dict)
+    # A hack to make Jellyfin work more like Mopidy for music tracks
+    scrobble_dict["playback_position_ticks"] = 0
+    scrobble_dict["playback_position"] = ""
+
+    return Scrobble.create_or_update(track, user_id, scrobble_dict)
 
 
 def jellyfin_scrobble_video(data_dict: dict, user_id: Optional[int]):
@@ -170,9 +186,9 @@ def jellyfin_scrobble_video(data_dict: dict, user_id: Optional[int]):
         return
     video = Video.find_or_create(data_dict)
 
-    scrobble_dict = create_jellyfin_scrobble_dict(data_dict, user_id)
+    scrobble_dict = build_scrobble_dict(data_dict, user_id)
 
-    return Scrobble.create_or_update_for_video(video, user_id, scrobble_dict)
+    return Scrobble.create_or_update(video, user_id, scrobble_dict)
 
 
 def manual_scrobble_video(data_dict: dict, user_id: Optional[int]):
@@ -183,9 +199,9 @@ def manual_scrobble_video(data_dict: dict, user_id: Optional[int]):
         return
     video = Video.find_or_create(data_dict)
 
-    scrobble_dict = create_jellyfin_scrobble_dict(data_dict, user_id)
+    scrobble_dict = build_scrobble_dict(data_dict, user_id)
 
-    return Scrobble.create_or_update_for_video(video, user_id, scrobble_dict)
+    return Scrobble.create_or_update(video, user_id, scrobble_dict)
 
 
 def manual_scrobble_event(data_dict: dict, user_id: Optional[int]):
@@ -196,8 +212,6 @@ def manual_scrobble_event(data_dict: dict, user_id: Optional[int]):
         return
     event = SportEvent.find_or_create(data_dict)
 
-    scrobble_dict = create_jellyfin_scrobble_dict(data_dict, user_id)
+    scrobble_dict = build_scrobble_dict(data_dict, user_id)
 
-    return Scrobble.create_or_update_for_sport_event(
-        event, user_id, scrobble_dict
-    )
+    return Scrobble.create_or_update(event, user_id, scrobble_dict)

vrobbler/apps/scrobbles/utils.py

@@ -67,18 +67,36 @@ def parse_mopidy_uri(uri: str) -> dict:
 
 
 def check_scrobble_for_finish(
-    scrobble: "Scrobble", force_finish=False
+    scrobble: "Scrobble", force_to_100=False, force_finish=False
 ) -> None:
     completion_percent = scrobble.media_obj.COMPLETION_PERCENT
 
     if scrobble.percent_played >= completion_percent or force_finish:
-        logger.debug(f"Completion percent {completion_percent} met, finishing")
+        logger.info(f"{scrobble.id} {completion_percent} met, finishing")
+
+        if (
+            scrobble.playback_position_ticks
+            and scrobble.media_obj.run_time_ticks
+            and force_to_100
+        ):
+            scrobble.playback_position_ticks = (
+                scrobble.media_obj.run_time_ticks
+            )
+            logger.info(
+                f"{scrobble.playback_position_ticks} set to {scrobble.media_obj.run_time_ticks}"
+            )
 
         scrobble.in_progress = False
         scrobble.is_paused = False
         scrobble.played_to_completion = True
+
         scrobble.save(
-            update_fields=["in_progress", "is_paused", "played_to_completion"]
+            update_fields=[
+                "in_progress",
+                "is_paused",
+                "played_to_completion",
+                'playback_position_ticks',
+            ]
         )
 
     if scrobble.percent_played % 5 == 0:

vrobbler/apps/scrobbles/views.py

@@ -130,7 +130,7 @@ class ManualScrobbleView(FormView):
             if data_dict:
                 manual_scrobble_event(data_dict, self.request.user.id)
 
-        return HttpResponseRedirect(reverse("home"))
+        return HttpResponseRedirect(reverse("vrobbler-home"))
 
 
 class JsonableResponseMixin:
@@ -182,6 +182,12 @@ def scrobble_endpoint(request):
 def jellyfin_websocket(request):
     data_dict = request.data
 
+    if (
+        data_dict['NotificationType'] == 'PlaybackProgress'
+        and data_dict['ItemType'] == 'Audio'
+    ):
+        return Response({}, status=status.HTTP_304_NOT_MODIFIED)
+
     # For making things easier to build new input processors
     if getattr(settings, "DUMP_REQUEST_DATA", False):
         json_data = json.dumps(data_dict, indent=4)

vrobbler/apps/sports/models.py

@@ -49,7 +49,12 @@ class Sport(TheSportsDbMixin):
     # run_time_ticks = run_time_seconds * 1000
     @property
     def default_event_run_time_ticks(self):
-        return self.default_event_run_time * 1000
+        default_run_time = getattr(
+            settings, 'DEFAULT_EVENT_RUNTIME_SECONDS', 14400
+        )
+        if self.default_event_run_time:
+            default_run_time = self.default_event_run_time
+        return default_run_time * 1000
 
 
 class League(TheSportsDbMixin):

vrobbler/apps/videos/models.py

@@ -34,6 +34,7 @@ class Series(TimeStampedModel):
 
 class Video(ScrobblableMixin):
     COMPLETION_PERCENT = getattr(settings, 'VIDEO_COMPLETION_PERCENT', 90)
+    SECONDS_TO_STALE = getattr(settings, 'VIDEO_SECONDS_TO_STALE', 14400)
 
     class VideoType(models.TextChoices):
         UNKNOWN = 'U', _('Unknown')
@@ -91,10 +92,6 @@ class Video(ScrobblableMixin):
             series, series_created = Series.objects.get_or_create(
                 name=series_name
             )
-            if series_created:
-                logger.debug(f"Created new series {series}")
-            else:
-                logger.debug(f"Found series {series}")
             video_dict['video_type'] = Video.VideoType.TV_EPISODE
 
         video, created = cls.objects.get_or_create(**video_dict)
@@ -119,11 +116,8 @@ class Video(ScrobblableMixin):
             video_extra_dict["tv_series_id"] = series.id
 
         if not video.run_time_ticks:
-            logger.debug(f"Created new video: {video}")
             for key, value in video_extra_dict.items():
                 setattr(video, key, value)
             video.save()
-        else:
-            logger.debug(f"Found video {video}")
 
         return video