Airplay to volumio don't work

[cmoulliard]

Issue

When we redirect the sound output on a macbook to use airplay, then volumio UI displays the airplay symbol but we can't hear anything. Do I miss something ? Do we have to configure something ?

Volumio log is not really verbose

2019-02-09T17:20:20.914Z - info: CoreStateMachine::setConsumeUpdateService undefined
2019-02-09T17:20:20.915Z - info: Airplay started streaming
2019-02-09T17:20:20.915Z - info: CoreCommandRouter::volumioStop
2019-02-09T17:20:20.916Z - info: CoreStateMachine::stop
2019-02-09T17:20:20.916Z - info: CoreStateMachine::serviceStop
2019-02-09T17:20:20.916Z - info: CoreCommandRouter::serviceStop

Any idea bout the origin of the problem ? Can we debug such issue ? @volumio

[cmoulliard]

Can someone have a look please and tell me what is the problem ?

[xipmix]

I can't find the log 'Airplay started streaming' in the code, the closest is

https://github.com/volumio/Volumio2/blob/2488f384538546350daead0ec9c4ab706450c79a/app/plugins/music_service/airplay_emulation/index.js#L225

Can you please tell what version you are finding this with, or perhaps just send a full log of a simple: boot, airplay, sendlog sequence (https://volumio.github.io/docs/User_Manual/Sending_logs_for_troubleshooting.html)

[cmoulliard]

here is the log : http://logs.volumio.org/volumio/u4xq76N.html Version used: 2.668

[xipmix]

Thanks

Jan 04 09:05:47 volumio volumio[1172]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received airplay_emulation

Just to clarify - did you have a webradio playing before trying to send an airplay stream to volumio? It's fine either way.

[xipmix]

This is interesting, but not sure it's relevant yet. Throughout the whole time mpd.log is seeing this:

Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun
Jan 06 09:05 : player: Decoder is too slow; playing silence to avoid xrun

it stops about 10:41, unclear why.

But you were getting sounds out, correct? eg here in the volumio.log you can see a webradio being played

Jan 04 09:06:24 volumio volumio[1172]: info: CoreCommandRouter::volumioPlay
Jan 04 09:06:24 volumio volumio[1172]: UNSET VOLATILE
Jan 04 09:06:24 volumio volumio[1172]: info: CoreStateMachine::play index undefined
Jan 04 09:06:24 volumio volumio[1172]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 04 09:06:24 volumio volumio[1172]: info: CorePlayQueue::getTrack 0
Jan 04 09:06:24 volumio volumio[1172]: info: CoreStateMachine::startPlaybackTimer
Jan 04 09:06:24 volumio volumio[1172]: info: CorePlayQueue::getTrack 0
Jan 04 09:06:24 volumio volumio[1172]: info: [1578128784390] ControllerWebradio::clearAddPlayTrack
Jan 04 09:06:24 volumio volumio[1172]: info: ControllerMpd::sendMpdCommand stop
Jan 04 09:06:24 volumio volumio[1172]: info: sending command...
Jan 04 09:06:24 volumio volumio[1172]: info: parsing response...
Jan 04 09:06:24 volumio volumio[1172]: info: ControllerMpd::sendMpdCommand clear
Jan 04 09:06:24 volumio volumio[1172]: info: sending command...
Jan 04 09:06:24 volumio volumio[1172]: info:
Jan 04 09:06:24 volumio volumio[1172]: ---------------------------- MPD announces system playlist update
Jan 04 09:06:24 volumio volumio[1172]: info: Ignoring MPD Status Update
Jan 04 09:06:24 volumio volumio[1172]: info: parsing response...
Jan 04 09:06:24 volumio volumio[1172]: info: ControllerMpd::sendMpdCommand load "https://radios.rtbf.be/classic21-128.mp3"
Jan 04 09:06:24 volumio volumio[1172]: info: sending command...
Jan 04 09:06:24 volumio volumio[1172]: info:

but mpd.log is complaining about "Decoder too slow" all the while.

[xipmix]

Ok I found the old log message, it changed in c65814a7e25c282da1ac037d027b4212b400531f . As you can see from the history https://github.com/volumio/Volumio2/commits/c65814a7e25c282da1ac037d027b4212b400531f/app/plugins/music_service/airplay_emulation/index.js there have been quite some changes to this module since November so I recommend trying the latest available (2.692, 19 Dec) on a separate SD card to see if things work better.

[cmoulliard]

Question: As volumio, when installed, also includes the git folder (= Nov 14 for release 2.668), can I pull the commit sha of the release 2.692 to test it ? @xipmix

[cmoulliard]

I re-installed 2.692 on my PiBox and tested again from my mac airplay. While Volumio sees it (see screenshot), we cannot hear anything.

Remark The web radio was not started at all during the test ! Log: http://logs.volumio.org/volumio/e0OPthG.html

@xipmix

[xipmix]

Thanks for doing that, it helps. This is all delightfully confusing. However there does seem to be an error in the logs that may be part of the problem:

Jan 07 08:00:51 volumio volumio[910]: info: Shairport-Sync Started
Jan 07 08:00:51 volumio volumio[910]: Error adding Membership: Error: addMembership EINVAL
Jan 07 08:00:51 volumio volumio[910]: info: Shairport-Sync Started

The error comes from here https://github.com/volumio/Volumio2/blob/2488f384538546350daead0ec9c4ab706450c79a/app/plugins/music_service/airplay_emulation/shairport-sync-reader/shairport-sync-reader-udp.js#L12-L18 but I have no idea what could cause it. Next step would be to try and examine the 'opts' object, something like

            } catch(e){
-                                console.log('Error adding Membership: '+e)
+                                console.log('Error adding Membership: '+e);
+                                console.log('opts.address: "'+opts.address+'"");
+// more ambitious, may not work
+                                const util = require('util');
+                                console.log(util.inspect(opts, {depth: null}));
                }

[cmoulliard]

I updated the js file as you suggested but I cannot see the errors under either /var/log/volumio.log and journactl only reports

Jan 07 13:16:44 volumio shairport-sync[2236]: {"time":1578403003690,"response":"airplayInactive Success"}  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
Jan 07 13:16:44 volumio shairport-sync[2236]: Dload  Upload   Total   Spent    Left  Speed
Jan 07 13:16:44 volumio sudo[9740]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jan 07 13:16:44 volumio volumio[910]: info: Airplay started streaming, receiving metadatas
Jan 07 13:16:44 volumio volumio[910]: info: CoreStateMachine::getState
Jan 07 13:16:44 volumio volumio[910]: info: Airplay started streaming, receiving metadatas
Jan 07 13:16:44 volumio volumio[910]: info: CoreStateMachine::getState
Jan 07 13:16:44 volumio shairport-sync[2236]: 0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
Jan 07 13:16:44 volumio shairport-sync[2236]: Dload  Upload   Total   Spent    Left  Speed

I see nevertheless this message Jan 07 08:04:10 volumio shairport-sync[1040]: Failed to create secure directory (/home/shairport-sync/.config/pulse): No such file or directory

Even if I create the directory, the problem is still there

ls -la /home/shairport-sync/.config/
total 12
drwxr-xr-x 2 volumio volumio 4096 Jan  7 14:00 .
drwxr-xr-x 3 root    root    4096 Jan  7 14:00 ..

Here is the config file created

-rw-r--r-- 1 volumio volumio 705 Jan  7 08:00 /tmp/shairport-sync.conf
volumio@volumio:~$ cat /tmp/shairport-sync.conf
general =
{
    name = "Volumio";
};

diagnostics =
{
    log_verbosity = 0;
};

alsa =
{
  output_device = "plughw:1,0";

};

sessioncontrol =
{
  allow_session_interruption = "yes";
  run_this_before_play_begins= "/usr/local/bin/volumio startairplayplayback";
  run_this_after_play_ends = "/usr/local/bin/volumio stopairplayplayback";
  run_this_before_entering_active_state="/usr/local/bin/volumio airplayactive";
  run_this_after_exiting_active_state="/usr/local/bin/volumio airplayinactive";
};

metadata =
{
    enabled = "yes";
    include_cover_art = "no";
    //pipe_name = "/tmp/shairport-sync-metadata";
    //pipe_timeout = 5000;
    socket_address = "127.0.0.1";
    socket_port = 5555;
};

Shairport version: shairport-sync -V 3.3.5-OpenSSL-Avahi-ALSA-soxr-metadata-dbus-sysconfdir:/etc

FYI, the connection is well created for localhost and port 5555

Here is the stack trace of the error

Error: addMembership EINVAL
    at _errnoException (util.js:1022:11)
    at Socket.addMembership (dgram.js:615:11)
    at Socket.<anonymous> (/volumio/app/plugins/music_service/airplay_emulation/shairport-sync-reader/shairport-sync-reader-udp.js:14:27)
    at emitNone (events.js:106:13)
    at Socket.emit (events.js:208:7)
    at startListening (dgram.js:156:10)
    at _handle.lookup (dgram.js:273:7)
    at _combinedTickCallback (internal/process/next_tick.js:141:11)
    at process._tickCallback (internal/process/next_tick.js:180:9)

I uploaded a new log : http://logs.volumio.org/volumio/LWlyME3.html

Question : Could the problem be related to this error I see in the log ?

info: Reloading queue from file
info:  message= [50@0] {} No such directory, stack=Error:  [50@0] {} No such directory
    at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:14)
    at Socket.<anonymous> (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:10)
    at emitOne (events.js:116:13)
    at Socket.emit (events.js:211:7)
    at addChunk (_stream_readable.js:263:12)
    at readableAddChunk (_stream_readable.js:246:13)
    at Socket.Readable.push (_stream_readable.js:208:10)
    at Pipe.onread (net.js:607:20)

