FoxxMD / multi-scrobbler

Scrobble plays from multiple sources to multiple clients
https://foxxmd.github.io/multi-scrobbler
MIT License
299 stars 14 forks source link

Jellyfin spams logs with "media type was not 'Audio', found type: undefined {}" #101

Closed tabithamoon closed 9 months ago

tabithamoon commented 9 months ago

Please check the FAQ before submitting a bug report.

Describe the bug Jellyfin sends second by second updates to multi-scrobbler which dumps Will not scrobble event because media type was not 'Audio', found type: undefined {} errors in the log. This results in the current playback position in seconds being updated only every minute or so.

To Reproduce

  1. Set up webhook on Jellyfin
  2. Begin playback on any client

Expected behavior Second by second playback status information updates, and no errors flooding into the logs.

Logs

[begins playback]
2023-09-26T11:23:11-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:23:11-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:23:11-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:23:11-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:23:11-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:23:12-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true

[later...]

2023-09-26T11:24:03-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:04-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:04-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:05-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:05-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:06-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Squaredance","Artist":"Kitsune²","Audio_0_Bitrate":916922,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","ClientName":"Android","DeviceId":"BC9311B570ABE4BD71EEEC0856A448AD","DeviceName":"samsung SM-S901E","IsAutomated":true,"IsPaused":false,"ItemId":"a8f15b29fdb162df7c91d4aa95ef10df","ItemType":"Audio","MediaSourceId":"a8f15b29fdb162df7c91d4aa95ef10df","Name":"Squaredance","NotificationType":"PlaybackProgress","NotificationUsername":"Tabitha","Overview":"","PlaybackPosition":"00:00:55","PlaybackPositionTicks":550000000,"Provider_musicbrainzalbum":"20d76f22-b42f-4704-90d0-10ee3508ec89","Provider_musicbrainzalbumartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzreleasegroup":"c75e0af7-ac3a-41ba-8674-43060200ecd7","Provider_musicbrainztrack":"fb64dc69-f581-32d8-95dd-355f7df6e498","RunTime":"00:02:43","RunTimeTicks":1638661248,"ServerId":"6c41d884a9c1490f8fd0863e04d75a69","ServerName":"maine","ServerUrl":"<redacted>","ServerVersion":"10.8.10","Tagline":"","Timestamp":"2023-09-26T11:24:06.8974676-03:00","UserId":"6d23c30c5e9d4ec6a66db6b05b63e516","UtcTimestamp":"2023-09-26T14:24:06.8974696Z","Year":2009}
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] Incoming play state ((a8f15b29fdb162df7c91d4aa95ef10df) Kitsune² - Squaredance) does not match existing state, removing existing: (514941104216969e74a8d87fc7893ad5) Kitsune² - Brother Madonna
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] New Play: (a8f15b29fdb162df7c91d4aa95ef10df) Kitsune² - Squaredance
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] Started new Player listen range.
2023-09-26T11:24:07-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:07-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:08-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:08-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:09-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true

Versions:

Additional context Tested with Symphonium and the official Jellyfin Android app.

tabithamoon commented 9 months ago

Of note: Setting up a simple HTTP server to log Jellyfin's POST requests show this being posted every second:

