search

MusicPlayerDaemon / mpdscribble

a MPD client which submits information about tracks being played to a scrobbler (e.g. last.fm)
GNU General Public License v2.0
114 stars 15 forks source link

Sometimes does not scrobble/update as "now playing" #26

Open keeganjk opened 3 years ago

keeganjk commented 3 years ago

It seems that sometimes mpdscribble will simply not update scrobbles or indicate that a track is being played. I am not sure if this is an issue with the servers themselves or with mpdscribble, but it seems to be related to mpdscribble.

o0Rh0mbus0o commented 3 years ago

I've encountered issues where mpdscribble fails to update when key metadata is expected, such as a file having no artist. This might be the same problem.

MaxKellermann commented 3 years ago

such as a file having no artist.

This is just following the protocol specification which disallows submitting songs without an artist. Not a bug.

triplem commented 3 years ago

When streaming (eg via UPNP) the field "duration" is set slightly later, then the notification, that the song is starting. I do experience this on streaming Tidal to a upmpdcli-Renderer. This is rather annoying.

triplem commented 3 years ago

All the following songs are played via UPNP on an upmpdcli-Renderer, which streams onto a MPD-Instance. This is not streamed from Tidal but from my local network. By looking on the timestamps, it seems like (just a first quick glance) that the durations of the not scrobbled songs are below the 4m time necessary for scrobbling. Could this be it?

Jun 04 21:42:08 alarm mpdscribble[10580]: 2021-06-04T21:42:08+0200 1622835728, songchange: Depeche Mode - A Question of Lust (263)
Jun 04 21:42:08 alarm mpdscribble[10580]: 2021-06-04T21:42:08+0200 new song detected (Depeche Mode - Sometimes), id: 2137, pos: 3
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] submitting 1 song
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] post data: s=8L8HVbXtK3ROwgI5YnWYH4wXHvxejbLx&a[0]=Depeche%20Mode&t[0]=A%20Question%20of%20Lust&l[0]=263&i[0]=1622835728&o[0]=R&r[0]=&b[0]=Black%20Celebration%>
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] OK
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] sending 'now playing' notification
Jun 04 21:42:09 alarm mpdscribble[10580]: 2021-06-04T21:42:09+0200 [last.fm] OK
Jun 04 21:44:02 alarm mpdscribble[10580]: 2021-06-04T21:44:02+0200 new song detected (Depeche Mode - It Doesn't Matter Two), id: 2138, pos: 4
Jun 04 21:44:03 alarm mpdscribble[10580]: 2021-06-04T21:44:03+0200 [last.fm] sending 'now playing' notification
Jun 04 21:44:03 alarm mpdscribble[10580]: 2021-06-04T21:44:03+0200 [last.fm] OK
Jun 04 21:46:53 alarm mpdscribble[10580]: 2021-06-04T21:46:53+0200 new song detected (Depeche Mode - A Question of Time), id: 2139, pos: 5
Jun 04 21:46:54 alarm mpdscribble[10580]: 2021-06-04T21:46:54+0200 [last.fm] sending 'now playing' notification
Jun 04 21:46:54 alarm mpdscribble[10580]: 2021-06-04T21:46:54+0200 [last.fm] OK
Jun 04 21:51:02 alarm mpdscribble[10580]: 2021-06-04T21:51:02+0200 1622836262, songchange: Depeche Mode - A Question of Time (249)
Jun 04 21:51:02 alarm mpdscribble[10580]: 2021-06-04T21:51:02+0200 new song detected (Depeche Mode - Stripped), id: 2140, pos: 6
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] submitting 1 song
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] post data: s=8L8HVbXtK3ROwgI5YnWYH4wXHvxejbLx&a[0]=Depeche%20Mode&t[0]=A%20Question%20of%20Time&l[0]=249&i[0]=1622836262&o[0]=R&r[0]=&b[0]=Black%20Celebration%>
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] OK
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] sending 'now playing' notification
Jun 04 21:51:03 alarm mpdscribble[10580]: 2021-06-04T21:51:03+0200 [last.fm] OK
Jun 04 21:55:19 alarm mpdscribble[10580]: 2021-06-04T21:55:19+0200 1622836519, songchange: Depeche Mode - Stripped (256)
Jun 04 21:55:19 alarm mpdscribble[10580]: 2021-06-04T21:55:19+0200 new song detected (Depeche Mode - Here Is the House), id: 2141, pos: 7
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] submitting 1 song
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] post data: s=8L8HVbXtK3ROwgI5YnWYH4wXHvxejbLx&a[0]=Depeche%20Mode&t[0]=Stripped&l[0]=256&i[0]=1622836519&o[0]=R&r[0]=&b[0]=Black%20Celebration%20%28Deluxe%29&n>
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] OK
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] sending 'now playing' notification
Jun 04 21:55:20 alarm mpdscribble[10580]: 2021-06-04T21:55:20+0200 [last.fm] OK

