AirPlay volume control - Githubissues

gcannar commented 6 years ago

Hi,

first of all thanks for the great job u've done!!

I'm having an issue with my connected AirPlay device...whatever volume control i send via MPC the volume on the device remain the same.

The strange thing is that if i control the device from my mac and set a volume, then forked will use that volume too for that device. No way to set it by MPC.

This can be very useful at exampe to control volume of different kind of notifications or alarm..

Can u help me with this?

Thank you so much. G.

ejurgensen commented 6 years ago

This is pretty well tested and should work. Try setting the log level to debug in the config file and then check in the log file that forked-daapd is actually getting the command.

gcannar commented 6 years ago

Hi this I s what I get when I bash “ $ mpc volume 10”

[2018-01-21 21:51:30] [DEBUG] mpd: Asynchronous listener callback called with event type 128. [2018-01-21 21:51:30] [DEBUG] mpd: Notify clients waiting for idle results: 128 [2018-01-21 21:52:41] [ INFO] mpd: New mpd client connection accepted [2018-01-21 21:52:41] [DEBUG] mpd: MPD message: setvol "10" [2018-01-21 21:52:41] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-21 21:52:41] [DEBUG] mpd: MPD message: status [2018-01-21 21:52:41] [DEBUG] player: Player status: stopped [2018-01-21 21:52:41] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-21 21:52:41] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-21 21:52:41] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-21 21:52:41] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-21 21:52:41] [DEBUG] db: End of queue enum results [2018-01-21 21:52:41] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-21 21:52:41] [DEBUG] mpd: MPD message: currentsong [2018-01-21 21:52:41] [DEBUG] player: Player status: stopped

It gets volume on “10” but the sound is not afflicted and the volume is the same that I set up before when the BL speaker was connected to the Mac. The volume commando off works for my other devices such a Google Home Mini.

Any suggestion?

Thanks, G.

On 21 Jan 2018, 22:41 +0100, ejurgensen notifications@github.com, wrote:

This is pretty well tested and should work. Try setting the log level to debug in the config file and then check in the log file that forked-daapd is actually getting the command. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

ejurgensen commented 6 years ago

I'm a bit confused now: The original question said Airplay volume, but then you mention a Bluetooth speaker and a Google Home (Chromecast, I think). What's the device that is not adjusting volume and how is it connected to forked-daapd? Also, from the log it doesn't look like any device is selected when you are doing the volume adjustment?

gcannar commented 6 years ago

I’m sorry I meant AirPlay not bluetooth!

I mentioned GHome just to let you know that setting volume for another device works ok.

These are the log from turning on the AirPlay device -> mpc volume 50