@xipmix

[cmoulliard]

Question: As alsa is apparently configured to use the HDMI card, how can volumio change the config to use the BossDAC (= card 1) ?

Useful references:

• http://blog.scphillips.com/posts/2013/01/sound-configuration-on-raspberry-pi-with-alsa/
• https://www.raspberrypi-spy.co.uk/2019/06/using-a-usb-audio-device-with-the-raspberry-pi/

aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: ALSA [bcm2835 ALSA], device 0: bcm2835 ALSA [bcm2835 ALSA]
  Subdevices: 7/7
  Subdevice #0: subdevice #0
  Subdevice #1: subdevice #1
  Subdevice #2: subdevice #2
  Subdevice #3: subdevice #3
  Subdevice #4: subdevice #4
  Subdevice #5: subdevice #5
  Subdevice #6: subdevice #6
card 0: ALSA [bcm2835 ALSA], device 1: bcm2835 IEC958/HDMI [bcm2835 IEC958/HDMI]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: ALSA [bcm2835 ALSA], device 2: bcm2835 IEC958/HDMI1 [bcm2835 IEC958/HDMI1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: BossDAC [BossDAC], device 0: Boss DAC HiFi [Master] pcm512x-hifi-0 [Boss DAC HiFi [Master] pcm512x-hifi-0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

cat /usr/share/alsa/alsa.conf | more

defaults.ctl.card 0
defaults.pcm.card 0

[cmoulliard]

@xipmix I was able to resolve the issue but it will be needed now that we extend the code of the plugins : airplay_emulation and audio_interface/alsa_controller

In my case, the alsa config of the file /tmp/shairport-sync.conf generated by the plugin app/plugins/music_service/airplay_emulation is wrong

general =
{
    name = "Volumio";
};

alsa =
{
  output_device = "plughw:1,0";

That works if I stop the volumio service systemctl stop volumio and next that I start manually the shairport-sync service

/usr/local/bin/shairport-sync --configfile=/tmp/shairport-sync.conf

using the following modified alsa section

general =
{
    name = "Volumio";
};

alsa =
{
  output_device = "hw:BossDAC";
  mixer_control_name = "Digital";
}
...

FYI, here is the alsamixer information reported on my Pi Box explaining why I chosen such output_device and mixer_control_name

and ticket created to discuss the problem with shairport-sync project: https://github.com/mikebrady/shairport-sync/issues/952

FYI, digital is well detected/displayed under General Playback option.

[ashthespy]

The current state of getting mixer names out of audio_interface/alsa_controller is quite bad. I dug into it a while back, and gave up as there are bits and pieces sprinkled across the codebase to handle different devices/mixers. But it's not up on the priority, as only a handful of plugins need this info, with majority of the heavy lifting being done my mpd.

[cmoulliard]

The fix to apply is very simple as currently the template - https://github.com/volumio/Volumio2/blob/master/app/plugins/music_service/airplay_emulation/shairport-sync.conf.tmpl#L13-L14 is missing the following line

  mixer_control_name = "${mixer}";

[ashthespy]

^You will also need to cover the case of mixer_device being different from the output card. IIRC, some of the Allos need this.

[cmoulliard]

What should be then the test to add here within the code - https://github.com/volumio/Volumio2/blob/b13c1fadd4d3bd4dc57e3db065afd6823ca59cba/app/plugins/music_service/airplay_emulation/index.js#L150 ?

[volumio]

IMHO the best way would be to let volume control be handled by Volumio, and not directly on alsa itself.

[cmoulliard]

IMHO the best way would be to let volume control be handled by Volumio, and not directly on alsa itself.

Could you please explain because from what I know about volumio, the plugin airplay_emulation relies on the information collected by the volumio alsa plugin and then use different vars to configure the shairport-sync service ...

BTW, Mike Brady of shairport-sync project recommends to define the hw and mixer_control_name: https://github.com/mikebrady/shairport-sync#examples

@volumio

[ashthespy]

IMHO the best way would be to let volume control be handled by Volumio, and not directly on alsa itself.

The current crop of non mpd sources (shairport,snapcast,spop,vollibrespot) all hook directly in to ALSA anyway for playback, so to trigger events from each of them for a volume change, that is then passed on to Volumio, that then calls amixer seems a bit roundabout. A more elegant option (IMO) would be for Volumio to expose the mixer information via a suitable API, and then hook into alsa to trigger volume events, irregardless of the source. I wrote quick N-API hack that does this, but never got to wrapping it into a proper node package.

[volumio]

I say this because there are situations where volume is not directly controlled by alsa. For example: a device that uses hardware to change volume (like allo stepped attenuator) or using an external i2c command to change volume on a microcontroller. There are several situations like that and leaving Volumio to handle volume would make such scenarios work as they are supposed to

[ashthespy]

^Fair point.. Could look into snd-dummy or something like that to propagate volume changes from each of those daemons -> Volumio. Else I don't see it being easy to get out Volume events without sinking deep hooks into each daemon. (I already do this for vollibrespot, but its still single direction only)