search

owntone / owntone-server

Linux/FreeBSD DAAP (iTunes) and MPD audio server with support for AirPlay 1 and 2 speakers (multiroom), Apple Remote (and compatibles), Chromecast, Spotify and internet radio.
https://owntone.github.io/owntone-server
GNU General Public License v2.0
2.07k stars 235 forks source link

Playback position reset after pause/play from Pebble MPD client #738

Closed cdlenfert closed 5 years ago

cdlenfert commented 5 years ago

Whenever I pause/play from my Pebble Watch MPD client (a very nice feature to have) the position of my queue returns to the first item.

It seems obvious the Pebble client is to blame, but why the sudden change?

cdlenfert commented 5 years ago

I've also confirmed that pausing from Pebble does not return to the first track in the queue. If I pause from the Pebble, but play from the web interface, the playback position is maintained correctly. Only clicking play from the Pebble app causes it to go to the first track.

ejurgensen commented 5 years ago

Can you set the logging to debug level and attach a log file with the logging from when you resume playback?

cdlenfert commented 5 years ago

Yes, thanks for the quick response and suggestion - https://pastebin.com/SgaVfi0G It's a little long, but a lot happens very fast in the log. The first song in the queue is Ace - How Long :)

ejurgensen commented 5 years ago

These two lines seem interesting (they come after you paused via the web, right?):

[2019-05-08 13:34:50] [DEBUG]      mpd: MPD message: pause 0
...
[2019-05-08 13:34:53] [DEBUG]      mpd: MPD message: play

They both have the effect of starting playback, but the latter ("play") will reset the playback position to the first item in the queue. I will let @chme be the judge of whether that is as it should be.

I don't understand why the Pebble sends both commands, and especially not why they are 3 seconds apart.

cdlenfert commented 5 years ago

@ejurgensen thanks for reviewing the log. You are spot on with what's happening there, but to clarify playback is already paused and these come after I've clicked play in the Pebble MPD Client app. I've tested this at work on another device running Forked-Daapd and am getting the same result, though this time the pause 0 and play command are happening in the same second. I'm not sure if: 

##GOOD PLAY COMMAND##
[2019-05-09 09:37:03] [DEBUG]      mpd: MPD message: pause 0

##CURRENTLY PAUSED SONG##
[2019-05-09 09:37:03] [DEBUG]   player: Resume playback of '/home/share/since78/Got to Let Go/04 Bossa Nova 101.mp3' (id=8859, item-id=39182)
[2019-05-09 09:37:03] [DEBUG]     main: Got worker execute request
[2019-05-09 09:37:03] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-05-09 09:37:03] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-05-09 09:37:03] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 39182 ORDER BY pos;'

##NOT SO GOOD PLAY COMMAND (RESETS PLAYBACK POSITION)##
[2019-05-09 09:37:03] [DEBUG]      mpd: MPD message: play
[2019-05-09 09:37:03] [DEBUG]   player: Player status: playing
[2019-05-09 09:37:03] [DEBUG]   player: Removing callback to device_streaming_cb, id 0
[2019-05-09 09:37:03] [DEBUG]   player: Registered callback to device_flush_cb with id 0 (device 0x149dd58, PogoPlug)
[2019-05-09 09:37:03] [DEBUG]   player: Number of active callbacks: 1
[2019-05-09 09:37:03] [DEBUG]   player: Callback request received, id is 0
[2019-05-09 09:37:03] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-05-09 09:37:03] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-05-09 09:37:03] [DEBUG]   player: Making deferred callback to device_flush_cb, id was 0
[2019-05-09 09:37:03] [DEBUG]   player: Callback from ALSA to device_flush_cb (status 2)
[2019-05-09 09:37:03] [DEBUG]   player: Registered callback to device_streaming_cb with id 0 (device 0x149dd58, PogoPlug)
[2019-05-09 09:37:03] [DEBUG]   player: Number of active callbacks: 1
[2019-05-09 09:37:03] [DEBUG]     main: Command has 0 pending events
[2019-05-09 09:37:03] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-05-09 09:37:03] [DEBUG]  artwork: Artwork request for item 8859
[2019-05-09 09:37:03] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 8859;'
[2019-05-09 09:37:03] [DEBUG]   player: 0. Active callback: device_streaming_cb
[2019-05-09 09:37:03] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 8859   ;'
[2019-05-09 09:37:03] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-05-09 09:37:03] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE pos = 0 ORDER BY pos;'
[2019-05-09 09:37:03] [DEBUG]       db: Running query 'END TRANSACTION;'

##FIRST SONG##
[2019-05-09 09:37:03] [DEBUG]   player: Start playback of '/home/share/since78/Got to Let Go/01 Goodmorning Sun.mp3' (id=8864, item-id=39179)
ejurgensen commented 5 years ago

the Pebble is sending 2 commands recently because it's getting a different response than before from Forked-Daapd

Yes, that sounds likely, it would also explain the time between the two commands. I did test the two commands with current master and with the latest release (26.5) to check for differences (recent bugs). The two commands did the same, so at first I ruled that out, but I didn't check the response content, so perhaps there is actually an issue there. I will look into that.

What is the last version of forked-daapd which worked? Can you test with the latest release version?

cdlenfert commented 5 years ago

That's a good question. I'm downgrading to 26.5 as I know I'm currently running something closer to the master branch (maybe a few commits behind). I don't remember exactly which version was working previously.

cdlenfert commented 5 years ago

@ejurgensen The issue is not present on release 26.5.

cdlenfert commented 5 years ago

It looks like the Pebble MPD client still sends the play command, but it is ignored.