[2018-01-21 22:12:56] [DEBUG] mdns: Avahi Browser: NEW service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0 [2018-01-21 22:12:56] [DEBUG] mdns: Avahi Resolver: resolved service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0, host LG-AUDIO-22EF45.local [2018-01-21 22:12:56] [DEBUG] mdns: Avahi Record Browser (LG-AUDIO-22EF45.local, proto 0): NEW record 192.168.1.109 for service type '_raop._tcp' [2018-01-21 22:12:56] [DEBUG] raop: Event for AirPlay device LG AUDIO 22EF45 (port 1024, id 2016d822ef45) [2018-01-21 22:12:56] [ INFO] raop: Adding AirPlay device 2016D822EF45@LG AUDIO 22EF45: password: 0, verification: 0, encrypt: 0, metadata: 0, type Other, address 192.168.1.109:1024 [2018-01-21 22:12:56] [DEBUG] db: Running query 'SELECT s.selected, s.volume, s.name, s.auth_key FROM speakers s WHERE s.id = 35282487537477;' [2018-01-21 22:12:56] [DEBUG] mdns: Avahi Browser: NEW service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0 [2018-01-21 22:12:56] [DEBUG] mdns: Avahi Resolver: resolved service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0, host LG-AUDIO-22EF45.local [2018-01-21 22:12:56] [DEBUG] mdns: Avahi Record Browser (LG-AUDIO-22EF45.local, proto 0): NEW record 192.168.1.109 for service type '_raop._tcp' [2018-01-21 22:12:56] [DEBUG] raop: Event for AirPlay device LG AUDIO 22EF45 (port 1024, id 2016d822ef45) [2018-01-21 22:12:56] [ INFO] raop: Adding AirPlay device 2016D822EF45@LG AUDIO 22EF45: password: 0, verification: 0, encrypt: 0, metadata: 0, type Other, address 192.168.1.109:1024 [2018-01-21 22:12:57] [DEBUG] mdns: Avahi Browser: REMOVE service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0 [2018-01-21 22:12:57] [DEBUG] raop: Event for AirPlay device LG AUDIO 22EF45 (port -1, id 2016d822ef45) [2018-01-21 22:12:57] [DEBUG] db: Running query 'INSERT OR REPLACE INTO speakers (id, selected, volume, name, auth_key) VALUES (35282487537477, 1, 10, 'LG AUDIO 22EF45', NULL);' [2018-01-21 22:12:57] [ INFO] player: Removing AirPlay device 'LG AUDIO 22EF45'; stopped advertising [2018-01-21 22:13:00] [DEBUG] mdns: Avahi Browser: NEW service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0 [2018-01-21 22:13:00] [DEBUG] mdns: Avahi Resolver: resolved service '2016D822EF45@LG AUDIO 22EF45' type '_raop._tcp' proto 0, host LG-AUDIO-22EF45.local [2018-01-21 22:13:00] [DEBUG] mdns: Avahi Record Browser (LG-AUDIO-22EF45.local, proto 0): NEW record 192.168.1.109 for service type '_raop._tcp' [2018-01-21 22:13:00] [DEBUG] raop: Event for AirPlay device LG AUDIO 22EF45 (port 1024, id 2016d822ef45) [2018-01-21 22:13:00] [ INFO] raop: Adding AirPlay device 2016D822EF45@LG AUDIO 22EF45: password: 0, verification: 0, encrypt: 0, metadata: 0, type Other, address 192.168.1.109:1024 [2018-01-21 22:13:00] [DEBUG] db: Running query 'SELECT s.selected, s.volume, s.name, s.auth_key FROM speakers s WHERE s.id = 35282487537477;' [2018-01-21 22:13:23] [ INFO] mpd: New mpd client connection accepted [2018-01-21 22:13:23] [DEBUG] mpd: MPD message: setvol "50" [2018-01-21 22:13:23] [DEBUG] mpd: Asynchronous listener callback called with event type 4. [2018-01-21 22:13:23] [DEBUG] mpd: Notify clients waiting for idle results: 4 [2018-01-21 22:13:23] [DEBUG] mpd: Notify client #0 [2018-01-21 22:13:23] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-21 22:13:23] [DEBUG] mpd: MPD message: status [2018-01-21 22:13:23] [DEBUG] player: Player status: stopped [2018-01-21 22:13:23] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-21 22:13:23] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-21 22:13:23] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-21 22:13:23] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-21 22:13:23] [DEBUG] db: End of queue enum results [2018-01-21 22:13:23] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-21 22:13:23] [DEBUG] mpd: MPD message: currentsong [2018-01-21 22:13:23] [DEBUG] player: Player status: stopped [2018-01-21 22:13:23] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-21 22:13:23] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-21 22:13:23] [DEBUG] db: End of queue enum results [2018-01-21 22:13:23] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-21 22:13:23] [DEBUG] mpd: MPD message: command_list_end [2018-01-21 22:13:23] [DEBUG] mpd: Removing mpd client [2018-01-21 22:13:24] [DEBUG] web: notify callback reason: 11

On 21 Jan 2018, 23:05 +0100, ejurgensen notifications@github.com, wrote:

I'm a bit confused now: The original question said Airplay volume, but then you mention a Bluetooth speaker and a Google Home (Chromecast, I think). What's the device that is not adjusting volume and how is it connected to forked-daapd? Also, from the log it doesn't look like any device is selected when you are doing the volume adjustment? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

ejurgensen commented 6 years ago

Can you try changing the volume during playback and then see what the log says? I assume that also doesn't work, right?

I would like to see if the device is returning an error. forked-daapd will try to set the AirPlay volume with a SET_PARAMETER command to the device.

gcannar commented 6 years ago

I gave it a tray and It worked and there are the logs… If a change the volume after play it’s ok…if. I set the volume before is not...