And another one:

Jun 03 21:54:46 alarm mpdscribble[5194]: 2021-06-03T21:54:46+0200 1622750086, songchange: Diana Krall - Departure Bay (339)
Jun 03 21:54:47 alarm mpdscribble[5194]: 2021-06-03T21:54:47+0200 [last.fm] submitting 1 song
Jun 03 21:54:47 alarm mpdscribble[5194]: 2021-06-03T21:54:47+0200 [last.fm] post data: s=g50iKd5MDMfTCvCez7knc7vvrSQVvLd0&a[0]=Diana%20Krall&t[0]=Departure%20Bay&l[0]=339&i[0]=1622750086&o[0]=R&r[0]=&b[0]=The%20Girl%20In%20The%20Other%2>
Jun 03 21:54:47 alarm mpdscribble[5194]: 2021-06-03T21:54:47+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 03 21:54:47 alarm mpdscribble[5194]: 2021-06-03T21:54:47+0200 [last.fm] OK
Jun 03 21:56:04 alarm mpdscribble[5194]: 2021-06-03T21:56:04+0200 new song detected (Amy Winehouse - Rehab), id: 2088, pos: 0
Jun 03 21:56:05 alarm mpdscribble[5194]: 2021-06-03T21:56:05+0200 [last.fm] sending 'now playing' notification
Jun 03 21:56:05 alarm mpdscribble[5194]: 2021-06-03T21:56:05+0200 [last.fm] OK
Jun 03 21:59:38 alarm mpdscribble[5194]: 2021-06-03T21:59:38+0200 new song detected (Amy Winehouse - You Know I'm No Good), id: 2089, pos: 1
Jun 03 21:59:39 alarm mpdscribble[5194]: 2021-06-03T21:59:39+0200 [last.fm] sending 'now playing' notification
Jun 03 21:59:39 alarm mpdscribble[5194]: 2021-06-03T21:59:39+0200 [last.fm] OK
Jun 03 22:03:56 alarm mpdscribble[5194]: 2021-06-03T22:03:56+0200 1622750636, songchange: Amy Winehouse - You Know I'm No Good (257)
Jun 03 22:03:56 alarm mpdscribble[5194]: 2021-06-03T22:03:56+0200 new song detected (Amy Winehouse - Me And Mr Jones), id: 2090, pos: 2
Jun 03 22:03:57 alarm mpdscribble[5194]: 2021-06-03T22:03:57+0200 [last.fm] submitting 1 song
Jun 03 22:03:57 alarm mpdscribble[5194]: 2021-06-03T22:03:57+0200 [last.fm] post data: s=g50iKd5MDMfTCvCez7knc7vvrSQVvLd0&a[0]=Amy%20Winehouse&t[0]=You%20Know%20I%27m%20No%20Good&l[0]=257&i[0]=1622750636&o[0]=R&r[0]=&b[0]=Back%20To%20Bl>
Jun 03 22:03:57 alarm mpdscribble[5194]: 2021-06-03T22:03:57+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
triplem commented 3 years ago

Just another idea, based on the Issue #23. Could it be, that if the duration of a song is "empty"/"not retrievable" the song is only scrobbled if the song is played for more then a specific time?

triplem commented 3 years ago

I have modified the log message, which shows the current playing song (Main.cxx - Line 75) to also contain the duration of the current song, this is (with UPnP) always 0. This seems to be the cause for the trouble, except the song is longer then 4m (that is a guess).

Jun 05 00:15:57 alarm mpdscribble[29908]: 2021-06-05T00:15:57+0200 new song detected (Goldfrapp - Anymore (Joe Goddard Remix)), id: 2169, pos: 13, dur: 0
Jun 05 00:15:58 alarm mpdscribble[29908]: 2021-06-05T00:15:58+0200 [last.fm] sending 'now playing' notification
Jun 05 00:15:58 alarm mpdscribble[29908]: 2021-06-05T00:15:58+0200 [last.fm] OK
Jun 05 00:22:11 alarm mpdscribble[29908]: 2021-06-05T00:22:11+0200 1622845331, songchange: Goldfrapp - Anymore (Joe Goddard Remix) (373)
Jun 05 00:22:11 alarm mpdscribble[29908]: 2021-06-05T00:22:11+0200 new song detected (Goldfrapp - Systemagic (Ralphi Rosario Lunar Eclipse Mix)), id: 2170, pos: 14, dur: 0
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] submitting 1 song
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] post data: s=dt0MJHamZmMUVrVN1rykM7xhny630kXT&a[0]=Goldfrapp&t[0]=Anymore%20%28Joe%20Goddard%20Remix%29&l[0]=373&i[0]=1622845331&o[0]=R&r[0]=&b[0]=Silver%20Eye>
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] OK
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] sending 'now playing' notification
Jun 05 00:22:12 alarm mpdscribble[29908]: 2021-06-05T00:22:12+0200 [last.fm] OK
Jun 05 00:29:09 alarm mpdscribble[29908]: 2021-06-05T00:29:09+0200 1622845749, songchange: Goldfrapp - Systemagic (Ralphi Rosario Lunar Eclipse Mix) (418)
Jun 05 00:29:09 alarm mpdscribble[29908]: 2021-06-05T00:29:09+0200 new song detected (Goldfrapp - Anymore (Whatever/Whatever Remix by Justin Strauss & Bryan Mette)), id: 2171, pos: 15, dur: 0
Jun 05 00:29:10 alarm mpdscribble[29908]: 2021-06-05T00:29:10+0200 [last.fm] submitting 1 song
Jun 05 00:29:10 alarm mpdscribble[29908]: 2021-06-05T00:29:10+0200 [last.fm] post data: s=dt0MJHamZmMUVrVN1rykM7xhny630kXT&a[0]=Goldfrapp&t[0]=Systemagic%20%28Ralphi%20Rosario%20Lunar%20Eclipse%20Mix%29&l[0]=418&i[0]=1622845749&o[0]=R&r>
Jun 05 00:29:10 alarm mpdscribble[29908]: 2021-06-05T00:29:10+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 05 00:29:11 alarm mpdscribble[29908]: 2021-06-05T00:29:11+0200 [last.fm] OK
Jun 05 00:29:11 alarm mpdscribble[29908]: 2021-06-05T00:29:11+0200 [last.fm] sending 'now playing' notification
Jun 05 00:29:11 alarm mpdscribble[29908]: 2021-06-05T00:29:11+0200 [last.fm] OK
Jun 05 00:37:04 alarm mpdscribble[29908]: 2021-06-05T00:37:04+0200 1622846224, songchange: Goldfrapp - Anymore (Whatever/Whatever Remix by Justin Strauss & Bryan Mette) (474)
Jun 05 00:37:05 alarm mpdscribble[29908]: 2021-06-05T00:37:05+0200 [last.fm] submitting 1 song
Jun 05 00:37:05 alarm mpdscribble[29908]: 2021-06-05T00:37:05+0200 [last.fm] post data: s=dt0MJHamZmMUVrVN1rykM7xhny630kXT&a[0]=Goldfrapp&t[0]=Anymore%20%28Whatever%2FWhatever%20Remix%20by%20Justin%20Strauss%20%26%20Bryan%20Mette%29&l[0>
Jun 05 00:37:05 alarm mpdscribble[29908]: 2021-06-05T00:37:05+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 05 00:37:05 alarm mpdscribble[29908]: 2021-06-05T00:37:05+0200 [last.fm] OK
Jun 05 11:28:05 alarm mpdscribble[29908]: 2021-06-05T11:28:05+0200 new song detected (Die Drei ??? - 183 - und der letzte Song (Teil 01)), id: 2174, pos: 0, dur: 0
Jun 05 11:28:06 alarm mpdscribble[29908]: 2021-06-05T11:28:06+0200 [last.fm] sending 'now playing' notification
Jun 05 11:28:06 alarm mpdscribble[29908]: 2021-06-05T11:28:06+0200 [last.fm] OK

An alternative would be to use the mpd_status_get_total_time(status), which returns valid values, even though I was unable to really figure out the difference between the mpd_status_get_total_time and mpd_song_get_duration_ms. Unfortunately in the GetSongDuration-Function, I do not have access to the status. I modified MpdObserver in line 209, to contain both of those values:

    FormatInfo("total_time(status)/duration(song): %u/%u",
            mpd_status_get_total_time(status) * 1000, 
            mpd_song_get_duration_ms(song));

The result is:

Jun 05 13:16:02 alarm mpdscribble[8285]: 2021-06-05T13:16:02+0200 total_time(status)/duration(song): 1260153240/0
Jun 05 13:16:02 alarm mpdscribble[8285]: 2021-06-05T13:16:02+0200 new song detected (Stratus, Kid Loco (Composer) - Uplink), id: 2227, pos: 4, dur: 0
Jun 05 13:16:02 alarm mpdscribble[8285]: 2021-06-05T13:16:02+0200 another new song detected (Stratus, Kid Loco (Composer) - Uplink), id: 2227, pos: 4, dur: 0
Jun 05 13:16:02 alarm mpdscribble[8285]: 2021-06-05T13:16:02+0200 total_time(status)/duration(song): 1260153240/0
Jun 05 13:16:03 alarm mpdscribble[8285]: 2021-06-05T13:16:03+0200 [last.fm] sending 'now playing' notification
Jun 05 13:16:03 alarm mpdscribble[8285]: 2021-06-05T13:16:03+0200 [last.fm] OK
Jun 05 13:16:30 alarm mpdscribble[8285]: 2021-06-05T13:16:30+0200 total_time(status)/duration(song): 107000/0
Jun 05 13:16:30 alarm mpdscribble[8285]: 2021-06-05T13:16:30+0200 new song detected (Tommy Hools, Kid Loco (Composer) - Barcelone), id: 2228, pos: 5, dur: 0
Jun 05 13:16:30 alarm mpdscribble[8285]: 2021-06-05T13:16:30+0200 another new song detected (Tommy Hools, Kid Loco (Composer) - Barcelone), id: 2228, pos: 5, dur: 0
Jun 05 13:16:30 alarm mpdscribble[8285]: 2021-06-05T13:16:30+0200 total_time(status)/duration(song): 107000/0
Jun 05 13:16:31 alarm mpdscribble[8285]: 2021-06-05T13:16:31+0200 [last.fm] sending 'now playing' notification
Jun 05 13:16:31 alarm mpdscribble[8285]: 2021-06-05T13:16:31+0200 [last.fm] OK
Jun 05 13:18:16 alarm mpdscribble[8285]: 2021-06-05T13:18:16+0200 total_time(status)/duration(song): 118000/0
Jun 05 13:18:16 alarm mpdscribble[8285]: 2021-06-05T13:18:16+0200 new song detected (Zero Theory - Cold Spin), id: 2229, pos: 6, dur: 0
Jun 05 13:18:16 alarm mpdscribble[8285]: 2021-06-05T13:18:16+0200 another new song detected (Zero Theory - Cold Spin), id: 2229, pos: 6, dur: 0
Jun 05 13:18:17 alarm mpdscribble[8285]: 2021-06-05T13:18:17+0200 [last.fm] sending 'now playing' notification
Jun 05 13:18:17 alarm mpdscribble[8285]: 2021-06-05T13:18:17+0200 [last.fm] OK
Jun 05 13:19:23 alarm mpdscribble[8285]: 2021-06-05T13:19:23+0200 total_time(status)/duration(song): 269000/0
Jun 05 13:19:23 alarm mpdscribble[8285]: 2021-06-05T13:19:23+0200 new song detected (Waldeck - Defenceless), id: 2246, pos: 0, dur: 0
Jun 05 13:19:23 alarm mpdscribble[8285]: 2021-06-05T13:19:23+0200 another new song detected (Waldeck - Defenceless), id: 2246, pos: 0, dur: 0
Jun 05 13:19:23 alarm mpdscribble[8285]: 2021-06-05T13:19:23+0200 total_time(status)/duration(song): 269000/0
Jun 05 13:19:23 alarm mpdscribble[8285]: 2021-06-05T13:19:23+0200 total_time(status)/duration(song): 269000/0
Jun 05 13:19:24 alarm mpdscribble[8285]: 2021-06-05T13:19:24+0200 [last.fm] sending 'now playing' notification
Jun 05 13:19:24 alarm mpdscribble[8285]: 2021-06-05T13:19:24+0200 [last.fm] OK
Jun 05 13:23:51 alarm mpdscribble[8285]: 2021-06-05T13:23:51+0200 total_time(status)/duration(song): 319000/0
Jun 05 13:23:51 alarm mpdscribble[8285]: 2021-06-05T13:23:51+0200 1622892231, songchange: Waldeck - Defenceless (268)
Jun 05 13:23:51 alarm mpdscribble[8285]: 2021-06-05T13:23:51+0200 new song detected (Waldeck - Spy Like An Angel), id: 2247, pos: 1, dur: 0
Jun 05 13:23:51 alarm mpdscribble[8285]: 2021-06-05T13:23:51+0200 another new song detected (Waldeck - Spy Like An Angel), id: 2247, pos: 1, dur: 0
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] submitting 1 song
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] post data: s=PvPvH72PtWe0t71Mr6ryljxKgyNhTpLi&a[0]=Waldeck&t[0]=Defenceless&l[0]=268&i[0]=1622892231&o[0]=R&r[0]=&b[0]=Balance%20Of%20The%20Force&n[0]=1&m[0]=
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] OK
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] sending 'now playing' notification
Jun 05 13:23:52 alarm mpdscribble[8285]: 2021-06-05T13:23:52+0200 [last.fm] OK
Jun 05 13:29:10 alarm mpdscribble[8285]: 2021-06-05T13:29:10+0200 total_time(status)/duration(song): 250000/0
Jun 05 13:29:10 alarm mpdscribble[8285]: 2021-06-05T13:29:10+0200 1622892550, songchange: Waldeck - Spy Like An Angel (319)
Jun 05 13:29:10 alarm mpdscribble[8285]: 2021-06-05T13:29:10+0200 new song detected (Waldeck - Children Of The Ghetto), id: 2248, pos: 2, dur: 0
Jun 05 13:29:10 alarm mpdscribble[8285]: 2021-06-05T13:29:10+0200 another new song detected (Waldeck - Children Of The Ghetto), id: 2248, pos: 2, dur: 0
Jun 05 13:29:11 alarm mpdscribble[8285]: 2021-06-05T13:29:11+0200 [last.fm] submitting 1 song
Jun 05 13:29:11 alarm mpdscribble[8285]: 2021-06-05T13:29:11+0200 [last.fm] post data: s=PvPvH72PtWe0t71Mr6ryljxKgyNhTpLi&a[0]=Waldeck&t[0]=Spy%20Like%20An%20Angel&l[0]=319&i[0]=1622892550&o[0]=R&r[0]=&b[0]=Balance%20Of%20The%20Force&n[>
Jun 05 13:29:11 alarm mpdscribble[8285]: 2021-06-05T13:29:11+0200 [last.fm] url: http://138.201.169.196/protocol_1.2
Jun 05 13:29:11 alarm mpdscribble[8285]: 2021-06-05T13:29:11+0200 [last.fm] OK
Jun 05 13:29:11 alarm mpdscribble[8285]: 2021-06-05T13:29:11+0200 [last.fm] sending 'now playing' notification

Any help on fixing this is greatly appreciated. Me is not a C++ Expert, but just a music lover :-)

X-dark commented 1 year ago

@MaxKellermann this is one of the issue I was referencing in https://github.com/MusicPlayerDaemon/MPD/issues/1774 I am clueless to understand how to alter this behavior if there is no way to set or get the song duration in those cases.