Skip to content
This repository has been archived by the owner on Aug 30, 2023. It is now read-only.

Track playback end is not confirmed #7

Closed
OdinGitDat opened this issue Oct 24, 2020 · 17 comments
Closed

Track playback end is not confirmed #7

OdinGitDat opened this issue Oct 24, 2020 · 17 comments

Comments

@OdinGitDat
Copy link

The Jellyfin Lastfm plugin depends on track playback ending being confirmed to submit scrobbles. Here is what happens when the discord bot plays songs:

[20:48:34] [INF] [19] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Chaos Face, track=Flatland, album=Doom Ride,
[20:44:05] [INF] [40] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Chaos Face, track=Body Hammer, album=Doom Ride,
[20:38:45] [INF] [19] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Chaos Face, track=Scanner, album=Doom Ride,
[20:29:29] [INF] [129] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Chaos Face, track=Crash, album=Doom Ride,
[20:17:47] [INF] [129] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Chaos Face, track=Subhuman, album=Doom Ride

This is what happens when the web client plays songs:

[20:57:15] [INF] [129] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Paint Ain't Mine, album=Gremlin,
[20:59:14] [INF] [89] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Paint Ain't Mine, album=Gremlin,
[20:59:15] [INF] [90] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Extravaganza Live, album=Gremlin,
[21:00:28] [INF] [25] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Extravaganza Live, album=Gremlin,
[21:00:28] [INF] [52] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Style for Sale, album=Gremlin,
[21:01:36] [INF] [68] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Style for Sale, album=Gremlin,
[21:01:36] [INF] [22] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Dj Freaky Zhit, album=Gremlin,
[21:03:45] [INF] [12] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Dj Freaky Zhit, album=Gremlin,
[21:03:46] [INF] [109] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Bounce, album=Gremlin,
[21:04:48] [INF] [38] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Bounce, album=Gremlin,
[21:04:49] [INF] [38] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Hyphen, album=Gremlin,
[21:07:06] [INF] [40] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss played artist=ZelooperZ, track=Hyphen, album=Gremlin,
[21:07:07] [INF] [60] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=ZelooperZ, track=Lost Me, album=Gremlin

Difference is that the Discord bot doesn't confirm track playback finish so it doesn't get picked up by the Lastfm plugin.

Can't make a more detailed bug report before #6 is implemented.

@Artiume
Copy link
Contributor

Artiume commented Oct 26, 2020

similar issue with audiobooks

image

@OdinGitDat OdinGitDat changed the title Track playback end are not confirmed Track playback end is not confirmed Oct 26, 2020
@KGT1
Copy link
Owner

KGT1 commented Oct 26, 2020

I think i fixed it with ea61bfb, could you try out the latest nightly and see if it fixed the issue for you?

@OdinGitDat
Copy link
Author

OdinGitDat commented Oct 26, 2020

No, track endings are still not send, they also do not show up in the log. I'm on docker commit 7e773f4.

[13:35:18] [INF] [74] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Sophie, track=Hard, album=Product,
[13:33:17] [INF] [22] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Sophie, track=Lemonade, album=Product,
[13:31:20] [INF] [50] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Sophie, track=Lemonade, album=Product,
[13:27:34] [INF] [4] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Sophie, track=Elle, album=Product,
[13:24:31] [INF] [18] Jellyfin.Plugin.Lastfm.ServerEntryPoint: Odinoss is now playing artist=Sophie, track=Bipp, album=Product

@KGT1
Copy link
Owner

KGT1 commented Oct 26, 2020

hm thats wierd. Does it register the endings if you use the stop command?
I do send jellyfin playback stop whenever the player stops or a song is skiped. Allthough im still new to the jellyfin api so i might be doing something wrong

@Artiume
Copy link
Contributor

Artiume commented Oct 26, 2020

it seems fixed for me, I'll play a few more to verify

@OdinGitDat
Copy link
Author

OdinGitDat commented Oct 26, 2020