[2018-01-22 15:17:20] [ INFO] mpd: New mpd client connection accepted [2018-01-22 15:17:20] [DEBUG] mpd: MPD message: setvol "30" [2018-01-22 15:17:20] [DEBUG] raop: Building SET_PARAMETER for 'LG AUDIO 22EF45' [2018-01-22 15:17:20] [DEBUG] mpd: Asynchronous listener callback called with event type 4. [2018-01-22 15:17:20] [DEBUG] player: Callback from AirPlay to device_command_cb [2018-01-22 15:17:20] [DEBUG] main: Command has 0 pending events [2018-01-22 15:17:20] [DEBUG] mpd: Notify clients waiting for idle results: 4 [2018-01-22 15:17:20] [DEBUG] mpd: Notify client #0 [2018-01-22 15:17:20] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 15:17:20] [DEBUG] mpd: MPD message: status [2018-01-22 15:17:20] [DEBUG] player: Player status: playing [2018-01-22 15:17:20] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 15:17:20] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 15:17:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 136 ORDER BY pos ASC;' [2018-01-22 15:17:20] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (136) [2018-01-22 15:17:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (136) [2018-01-22 15:17:20] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 136;' [2018-01-22 15:17:20] [DEBUG] db: Fetch by pos: item (136) has absolute pos 0 [2018-01-22 15:17:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 15:17:20] [DEBUG] db: End of queue enum results [2018-01-22 15:17:20] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 15:17:20] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] mpd: MPD message: currentsong [2018-01-22 15:17:20] [DEBUG] player: Player status: playing [2018-01-22 15:17:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 136 ORDER BY pos ASC;' [2018-01-22 15:17:20] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 15:17:20] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 15:17:20] [DEBUG] mpd: Removing mpd client

On 22 Jan 2018, 08:57 +0100, ejurgensen notifications@github.com, wrote:

Can you try changing the volume during playback and then see what the log says? I assume that also doesn't work, right? I would like to see if the device is returning an error. forked-daapd will try to set the AirPlay volume with a SET_PARAMETER command to the device. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

ejurgensen commented 6 years ago

I have trouble reproducing this, also when there is no playback. E.g.:

mpc enable [my speaker]
mpc volume 10
mpc play
mpc stop
mpc volume 50
mpc play

How does that sequence work for you? If it works, can you then provide me a sequence that produces unexpected behaviour?

gcannar commented 6 years ago

Setting the volume after the playback work well…these are the log for your sequence…

