Sometimes does not scrobble/update as "now playing"

[keeganjk]

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]

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]

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]

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]

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]

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]

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]

@MaxKellermann this is one of the issue I was referencing in MusicPlayerDaemon/MPD#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.

[ghaspias]

I understand there being a minimum track length, but 4 min is ridiculous. I have many albums with tracks shorter than that. I listen to a full three-disc album set and only 5 tracks are submitted! Could we have a setting for this?

--- UPDATE ---

I realized that this issue was only with tracks being played through cantata's local file server. I apologize for the confusion.
Still, I don't understand what causes it -- is it the fact that the track is seen as a stream and ignored, or the fact that there is some delay in mpd realizing the file has a finite duration and updating the "duration" tag, which is then missed by mpdscribble?

[MaxKellermann]

I understand there being a minimum track length, but 4 min is

... is not true. That's not the actual minimum track length. That would be 30 seconds.