Shairport-sync: Heavy Delay on MQTT

[dejanzelic]

Hello!
I'm having issues with the MQTT set up in Shairport. The messages come in with a very long delay (sometimes 4+ minutes). When messages come in, they do not all update at the same time. For example, there are many times that the artist and title do not match up. I am also subscribing to the play_start, play_end, play_resume, and play_flush topics which also have a very long delay.

shairport-sync -V
3.3.6-OpenSSL-Avahi-ALSA-pa-stdout-pipe-soxr-metadata-mqtt-sysconfdir:/etc

Here is the Dockerfile with the build of Shairport highlighted: https://gitlab.com/dejandayoff/snapserver-spotify/-/blob/master/Dockerfile#L16-53

Here is the configuration for MQTT:

mqtt =
{
        enabled = "yes";
        hostname = "192.168.1.100";
        port = 1883;
        topic = "shairport-sync/snapcast";
        publish_parsed = "yes";
        publish_cover = "no";
        enable_remote = "no";
        username = "REDACTED";
        password = "REDACTED";
}

I am running Shairport via the Snapcast configuration. The Shairport server and MQTT are on the same subnet with very low latency.

I turned off cover reporting to make sure it wasn't being slowed down by having to send a larger file.

Any help would be appreciated!

I'm having a difficult time finding log files since Snapcast starts Shairport so the logs are not in journalctl like discussed here: https://github.com/mikebrady/shairport-sync/issues/727

[mikebrady]

Thanks for the post. Hmm, not too sure where to start on this. It may be that Shairport Sync isn't generating any log entries. Try setting the log_verbosity to 1 in the configuration file, which would normally be at /etc/shairport-sync.conf. Then see if any shairport-sync entries are turning up anywhere.

[dejanzelic]

Thank you for the quick reply!

I set log_verbosity in both the diagnostics section and the general section. Searching for anything that includes shairport-sync comes up with the following items:

root@208f205992f7:/var/log/supervisor# find / -name *shairport-sync*
/usr/bin/shairport-sync
/etc/shairport-sync.conf
/tmp/shairport-sync-metadata
/tmp/shairport-sync

Snapcast is started with supervisord and when I look any logs that relate to Shairport, the following is the most relevant (However I think that this is Snapcast's logs and not Shairport's)

2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) make_lpf(n=89 Fc=0.4178769 β=11.0993 ρ=0.5 scale=1)
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) fir_len=89 dft_length=1024 Fp=0.67627 Fs=1 Fn=2.0057 att=108.371 2/1
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) make_lpf(n=4211 Fc=0.002315827 β=11.2846 ρ=0.63 scale=351)
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) fir_len=12 phases=351 coef_interp=0 size=16.8k
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) 0.997159: »0⋅2/0⋅351/704⋅1/1
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay)     0|0     preload=22 remL=0 o/i=2
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay)     0|11    preload=5 remL=0 o/i=0.49858
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay) 0.997159: »0⋅2/0⋅351/704⋅1/1
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay)     0|0     preload=22 remL=0 o/i=2
2020-05-14 18-33-24 [Info] (AirplayStream) (Airplay)     0|11    preload=5 remL=0 o/i=0.49858

I searched the entire file system for "shairport-sync" and except for the config file the only thing I found was:

/var/log/supervisor/snapserver-stdout---supervisor-1NHp9f.log:2020-05-14 18-33-22 [Info] (main) Adding stream: airplay:///shairport-sync?name=Airplay&devicename=Home
/var/log/supervisor/snapserver-stdout---supervisor-1NHp9f.log:2020-05-14 18-33-22 [Info] (start) Stream: {"fragment":"","host":"","path":"/shairport-sync","query":{"chunk_ms":"20","codec":"flac","devicename":"Home","name":"Airplay","sampleformat":"44100:16:2"},"raw":"airplay:////shairport-sync?chunk_ms=20&codec=flac&devicename=Home&name=Airplay&sampleformat=44100:16:2","scheme":"airplay"}

FWIW, this is the command I ran find / -xdev -type f -print0 | xargs -0 grep -H "shairport-sync"

I tried to start Shairport with a pipe backend so that I don't have to use Snapcast as the method of execution, but I ran into other issues with crackling (This might have been a Snapcast issue, I wasn't able to diagnose.)

[mikebrady]

Thanks. I'm afraid I'm a bit stumped. If it were possible, it would be interesting to build Shairport Sync as a stand-alone, maybe outputting to an ALSA device and seeing if the issue with MQTT remains.

[dejanzelic]