[2018-01-22 19:14:28] [DEBUG] mpd: MPD message: setvol "10" [2018-01-22 19:14:28] [DEBUG] mpd: Asynchronous listener callback called with event type 4. [2018-01-22 19:14:28] [DEBUG] mpd: Notify clients waiting for idle results: 4 [2018-01-22 19:14:28] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:28] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 19:14:28] [DEBUG] mpd: MPD message: status [2018-01-22 19:14:28] [DEBUG] player: Player status: stopped [2018-01-22 19:14:28] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:14:28] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 19:14:28] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:28] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:28] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:28] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:14:28] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:14:28] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:14:28] [DEBUG] db: End of queue enum results [2018-01-22 19:14:28] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:14:28] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] mpd: MPD message: currentsong [2018-01-22 19:14:28] [DEBUG] player: Player status: stopped [2018-01-22 19:14:28] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:28] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:28] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 19:14:28] [DEBUG] mpd: Removing mpd client [2018-01-22 19:14:32] [ INFO] mpd: New mpd client connection accepted [2018-01-22 19:14:32] [DEBUG] mpd: MPD message: play [2018-01-22 19:14:32] [DEBUG] player: Player status: stopped [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] player: Start playback of '/home/pi/music/song.mp3' (id=4, item-id=142) [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT f. FROM files f WHERE f.id = 4;' [2018-01-22 19:14:32] [ INFO] player: Opening '/home/pi/music/song.mp3' (id=4, item-id=142) [2018-01-22 19:14:32] [DEBUG] player: Action is setup [2018-01-22 19:14:32] [DEBUG] ffmpeg: Skipping 0 bytes of junk at 764. [2018-01-22 19:14:32] [DEBUG] ffmpeg: tb:1/14112000 samplefmt:s16 samplerate:44100 chlayout:0x3 [2018-01-22 19:14:32] [DEBUG] player: Action is start [2018-01-22 19:14:32] [DEBUG] player: Action is metadata_get [2018-01-22 19:14:32] [DEBUG] main: Got worker execute request [2018-01-22 19:14:32] [DEBUG] raop: Building OPTIONS for 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:32] [ INFO] player: Using selected AirPlay device 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] artwork: Artwork request for item 4 [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT COUNT() FROM files f WHERE f.disabled = 0 AND id = 4;' [2018-01-22 19:14:32] [DEBUG] db: Starting query 'SELECT f. FROM files f WHERE f.disabled = 0 AND id = 4 ;' [2018-01-22 19:14:32] [DEBUG] cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 5024056800311776848 AND a.max_w = 600 AND a.max_h = 600;' [2018-01-22 19:14:32] [ WARN] ffmpeg: Could not update timestamps for skipped samples. [2018-01-22 19:14:32] [DEBUG] cache: No results [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 5024056800311776848;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 5024056800311776848;' [2018-01-22 19:14:32] [DEBUG] db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 5024056800311776848 ;' [2018-01-22 19:14:32] [DEBUG] raop: Local address: 192.168.1.103 (LL: no) port 56466 [2018-01-22 19:14:32] [DEBUG] db: End of query results [2018-01-22 19:14:32] [ INFO] raop: Setting up AirPlay session 2034487101 (192.168.1.103 -> 192.168.1.109) [2018-01-22 19:14:32] [DEBUG] raop: Building ANNOUNCE for 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 5024056800311776848;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT COUNT() FROM files f WHERE f.disabled = 0 AND id = 4 AND f.songalbumid = 5024056800311776848;' [2018-01-22 19:14:32] [DEBUG] db: Starting query 'SELECT f. FROM files f WHERE f.disabled = 0 AND id = 4 AND f.songalbumid = 5024056800311776848 ;' [2018-01-22 19:14:32] [DEBUG] ffmpeg: Skipping 0 bytes of junk at 764. [2018-01-22 19:14:32] [DEBUG] artwork: No artwork found in '/home/pi/music/song.mp3' [2018-01-22 19:14:32] [DEBUG] db: End of query results [2018-01-22 19:14:32] [DEBUG] artwork: No artwork found for item 4 [2018-01-22 19:14:32] [DEBUG] raop: Building SETUP for 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [ INFO] raop: Failed to retrieve artwork for file id 142; no artwork will be sent [2018-01-22 19:14:32] [DEBUG] raop: token: unicast [2018-01-22 19:14:32] [DEBUG] raop: token: mode [2018-01-22 19:14:32] [DEBUG] raop: token: record [2018-01-22 19:14:32] [DEBUG] raop: token: server_port [2018-01-22 19:14:32] [DEBUG] raop: token: control_port [2018-01-22 19:14:32] [DEBUG] raop: token: timing_port [2018-01-22 19:14:32] [DEBUG] raop: Negotiated AirTunes v2 UDP streaming session 1; ports s=1279 c=1281 t=1283 [2018-01-22 19:14:32] [DEBUG] raop: Building RECORD for 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [DEBUG] raop: RAOP audio latency is 4096 [2018-01-22 19:14:32] [DEBUG] raop: Building SET_PARAMETER for 'LG AUDIO 22EF45' [2018-01-22 19:14:32] [DEBUG] player: Callback from AirPlay to device_restart_cb [2018-01-22 19:14:32] [DEBUG] main: Command has 0 pending events [2018-01-22 19:14:32] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:32] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:32] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:32] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:32] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:32] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:32] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 19:14:32] [DEBUG] mpd: MPD message: status [2018-01-22 19:14:32] [DEBUG] player: Player status: playing (buffering) [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:32] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:14:32] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:14:32] [DEBUG] db: End of queue enum results [2018-01-22 19:14:32] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] mpd: MPD message: currentsong [2018-01-22 19:14:32] [DEBUG] player: Player status: playing (buffering) [2018-01-22 19:14:32] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:32] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:32] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 19:14:32] [DEBUG] mpd: Removing mpd client [2018-01-22 19:14:34] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:34] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:42] [ INFO] mpd: New mpd client connection accepted [2018-01-22 19:14:42] [DEBUG] mpd: MPD message: stop [2018-01-22 19:14:42] [DEBUG] raop: Building FLUSH for 'LG AUDIO 22EF45' [2018-01-22 19:14:42] [DEBUG] player: Pause called, stopping playback loop [2018-01-22 19:14:42] [DEBUG] player: Playback loop stopped (break is 1, ret 0) [2018-01-22 19:14:42] [DEBUG] player: Flushing 356028 bytes with flags 0 [2018-01-22 19:14:42] [DEBUG] player: Action is stop [2018-01-22 19:14:42] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:42] [DEBUG] player: Callback from AirPlay to device_command_cb [2018-01-22 19:14:42] [DEBUG] main: Command has 0 pending events [2018-01-22 19:14:42] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:42] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:42] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 19:14:42] [DEBUG] mpd: MPD message: status [2018-01-22 19:14:42] [DEBUG] player: Player status: stopped [2018-01-22 19:14:42] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:14:42] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 19:14:42] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:42] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:42] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:42] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:14:42] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:14:42] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:14:42] [DEBUG] db: End of queue enum results [2018-01-22 19:14:42] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:14:42] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] mpd: MPD message: currentsong [2018-01-22 19:14:42] [DEBUG] player: Player status: stopped [2018-01-22 19:14:42] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:42] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:42] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 19:14:42] [DEBUG] mpd: Removing mpd client [2018-01-22 19:14:45] [ INFO] mpd: New mpd client connection accepted [2018-01-22 19:14:45] [DEBUG] mpd: MPD message: setvol "50" [2018-01-22 19:14:45] [DEBUG] raop: Building SET_PARAMETER for 'LG AUDIO 22EF45' [2018-01-22 19:14:45] [DEBUG] mpd: Asynchronous listener callback called with event type 4. [2018-01-22 19:14:45] [DEBUG] player: Callback from AirPlay to device_command_cb [2018-01-22 19:14:45] [DEBUG] main: Command has 0 pending events [2018-01-22 19:14:45] [DEBUG] mpd: Notify clients waiting for idle results: 4 [2018-01-22 19:14:45] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:45] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 19:14:45] [DEBUG] mpd: MPD message: status [2018-01-22 19:14:45] [DEBUG] player: Player status: stopped [2018-01-22 19:14:45] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:14:45] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 19:14:45] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:45] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:45] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:45] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:14:45] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:14:45] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:14:45] [DEBUG] db: End of queue enum results [2018-01-22 19:14:45] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:14:45] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] mpd: MPD message: currentsong [2018-01-22 19:14:45] [DEBUG] player: Player status: stopped [2018-01-22 19:14:45] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:45] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:45] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 19:14:45] [DEBUG] mpd: Removing mpd client [2018-01-22 19:14:48] [ INFO] mpd: New mpd client connection accepted [2018-01-22 19:14:48] [DEBUG] mpd: MPD message: play [2018-01-22 19:14:48] [DEBUG] player: Player status: stopped [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 0 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] player: Start playback of '/home/pi/music/song.mp3' (id=4, item-id=142) [2018-01-22 19:14:48] [DEBUG] db: Running query 'SELECT f. FROM files f WHERE f.id = 4;' [2018-01-22 19:14:48] [ INFO] player: Opening '/home/pi/music/song.mp3' (id=4, item-id=142) [2018-01-22 19:14:48] [DEBUG] player: Action is setup [2018-01-22 19:14:48] [DEBUG] ffmpeg: Skipping 0 bytes of junk at 764. [2018-01-22 19:14:48] [DEBUG] ffmpeg: tb:1/14112000 samplefmt:s16 samplerate:44100 chlayout:0x3 [2018-01-22 19:14:48] [DEBUG] player: Action is start [2018-01-22 19:14:48] [DEBUG] player: Action is metadata_get [2018-01-22 19:14:48] [DEBUG] main: Got worker execute request [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:48] [ WARN] ffmpeg: Could not update timestamps for skipped samples. [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:48] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] artwork: Artwork request for item 4 [2018-01-22 19:14:48] [DEBUG] db: Running query 'SELECT COUNT() FROM files f WHERE f.disabled = 0 AND id = 4;' [2018-01-22 19:14:48] [DEBUG] db: Starting query 'SELECT f. FROM files f WHERE f.disabled = 0 AND id = 4 ;' [2018-01-22 19:14:48] [DEBUG] mpd: MPD message: command_list_ok_begin [2018-01-22 19:14:48] [DEBUG] mpd: MPD message: status [2018-01-22 19:14:48] [DEBUG] cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 5024056800311776848 AND a.max_w = 600 AND a.max_h = 600;' [2018-01-22 19:14:48] [DEBUG] player: Player status: playing (buffering) [2018-01-22 19:14:48] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:14:48] [DEBUG] cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 5024056800311776848 AND a.max_w = 600 AND a.max_h = 600; [2018-01-22 19:14:48] [DEBUG] artwork: Source 'cache' stopped search for artwork for group 5024056800311776848 [2018-01-22 19:14:48] [DEBUG] artwork: No artwork found for item 4 [2018-01-22 19:14:48] [ INFO] raop: Failed to retrieve artwork for file id 142; no artwork will be sent [2018-01-22 19:14:48] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:14:48] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:14:48] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] db: End of queue enum results [2018-01-22 19:14:48] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] mpd: MPD message: currentsong [2018-01-22 19:14:48] [DEBUG] player: Player status: playing (buffering) [2018-01-22 19:14:48] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 142 ORDER BY pos ASC;' [2018-01-22 19:14:48] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:14:48] [DEBUG] mpd: MPD message: command_list_end [2018-01-22 19:14:48] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:48] [DEBUG] mpd: Notify client #0 [2018-01-22 19:14:48] [DEBUG] mpd: Removing mpd client [2018-01-22 19:14:49] [DEBUG] player: Input buffer has 356028 bytes [2018-01-22 19:14:50] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:14:50] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:14:59] [DEBUG] player: Input buffer has 356668 bytes [2018-01-22 19:15:09] [DEBUG] player: Input buffer has 357308 bytes [2018-01-22 19:15:19] [DEBUG] player: Input buffer has 353340 bytes [2018-01-22 19:15:23] [DEBUG] raop: Got retransmit request from 'LG AUDIO 22EF45', seq_start 64407 len 1 [2018-01-22 19:15:29] [DEBUG] player: Input buffer has 353980 bytes [2018-01-22 19:15:39] [DEBUG] player: Input buffer has 354620 bytes [2018-01-22 19:15:49] [DEBUG] player: Input buffer has 355260 bytes [2018-01-22 19:15:59] [DEBUG] player: Input buffer has 355900 bytes [2018-01-22 19:16:09] [DEBUG] player: Input buffer has 356540 bytes [2018-01-22 19:16:19] [DEBUG] player: Input buffer has 357180 bytes [2018-01-22 19:16:29] [DEBUG] player: Input buffer has 353212 bytes [2018-01-22 19:16:39] [DEBUG] player: Input buffer has 353852 bytes [2018-01-22 19:16:49] [DEBUG] player: Input buffer has 354492 bytes [2018-01-22 19:16:59] [DEBUG] player: Input buffer has 355132 bytes [2018-01-22 19:17:09] [DEBUG] player: Input buffer has 355772 bytes [2018-01-22 19:17:19] [DEBUG] player: Input buffer has 356412 bytes [2018-01-22 19:17:29] [DEBUG] player: Input buffer has 357052 bytes [2018-01-22 19:17:39] [DEBUG] player: Input buffer has 353084 bytes [2018-01-22 19:17:49] [DEBUG] player: Input buffer has 353724 bytes [2018-01-22 19:17:59] [DEBUG] player: Input buffer has 354364 bytes [2018-01-22 19:18:09] [DEBUG] player: Input buffer has 355004 bytes [2018-01-22 19:18:19] [DEBUG] player: Input buffer has 355644 bytes [2018-01-22 19:18:29] [DEBUG] player: Input buffer has 356284 bytes [2018-01-22 19:18:39] [DEBUG] player: Input buffer has 356924 bytes [2018-01-22 19:18:49] [DEBUG] player: Input buffer has 352956 bytes [2018-01-22 19:18:55] [ WARN] ffmpeg: Could not update timestamps for discarded samples. [2018-01-22 19:18:55] [ WARN] xcode: Could not read frame: End of file [2018-01-22 19:18:55] [DEBUG] player: Playback loop stopped (break is 0, ret 0) [2018-01-22 19:18:57] [DEBUG] player: Switching track [2018-01-22 19:18:57] [DEBUG] player: Pause called, stopping playback loop [2018-01-22 19:18:57] [DEBUG] player: Flushing 0 bytes with flags 0 [2018-01-22 19:18:57] [DEBUG] player: Action is stop [2018-01-22 19:18:57] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:18:57] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:18:57] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (142) [2018-01-22 19:18:57] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 142;' [2018-01-22 19:18:57] [DEBUG] db: Fetch by pos: item (142) has absolute pos 0 [2018-01-22 19:18:57] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE pos = 1 ORDER BY pos ASC;' [2018-01-22 19:18:57] [DEBUG] db: End of queue enum results [2018-01-22 19:18:57] [DEBUG] db: Fetch by pos: fetched item (id=0, pos=0, file-id=0) [2018-01-22 19:18:57] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:18:57] [DEBUG] player: Reached end of queue [2018-01-22 19:18:59] [DEBUG] main: Got worker execute request [2018-01-22 19:18:59] [DEBUG] main: Got worker execute request [2018-01-22 19:18:59] [DEBUG] player: Current playing/streaming song already in history [2018-01-22 19:18:59] [DEBUG] raop: Building TEARDOWN for 'LG AUDIO 22EF45' [2018-01-22 19:18:59] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2018-01-22 19:18:59] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2018-01-22 19:18:59] [DEBUG] db: Running query 'DELETE FROM queue where id <> 0;' [2018-01-22 19:18:59] [DEBUG] db: Running query 'INSERT OR REPLACE INTO admin (key, value) VALUES ('queue_version', '373');' [2018-01-22 19:18:59] [DEBUG] db: Running query 'END TRANSACTION;' [2018-01-22 19:18:59] [DEBUG] mpd: Asynchronous listener callback called with event type 2. [2018-01-22 19:18:59] [DEBUG] mpd: Notify clients waiting for idle results: 2 [2018-01-22 19:18:59] [DEBUG] mpd: Asynchronous listener callback called with event type 1. [2018-01-22 19:18:59] [DEBUG] mpd: Notify clients waiting for idle results: 1 [2018-01-22 19:18:59] [DEBUG] player: Callback from AirPlay to device_streaming_cb [2018-01-22 19:18:59] [ INFO] player: The AirPlay device 'LG AUDIO 22EF45' stopped [2018-01-22 19:19:04] [DEBUG] db: Running query 'UPDATE files SET play_count = play_count + 1, time_played = 1516648744, seek = 0 WHERE id = 4;' [2018-01-22 19:19:07] [DEBUG] lastfm: Got LastFM scrobble request