[2019-05-09 15:00:03] [DEBUG]       db: Fetch by pos: fetched item (id=39418, pos=2, file-id=11490)
[2019-05-09 15:00:03] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-05-09 15:00:03] [DEBUG]       db: Fetch by pos: fetched item (id=39418, pos=2, file-id=11490)
[2019-05-09 15:00:03] [DEBUG]      mpd: MPD message: currentsong
[2019-05-09 15:00:03] [DEBUG]   player: Player status: paused
[2019-05-09 15:00:03] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-05-09 15:00:03] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 39417 ORDER BY pos;'
[2019-05-09 15:00:03] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-05-09 15:00:03] [DEBUG]      mpd: MPD message: command_list_end
[2019-05-09 15:00:03] [DEBUG]      mpd: Removing mpd client
[2019-05-09 15:00:07] [ INFO]      mpd: New mpd client connection accepted
[2019-05-09 15:00:07] [DEBUG]      mpd: MPD message: command_list_begin

## PLAY BUTTON PRESSED ON PEBBLE ##
[2019-05-09 15:00:07] [DEBUG]      mpd: MPD message: pause 0
[2019-05-09 15:00:07] [DEBUG]   player: Resume playback of '/home/share/Ducktails/Jersey Devil/Jersey Devil-002-Ducktails-Light a Candle.mp3' (id=11492, item-id=39417)
[2019-05-09 15:00:07] [DEBUG]   player: Action is metadata_get
[2019-05-09 15:00:07] [DEBUG]     main: Got worker execute request
[2019-05-09 15:00:07] [DEBUG]   laudio: Starting ALSA audio (pos 5834017597, next_pkt 5834105949)
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-05-09 15:00:07] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 39417 ORDER BY pos;'
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-05-09 15:00:07] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 39417 ORDER BY pos;'
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-05-09 15:00:07] [DEBUG]  artwork: Artwork request for item 11492
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 11492;'
[2019-05-09 15:00:07] [DEBUG]   laudio: Will prebuffer 252 packets
[2019-05-09 15:00:07] [DEBUG]   laudio: Dump of sound device config:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 262144
  period_size  : 256
  period_time  : 5804
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 256
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 262144
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824

[2019-05-09 15:00:07] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.

## PEBBLE CLIENT ISSUES PLAY COMMAND THAT GETS IGNORED ##
[2019-05-09 15:00:07] [DEBUG]      mpd: MPD message: play
[2019-05-09 15:00:07] [DEBUG]   player: Player status: playing (buffering)
[2019-05-09 15:00:07] [DEBUG]   player: Player is already playing, ignoring call to playback start
[2019-05-09 15:00:07] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-05-09 15:00:07] [DEBUG]      mpd: MPD message: status
[2019-05-09 15:00:07] [DEBUG]   player: Player status: playing (buffering)
[2019-05-09 15:00:07] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2019-05-09 15:00:07] [DEBUG]   player: Action is start
ejurgensen commented 5 years ago

Thanks, that is interesting. I think I now understand what is going on, and it is not related to the content of the response after all. It has to do with the timing of the "mpc play" command. A bit of a long story, let me try and explain:

As you can see from the log, during the first seconds the player buffers, and during that time the player state is "paused". After that the state becomes "playing". The mpc command handler is made so that if an "mpc play" command is received, and the state is "playing", the player will be stopped, and the position will be reset. However, if the command is received before that while buffering/paused, the player will not be stopped, but will instead be requested to start playing the first track by the mpd handler. The player will ignore that request, because it thinks it is already playing (and you see the log line "Player is already playing, ignoring call to playback start").

As far as I can tell, this behavior has not been changed between release 26.5 and master, but you can see from your logs that something has changed the timing of the "mpc play". In the last one you sent it comes straight after the "mpc pause 0", while forked-daapd is buffering, and the original it came 3 seconds later, while forked-daapd was playing.

I'm not sure what has changed the timing, but in any case the fix is probably more about making sure "mpc play" works the same, buffering or not. Let's see if @chme has an idea about how to proceed with a fix.

cdlenfert commented 5 years ago

Thanks for the details. I'm not sure why the first log shows a 3 second gap between pause 0 and play commands, but my second log from this post was also from Master and the pause/play commands were in the same second. Only my last log was from 26.5 and in that case the commands are also in the same second.

The first difference I see in the logs is: Master mpd: Asynchronous listener callback called with event type 1. 26.5 laudio: Starting ALSA audio (pos 5834017597, next_pkt 5834105949)

I'm not sure there is any correlation, but I have clear_queue_on_stop_disable = true set in my config file. I did this a while back in order to be able to stop and start internet radio streams. With it set to the default of false if I stopped a radio station and tried to start it again, it was no longer queued.

ejurgensen commented 5 years ago

Yes, you are right that there is more to it than timing. I can see that "pause 0" causes the 26.5 player to go to paused/buffering state, but master goes directly to playing. The latter is incorrect, so I will get that fixed asap.

ejurgensen commented 5 years ago

I've added a change to master that I think should fix the regression since 26.5. With the change the state should be buffering after playback as resumed, and the "mpc play" should be ignored. I hope you will test it and let me know if it works.

cdlenfert commented 5 years ago

@ejurgensen Thank you! I've updated to master and unpausing from the Pebble MPD Client app is working again.

cdlenfert commented 5 years ago

@ejurgensen I'd consider this issue resolved personally, but since you call it a "partial fix" in your commit message, feel free to leave the issue open if you prefer.

ejurgensen commented 5 years ago

Thanks, I am keeping the issue open to remember that there is a small fix required in mpc.c. I think @chme will do that when he has more time.