That's a good idea, I'll do that and report back. I have another docker container with only Shairport that I can give this a try with.

[dejanzelic]

Looks like the issue is somehow caused when Snapcast spawns Shairport.
Here are the steps that I took:

1) Stopped Snapcast instance
2) Started Shairport using the same command Snapcast uses /usr/bin/shairport-sync --name="Home" --output=stdout --metadata-pipename /tmp/shairmeta.17 --port=5000
3) Observe MQTT

When Shairport is called directly, I have no issues with MQTT and every change is instant. However, when I start Shairport with Snapcast, the MQTT delay is back.

I also attempted to redirect STDOUT of the Shairport process spawned by Snapcast to a file using reredirect. However, since Snapcast write uses the STDOUT of Shairport as the output, anytime I play something, the file becomes very large and unusable for logs.

I'll keep poking around later today and see if I can get anything else, but I'm kind of stuck too.

All I really need is a boolean if something is being played or not. Worst case scenario if we can't figure this out, I'll create a script to scrape the Snapcast log files and send an MQTT message if something is playing. It's not ideal, but accomplishes what I'm looking for.

Please let me know if you have any ideas or if there is a way to log to a specific file.

[dejanzelic]

I looked into it more and wasn't able to get anywhere. I was able to diagnose that it is not a network issue by doing a tcpdump. I was, however, able to accomplish what I was looking for in a different way. If anyone else runs into this issues, I was able to get the current status by using the following in the Shairport configuration file:

sessioncontrol =
{
      run_this_before_play_begins = "/mqtt_start.sh";
      run_this_after_play_ends = "/mqtt_stop.sh"; 
};

The mqtt_start.sh and mqtt_stop.sh script publish to the topic that I set via an environmental variable. This can be seen in the Docker repo (https://gitlab.com/dejandayoff/snapserver-spotify/). It's not ideal, but it accomplishes what I needed.

I'll leave this open incase this is something you want to continue looking into @mikebrady but feel free to close it if not.

Thank you for your help!

[burol]

Hi Dejan
Thank you very much for sharing the solution approach in the last post. It's exactly what I was looking for!
Regards
Roland

[mikebrady]

Hi there. Still looking into this issue. Can you clarify if these steps that you mentioned above will still cause the problem?

[dejanzelic]

Correct I am still having the same issues. It is also still true when I run Shairport directly that it does not have issues with mqtt. Here is something that might make debugging this a bit easier: https://gist.github.com/dejanzelic/87b1eb708431109ead610b53ad5d8408

Not sure if you are familiar with docker, but if you save these files you can run docker-compose up to start the containers.

If you run docker-compose exec snapcast /bin/bash you can get a bash shell in the container. I used mqtt-explorer to connect to the host I started docker from.

Note: Since this uses "network_mode: host" running this on mac won't work (I'm unsure about Windows, but I'm guessing it won't work either.) I set up a Ubuntu VM with Docker and docker-compose installed to get it to work. Let me know if you have trouble starting it.

[mikebrady]

That's very useful, thanks.

[mikebrady]

That's been very useful indeed, thanks. I am not familiar with either docker or snapcast, so it's quite a learning curve, but I can reproduce the delay. I need to modify Shairport Sync so that logs can be directed to STDOUT or STDERR instead of the syslog using a configuration file setting. It's already available as a command-line option -u. Then I need to build a docker image of my own rather than rely on dejandayoff's.

The MQTT subsystem in Shairport Sync is part of the metadata subsystem which runs on its own thread. It is responsible for writing to the metadata pipe as well as to MQTT. I am guessing that writing to the metadata pipe is bogging down due to some interaction with snapcast, but it's only a guess. I need to get to the point where I can debug it. The metadata subsystem also is responsible for some dbus interactions. Therefore, the following might be important: Running on Ubuntu 20.04 inside a VM (on a Mac), an odd thing I got using your setup was:

mike@ubuntu:~/87b1eb708431109ead610b53ad5d8408-be64040c3077b0eab13fdcb0324a7e5075d6d925$ docker-compose up
Starting snapserver ... done
Starting mqtt       ... done
Attaching to snapserver, mqtt
mqtt                 | 1590573203: mosquitto version 1.6.9 starting
mqtt                 | 1590573203: Config loaded from /mosquitto/config/mosquitto.conf.
mqtt                 | 1590573203: Opening ipv4 listen socket on port 1883.
mqtt                 | 1590573203: Opening ipv6 listen socket on port 1883.
snapserver           | rm: cannot remove '/var/run/dbus': Device or resource busy
mqtt                 | 1590573204: New connection from 127.0.0.1 on port 1883.
mqtt                 | 1590573204: New client connected from 127.0.0.1 as mqtt-explorer-0ba4a6b5 (p2, c1, k60).
snapserver           | 2020-05-27 09:53:28,764 CRIT Supervisor running as root (no user in config file)
snapserver           | 2020-05-27 09:53:28,767 INFO supervisord started with pid 13
snapserver           | 2020-05-27 09:53:29,769 INFO spawned: 'avahi' with pid 16
snapserver           | 2020-05-27 09:53:29,771 INFO spawned: 'snapserver' with pid 17
snapserver           | 2020-05-27 09:53:29,773 INFO exited: avahi (exit status 255; not expected)
mqtt                 | 1590573209: New connection from 127.0.0.1 on port 1883.
mqtt                 | 1590573209: New client connected from 127.0.0.1 as "Test" (p1, c1, k60).
snapserver           | 2020-05-27 09:53:30,770 INFO success: snapserver entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
snapserver           | 2020-05-27 09:53:30,774 INFO spawned: 'avahi' with pid 31
snapserver           | 2020-05-27 09:53:32,696 INFO success: avahi entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Is the line:

snapserver           | rm: cannot remove '/var/run/dbus': Device or resource busy

important at all?

[dejanzelic]

Oh interesting. I didn't realize that the metadata subsytem is responsible for dbus interaction as well. That error comes from this line when starting snapserver: https://gitlab.com/dejandayoff/snapserver-spotify/-/blob/master/start.sh#L7

That was a left over from someone elses docker container that I used to build mine out. Since I'm mounting /var/run/dbus as a volume in the docker-compose, I think that the error is coming from me trying to delete an entire volume (which shouldn't work). I would say it's safe to ignore that error.

FWIW, I use dbus for avahi in that container and avahi is working fine.

[mikebrady]

May thanks. So, I have modified the development branch of Shairport Sync so that it can direct its logs to a file, so I can actually see what it's doing. The metadata subsystem is definitely misbehaving.

[mikebrady]

Early indications are that the problem is that the metadata pipe is backing up from time to time.

That is, SnapCast seems to totally stop reading the metadata, and this blocks the metadata system. Shairport Sync takes too long and tries too hard to wait for the pipe to resume, so eventually everything backs up. Eventually it backs up into the dbus system and the remote control scanner.

Tomorrow, I'll fix it by getting Shairport Sync to respond to a faulty metadata pipe more quickly.

[mikebrady]

It seems like I was right about SnapCast. For some reason it opens the metadata pipe for reading but then stops reading it or maybe never reads it. Anyway, this was causing the metadata system in Shairport Sync to back up, block and sometimes even crash.

So, I've pushed an update which has separate threads for the (1) metadata pipe and multicast, (2) MQTT and (3) the supply of metadata to the dbus and MPRIS interfaces. If one of them blocks, it won't affect the others.

Another change is to use more standard code when writing both to the audio the metadata pipes.

I've also added a new setting: log_output_to in the diagnostics part of the configuration file – it can be set to syslog (default), stdout, stderr or a path to a file or pipe, e.g. /var/log/shairport-sync.log. I was able to use this to observe the diagnostics coming from Shairport Sync while in that Docker container you kindly specified.

I changed the diagnostics part of the shairport-sync.conf file you specified to:

diagnostics =
{
//        statistics = "yes"; // set to "yes" to print statistics in the log
    log_output_to = "/var/log/shairport-sync.log";
        log_verbosity = 2; // "0" means no debug verbosity, "3" is most verbose.
};

I made some changes to the Dockerfile in the Snapserver-spotify folder to make it point to the development version of Shairport Sync:

I changed line 38 to:

RUN wget https://github.com/mikebrady/shairport-sync/archive/development.tar.gz \

and lines 96 and 97 to:

COPY --from=shairportBuilder /shairport-sync-development/shairport-sync /usr/bin/shairport-sync
COPY --from=shairportBuilder /shairport-sync-development/scripts/shairport-sync.conf /etc/shairport-sync.conf

I've been experimenting with it now for quite a while and it seems to be working. Sure enough, the metadata pipe is blocking, but the MQTT stuff is all working. TBH, I haven't tested the actual audio itself in this configuration, though of course it works in a standard configuration.

Anyway, if you got a chance to play with it at your leisure, it would be great to get your feedback.

[dejanzelic]

Sorry for the slow reply but it's working! Thank you!

[mikebrady]

Many thanks for your help.