On 22 Jan 2018, 17:09 +0100, ejurgensen notifications@github.com, wrote:

I have trouble reproducing this, also when there is no playback. E.g.: mpc enable [my speaker] mpc volume 10 mpc play mpc stop mpc volume 50 mpc play How does that sequence work for you? If it works, can you then provide me a sequence that produces unexpected behaviour? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

ejurgensen commented 6 years ago

Ok, but I wasn't so much asking for log output. Check my questions in my previous post.

gcannar commented 6 years ago

Yes the sequence that give problems is

Mpc volume Mpc play

I mean the volum control sent before playback command.

On Tue, Jan 23, 2018, 20:42 ejurgensen notifications@github.com wrote:

Ok, but I wasn't so much asking for log output. Check my questions in my previous post.

— You are receiving this because you authored the thread.

Reply to this email directly, view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/482#issuecomment-359906548, or mute the thread https://github.com/notifications/unsubscribe-auth/Ahr5O0x1sLAxDjMQt6q2oX8E6sl4OTX9ks5tNjYLgaJpZM4Rl8Rw .

ejurgensen commented 6 years ago

Does the sequence also give problems if you enable the device first, i.e.:

mpc enable [device]
mpc volume xx
mpc play

ejurgensen commented 6 years ago

Closing, no feedback

owntone / owntone-server

AirPlay volume control #482