POST / HTTP/1.1
Host: 172.24.2.1:9009
User-Agent: Jellyfin-Server/10.8.10
Accept: application/json; q=1.0, application/xml; q=0.9, */*; q=0.8
Accept-Encoding: gzip, deflate, br
traceparent: 00-68e8cacd2e8fd0b5b6f9e0fd7f1ead74-df8ce0781cccc083-00
Content-Type: text/plain; charset=utf-8
Content-Length: 1389

{"ServerId":"6c41d884a9c1490f8fd0863e04d75a69","ServerName":"maine","ServerVersion":"10.8.10","ServerUrl":"<redacted>","NotificationType":"PlaybackProgress","Timestamp":"2023-09-26T11:18:17.8399513-03:00","UtcTimestamp":"2023-09-26T14:18:17.8399533Z","Name":"Brother Madonna","Overview":"","Tagline":"","ItemId":"514941104216969e74a8d87fc7893ad5","ItemType":"Audio","RunTimeTicks":926533312,"RunTime":"00:01:32","Year":2008,"Album":"I Kind of Really Want to Make Love to You","Artist":"Kitsune\u00B2","Provider_musicbrainzalbumartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzalbum":"7c10f8a5-669f-4ff6-bb88-de59846c0e0c","Provider_musicbrainzreleasegroup":"85c9ae8b-13e4-4fbf-9f09-5e405039772c","Provider_musicbrainztrack":"3c2c1f40-b22e-360e-a29a-1b1610190a8c","Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Audio_0_Language":null,"Audio_0_Codec":"flac","Audio_0_Channels":2,"Audio_0_Bitrate":917349,"Audio_0_SampleRate":44100,"Audio_0_Default":false,"PlaybackPositionTicks":640000000,"PlaybackPosition":"00:01:04","MediaSourceId":"514941104216969e74a8d87fc7893ad5","IsPaused":false,"IsAutomated":true,"DeviceId":"BC9311B570ABE4BD71EEEC0856A448AD","DeviceName":"samsung SM-S901E","ClientName":"Android","NotificationUsername":"Tabitha","UserId":"6d23c30c5e9d4ec6a66db6b05b63e516"}

Could it have something to do with the incorrect Content-Type header?

FoxxMD commented 9 months ago

Can you confirm for me which Notification Type(s) you have checked in the Webhook plugin? Do you have more than just Playback Progress checked?

tabithamoon commented 9 months ago

Only playback progress is checked, along with only item type Songs and Send All Properties enabled.

FoxxMD commented 9 months ago

Logging payload due to at least one Jellyfin source having 'logPayload: true

Did you truncate this or is it not displaying anything? Is this from the dashboard view or from docker logs?

tabithamoon commented 9 months ago

It's not truncated, it shows like that on both Docker logs and the web dashboard, nothing in front of logPayload: true.

tabithamoon commented 9 months ago

What I mentioned earlier seems to be the case. I manually added Content-Type: application/json to the headers in the plugin settings and now it's working as expected, second by second updates with no errors.

image

Seems this is a bug with the plugin then?

FoxxMD commented 9 months ago

Ah thanks, that's the hint I needed.

The webhook plugin (or could be JF http system?) always sends JSON in the body but the request has (up until now) always had the header Content-Type: text/utf-8. I'm running the same JF and webhook plugin as you so I'm not sure why it is different but from your request above it is sending Content-Type: text/plain; charset=utf-8 which the middleware MS uses to parse the request is not recognizing.

tabithamoon commented 9 months ago

That is odd, some more setup details: I'm running the linuxserver.io Docker container instead of the standard, and I've put both Jellyfin and MS behind Caddy for HTTPS. Could Caddy be altering the header when it proxies requests?

FoxxMD commented 9 months ago

It's possible Caddy is rewriting headers. I also tested the webhook plugin using text/plain as the value and the resulting header in MS also looked like text/plain; charset=utf-8 so who knows :man_shrugging:

I've added a fix to develop that makes MS more lenient in what Content-Type it accepts. It should fix your issue without requiring you to manually specify the Content-Type header in the plugin.

Please update your docker image (use the newest develop image), remove the request header from the webhook plugin, and see if it resolves the issue.

tabithamoon commented 9 months ago

It's still broken, but now with a different message in the log: [API] Jellyfin is not sending a request with valid headers. Content-Type must be either application/json or a text/* wildcard (like text/plain) -- given: Content-Type => text/plain; charset=utf-8

FoxxMD commented 9 months ago

I suspect there is still something funky happening to your headers. The underlying library checking for Content-Type, type-is, has no issues handling wildcards like text/* with additional info (charset) as long as the Content-Type value is within spec. It will reject it entirely if its not formed normally, even if would normally match the beginning based on a wildcard or something (1 2).

If you manually set Content-Type: text/plain in the webhook plugin request header does it start working?

tabithamoon commented 9 months ago

Unfortunately that does not fix it.

image image

Setting it to application/json does, though. According to Caddy's docs, it should not be modifying headers: https://caddyserver.com/docs/caddyfile/directives/reverse_proxy#defaults

FoxxMD commented 9 months ago

I'm sorry I cannot replicate this anymore. The fix in develop works for me given the exact same stack. I think there is something else going on with your networking besides just content-type because

2023-09-26T11:24:05-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:05-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}
2023-09-26T11:24:06-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Squaredance","Artist":"Kitsune²","Audio_0_Bitrate":916922,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","ClientName":"Android","DeviceId":"BC9311B570ABE4BD71EEEC0856A448AD","DeviceName":"samsung SM-S901E","IsAutomated":true,"IsPaused":false,"ItemId":"a8f15b29fdb162df7c91d4aa95ef10df","ItemType":"Audio","MediaSourceId":"a8f15b29fdb162df7c91d4aa95ef10df","Name":"Squaredance","NotificationType":"PlaybackProgress","NotificationUsername":"Tabitha","Overview":"","PlaybackPosition":"00:00:55","PlaybackPositionTicks":550000000,"Provider_musicbrainzalbum":"20d76f22-b42f-4704-90d0-10ee3508ec89","Provider_musicbrainzalbumartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzartist":"6e659357-5963-4daf-a634-a3596893f3d7","Provider_musicbrainzreleasegroup":"c75e0af7-ac3a-41ba-8674-43060200ecd7","Provider_musicbrainztrack":"fb64dc69-f581-32d8-95dd-355f7df6e498","RunTime":"00:02:43","RunTimeTicks":1638661248,"ServerId":"6c41d884a9c1490f8fd0863e04d75a69","ServerName":"maine","ServerUrl":"<redacted>","ServerVersion":"10.8.10","Tagline":"","Timestamp":"2023-09-26T11:24:06.8974676-03:00","UserId":"6d23c30c5e9d4ec6a66db6b05b63e516","UtcTimestamp":"2023-09-26T14:24:06.8974696Z","Year":2009}
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] Incoming play state ((a8f15b29fdb162df7c91d4aa95ef10df) Kitsune² - Squaredance) does not match existing state, removing existing: (514941104216969e74a8d87fc7893ad5) Kitsune² - Brother Madonna
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] New Play: (a8f15b29fdb162df7c91d4aa95ef10df) Kitsune² - Squaredance
2023-09-26T11:24:06-03:00 debug   : [Sources] [Jellyfin - jellyfin] [Player BC9311B570-samsung SM-S901E-Tabitha] Started new Player listen range.
2023-09-26T11:24:07-03:00 debug   : [API] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true
2023-09-26T11:24:07-03:00 debug   : [Sources] [Jellyfin - jellyfin] Will not scrobble event because media type was not 'Audio', found type: undefined {}

even before specifying it you were sometimes getting valid payloads. If this was purely a header issue it would have been all-or-nothing because the header should be constant. I've also never had another user encounter this issue.

I would suggest keeping the Content-Type header explicitly specified as application/json in the webhook as a workaround. If you find that this breaks sometime in the future, you find another clue, or someone else encounters this issue then I'll re-open the issue.

tabithamoon commented 9 months ago

The workaround works just fine, especially since according to you, Jellyfin only ever sends JSON anyway, so this is acceptable. Perhaps it's worth adding this workaround to the docs? Just in case another user runs into this issue, would avoid the headache for both the user and you if they open another issue.

nothing2obvi commented 2 weeks ago

I'm using Jellyfin 10.9.6 and am getting the following message in Multi-Scrobbler:

Jellyfin is not sending a request with valid headers. Content-Type must be either application/json or a text/* wildcard (like text/plain) -- given: Content-Type => 'text/plain; charset=utf-8'

However, the scrobble is successfully sent to Maloja.

FoxxMD commented 2 weeks ago

@nothing2obvi please try this fix from the FAQ