If it is fixed for @Artiume then I'm not sure that it's an issue with this bot anymore. I will make an issue on that repo too referencing this issue (jesseward/jellyfin-plugin-lastfm#27).

Btw, thanks for taking this obscure issue seriously 😃

@Artiume
Copy link
Contributor

Artiume commented Oct 26, 2020

Ok, it's still persisting for me, it's not fixed.

@Artiume
Copy link
Contributor

Artiume commented Oct 29, 2020

I feel like the issue for me is the websocket keeps closing which would prevent the updated status.

@KGT1
Copy link
Owner

KGT1 commented Oct 30, 2020

@Artiume but the updated status(stop playing song etc) isnt handeled over a websocket but rather via rest api calls

@Artiume
Copy link
Contributor

Artiume commented Oct 30, 2020

so even with 10 minute long clips, i get a bunch of unfinished clips. their saved position ranges from 5 minutes to 9 minutes.

https://gofile.io/d/pkL396

@KGT1
Copy link
Owner

KGT1 commented Nov 20, 2020

@Artiume I think i fixed it with the last commit, can you test? I dont really hear audiobooks thats why i havent really given much thought to them.

@Artiume
Copy link
Contributor

Artiume commented Nov 27, 2020

No success, here's the logs. I do find it weird it stopped at exactly 5 minutes for tracking.

[2020-11-27 00:16:38.224 -05:00] [INF] [33] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Discord Music Bot" "0.0.1" playing "Peace Talks: Dresden Files, Book 16". Stopped at "300000" ms

[2020-11-27 00:11:38.156 -05:00] [INF] [46] MediaBrowser.Api.Playback.MediaInfoService: User policy for "botjambox". EnableAudioPlaybackTranscoding: True
[2020-11-27 00:11:38.163 -05:00] [INF] [46] MediaBrowser.Api.Playback.MediaInfoService: Profile: "Unknown Profile", No direct play profiles found for Path: "/media/audiobooks/Jim Butcher/Dresden Files/16 - Peace Talks/Peace Talks The Dresden Files, Book 16 - 024.mp3"
[2020-11-27 00:11:38.178 -05:00] [INF] [46] MediaBrowser.Api.Playback.MediaInfoService: Profile: "Unknown Profile", No direct play profiles found for Path: "/media/audiobooks/Jim Butcher/Dresden Files/16 - Peace Talks/Peace Talks The Dresden Files, Book 16 - 024.mp3"
[2020-11-27 00:11:38.178 -05:00] [INF] [46] MediaBrowser.Api.Playback.MediaInfoService: Profile: "Unknown Profile", No direct play profiles found for Path: "/media/audiobooks/Jim Butcher/Dresden Files/16 - Peace Talks/Peace Talks The Dresden Files, Book 16 - 024.mp3"
[2020-11-27 00:11:38.261 -05:00] [INF] [42] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Adding playback tracker : botjambox-5bc381aad42c43ed9bfd5c99f509424b-f55477dadc77d5439
[2020-11-27 00:11:38.262 -05:00] [INF] [42] Jellyfin.Plugin.PlaybackReporting.Data.PlaybackTracker: PlaybackTracker : Adding Start Event : 11/27/2020 00:11:38
[2020-11-27 00:11:38.262 -05:00] [INF] [42] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Creating StartPlaybackTimer Task
[2020-11-27 00:11:38.264 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : Entered
[2020-11-27 00:11:38.280 -05:00] [INF] [63] MediaBrowser.Api.Playback.Hls.DynamicHlsService: /usr/lib/jellyfin-ffmpeg/ffmpeg -i file:"/media/audiobooks/Jim Butcher/Dresden Files/16 - Peace Talks/Peace Talks The Dresden Files, Book 16 - 024.mp3" -map_metadata -1 -map_chapters -1 -threads 0   -acodec libopus -ac 2 -vn -copyts -avoid_negative_ts disabled -f hls -max_delay 5000000 -hls_time 3 -individual_header_trailer 0 -hls_segment_type mpegts -start_number 0 -hls_segment_filename "/config/transcodes/f84430481b266fc6d4b3051d99ab16ef%d.mpegts" -hls_playlist_type vod -hls_list_size 0 -y "/config/transcodes/f84430481b266fc6d4b3051d99ab16ef.m3u8"
[2020-11-27 00:11:39.204 -05:00] [INF] [42] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Processing playback tracker : "botjambox-5bc381aad42c43-f55477dadc77d54f91291685bb47a839"
[2020-11-27 00:11:39.537 -05:00] [WRN] [42] Emby.Server.Implementations.HttpServer.HttpListenerHost: HTTP Response 200 to "172.18.0.7". Time (slow): 0:00:01.2915256. "http://172.18.0.20:8096/Audio/f55477da-dc77-d54f-9129/hls1/main/0.mpegts?UserId=5bc381aad42c43e&DeviceId=botjambox&MaxStreamingBitrate=96000&Container=ogg,opus&AudioCodec=opus&TranscodingContainer=ts&TranscodingProtocol=hls&SegmentContainer=mpegts&TranscodeReasons=ContainerNotSupported,AudioCodecNotSupported"
[2020-11-27 00:11:46.587 -05:00] [INF] [46] MediaBrowser.Api.Playback.Hls.DynamicHlsService: FFMpeg exited with code 0
[2020-11-27 00:11:58.271 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: session.RemoteEndPoint : "172.18.0.7"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : event_playing_id     = "f55477dadc77d5"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : event_user_id        = "5bc381aad42c43ed9bf"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : event_user_id_int    = 4
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : session_playing_id   = "f55477dadc77d54f9"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : session_user_id      = "5bc381aad42c43ed9"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : play_method          = "DirectPlay"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : e.ClientName         = "Discord Music Bot"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : e.DeviceName         = "botjambox"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : ItemName             = "Peace Talks: Dresden Files, Book 16"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : ItemId               = "f55477dadc77d54f91291685bb47a839"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : ItemType             = "AudioBook"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : All matches, playback registered
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Playback tracker found, adding playback info : "botjambox-5bc381aad42c43ed9bfd5c99f509424b-f55477dadc77d54f91291685bb47a839"
[2020-11-27 00:11:58.274 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Saving playback tracking activity in DB
[2020-11-27 00:11:58.284 -05:00] [INF] [32] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: StartPlaybackTimer : Exited
[2020-11-27 00:12:00.199 -05:00] [INF] [87] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Processing playback tracker : "botjambox-5bc381aad42c43ed9bfd5c99f509424b-f55477dadc77d54f91291685bb47a839"
Truncated Logs
[2020-11-27 00:16:26.199 -05:00] [INF] [43] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Processing playback tracker : "botjambox-5bc381aad42c43ed9bfd5c99f509424b-f55477dadc77d54f91291685bb47a839"
[2020-11-27 00:16:38.224 -05:00] [INF] [33] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Discord Music Bot" "0.0.1" playing "Peace Talks: Dresden Files, Book 16". Stopped at "300000" ms
[2020-11-27 00:16:38.252 -05:00] [INF] [89] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Playback stop tracker found, processing stop : "botjambox-5bc381aad42c43ed9bfd5c99f509424b-f55477dadc77d54f91291685bb47a839"
[2020-11-27 00:16:38.253 -05:00] [INF] [89] Jellyfin.Plugin.PlaybackReporting.Data.PlaybackTracker: PlaybackTracker : Adding Stop Event : 11/27/2020 00:16:38
[2020-11-27 00:16:38.253 -05:00] [INF] [89] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Saving playback tracking activity in DB
[2020-11-27 00:25:27.607 -05:00] [WRN] [96] Emby.Server.Implementations.Activity.ActivityLogEntryPoint: PlaybackStart reported with null media info.
[2020-11-27 00:25:27.606 -05:00] [ERR] [97] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request. URL: "http://172.18.0.20:8096/Audio/undefined/universal?UserId=5bc381aad42c43&DeviceId=botjambox&MaxStreamingBitrate=96000&Container=ogg,opus&AudioCodec=opus&TranscodingContainer=ts&TranscodingProtocol=hls"
System.FormatException: Input string was not in a correct format.
   at ServiceStack.Text.DefaultMemory.ParseGeneralStyleGuid(ReadOnlySpan`1 value, Int32& len) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\DefaultMemory.cs:line 629
   at ServiceStack.Text.DefaultMemory.ParseGuid(ReadOnlySpan`1 value) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\DefaultMemory.cs:line 414
   at ServiceStack.Text.Common.DeserializeBuiltin`1.<>c.<GetParseStringSpanFn>b__7_6(ReadOnlySpan`1 value) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\Common\DeserializeBuiltin.cs:line 72
   at ServiceStack.Text.Jsv.JsvReader.<>c__DisplayClass2_0.<GetParseFn>b__0(String v) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\Jsv\JsvReader.Generic.cs:line 18
   at Emby.Server.Implementations.Services.StringMapTypeDeserializer.PopulateFromMap(Object instance, IDictionary`2 keyValuePairs)
   at Emby.Server.Implementations.Services.RestPath.CreateRequest(String pathInfo, Dictionary`2 queryStringAndFormData, Object fromInstance)
   at Emby.Server.Implementations.Services.ServiceHandler.CreateRequest(IRequest httpReq, RestPath restPath, Dictionary`2 requestParams, Object requestDto)
   at Emby.Server.Implementations.Services.ServiceHandler.CreateRequest(HttpListenerHost host, IRequest httpReq, RestPath restPath, ILogger logger)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-11-27 00:25:27.634 -05:00] [WRN] [96] Emby.Server.Implementations.Activity.ActivityLogEntryPoint: PlaybackStart reported with null media info.
[2020-11-27 00:25:27.636 -05:00] [ERR] [100] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request. URL: "http://172.18.0.20:8096/Audio/undefined/universal?UserId=5bc381aad42c43ed&DeviceId=botjambox&MaxStreamingBitrate=96000&Container=ogg,opus&AudioCodec=opus&TranscodingContainer=ts&TranscodingProtocol=hls"
System.FormatException: Input string was not in a correct format.
   at ServiceStack.Text.DefaultMemory.ParseGeneralStyleGuid(ReadOnlySpan`1 value, Int32& len) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\DefaultMemory.cs:line 629
   at ServiceStack.Text.DefaultMemory.ParseGuid(ReadOnlySpan`1 value) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\DefaultMemory.cs:line 414
   at ServiceStack.Text.Common.DeserializeBuiltin`1.<>c.<GetParseStringSpanFn>b__7_6(ReadOnlySpan`1 value) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\Common\DeserializeBuiltin.cs:line 72
   at ServiceStack.Text.Jsv.JsvReader.<>c__DisplayClass2_0.<GetParseFn>b__0(String v) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\Jsv\JsvReader.Generic.cs:line 18
   at Emby.Server.Implementations.Services.StringMapTypeDeserializer.PopulateFromMap(Object instance, IDictionary`2 keyValuePairs)
   at Emby.Server.Implementations.Services.RestPath.CreateRequest(String pathInfo, Dictionary`2 queryStringAndFormData, Object fromInstance)
   at Emby.Server.Implementations.Services.ServiceHandler.CreateRequest(IRequest httpReq, RestPath restPath, Dictionary`2 requestParams, Object requestDto)
   at Emby.Server.Implementations.Services.ServiceHandler.CreateRequest(HttpListenerHost host, IRequest httpReq, RestPath restPath, ILogger logger)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-11-27 00:25:27.650 -05:00] [ERR] [96] Emby.Server.Implementations.Session.SessionManager: Error in event handler
System.NullReferenceException: Object reference not set to an instance of an object.
   at Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint._sessionManager_PlaybackStop(Object sender, PlaybackStopEventArgs e)
   at MediaBrowser.Common.Events.EventHelper.<>c__DisplayClass1_0`1.<QueueEventIfNotNull>b__0()
[2020-11-27 01:37:21.135 -05:00] [INF] [219] Emby.Server.Implementations.HttpServer.HttpListenerHost: WS "::ffff:172.18.0.5" closed
[2020-11-27 01:37:26.904 -05:00] [ERR] [220] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request: "The operation was canceled". URL: "http://domain/web/favicon.ico"
[2020-11-27 01:37:26.905 -05:00] [ERR] [221] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request: "The operation was canceled". URL: "http://domain/web/touchicon.png"
[2020-11-27 01:37:31.638 -05:00] [INF] [219] Emby.Server.Implementations.HttpServer.HttpListenerHost: WS "::ffff:172.18.0.5" request
[2020-11-27 01:38:53.726 -05:00] [INF] [210] Emby.Server.Implementations.HttpServer.HttpListenerHost: WS "::ffff:172.18.0.5" request

test

@OdinGitDat
Copy link
Author

This may give a clue: PlaybackProgressEventArgs. As per this comment: jesseward/jellyfin-plugin-lastfm#27 (comment)

@KGT1
Copy link
Owner

KGT1 commented Jan 17, 2021

I think the issue here was, that the wrong itemId was used when reporting playbackstop when playback finished for 1 song. Fixed that with the latest commit

@OdinGitDat
Copy link
Author

I just tested it and it's not fixed.

@KGT1
Copy link
Owner

KGT1 commented Jan 18, 2021

@OdinGitDat I added a basic debug mode and fixed some things. Can you maybe try again with the latest nightly, add "-e LOG_LEVEL="debug"" to the docker and return with your logs?

@OdinGitDat
Copy link
Author

Yes, it works now. Thanks for your dedication to this!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants