shairport-sync metadata log errors in snapserver

[Drizzt321]

Similar to #672, I'm seeing metadata read errors from shairport-sync

Jun 25 12:57:58 snapcast-server snapserver[1482]: Error opening metadata pipe, retrying in 500ms. Error: assign: Bad file descriptorJun 25 12:58:01 snapcast-server snapserver[1482]: Waiting for metadata, retrying in 2500ms
Jun 25 12:58:01 snapcast-server snapserver[1482]: Waiting for metadata, retrying in 2500ms
Jun 25 12:58:04 snapcast-server snapserver[1482]: Waiting for metadata, retrying in 2500ms
...
...

And I just keep getting the last message continuously. Tried with only a single airplay source defined, same thing.

My /etc/snapserver.conf

[stream]
source = airplay:///usr/bin/shairport-sync?name=Airplay1&devicename=Airplay1&port=5000
source = airplay:///usr/bin/shairport-sync?name=Airplay2&devicename=Airplay2&port=5001
source = pipe:///tmp/snapfifo?name=mopidiy&codec=pcm

Unlike in #672, I'm not seeing the HAS_EXPAT not defined issue, so things seem good there. And the shairport-sync is compiled with the metadata, and in shairport config I have metadata enabled

/etc/shairport-sync.conf

metadata =
{
        enabled = "yes";
        include_cover_art = "yes";
        cover_art_cache_directory = "/tmp/shairport-sync/.cache/coverart";
};

And when I run the shairport-sync manually with the verbosity turned on, based on a ps listing from when snapserver is up and running, how it started one of the inputs.

/usr/bin/shairport-sync --name="Airplay1" --output=stdout --use-stderr --get-coverart --metadata-pipename=/tmp/shairmeta.1482.5000 --port=5000 -vvv
         0.000036806 "shairport.c:461" looking for configuration file at full path "/etc/shairport-sync.conf"
         0.000398686 "shairport.c:1729" Started!
         0.000090097 "shairport.c:1756" software version: "3.3.7-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
         0.000098353 "shairport.c:1762" log verbosity is 3.
         0.000080447 "shairport.c:1777" The processor is running little-endian.
         0.000088894 "shairport.c:1810" disable resend requests is off.
         0.000072991 "shairport.c:1811" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000086569 "shairport.c:1815" statistics_requester status is 0.
         0.000074495 "shairport.c:1817" daemon status is 0.
         0.000081989 "shairport.c:1818" daemon pid file path is "/run/shairport-sync/shairport-sync.pid".
         0.000073673 "shairport.c:1820" rtsp listening port is 5000.
         0.000083463 "shairport.c:1821" udp base port is 6001.
         0.000076248 "shairport.c:1822" udp port range is 10.
         0.000069664 "shairport.c:1823" player name is "Airplay1".
         0.000082310 "shairport.c:1824" backend is "stdout".
         0.000073512 "shairport.c:1825" run_this_before_play_begins action is "(null)".
         0.000082291 "shairport.c:1826" run_this_after_play_ends action is "(null)".
         0.000069464 "shairport.c:1827" wait-cmd status is 0.
         0.000094004 "shairport.c:1828" run_this_before_play_begins may return output is 0.
         0.000080006 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000084745 "shairport.c:1830" run_this_before_entering_active_state action is  "(null)".
         0.000091610 "shairport.c:1831" run_this_after_exiting_active_state action is  "(null)".
         0.000085738 "shairport.c:1832" active_state_timeout is  10.000000 seconds.
         0.000075276 "shairport.c:1833" mdns backend "(null)".
         0.000077821 "shairport.c:1834" userSuppliedLatency is 0.
         0.000076698 "shairport.c:1835" interpolation setting is "auto".
         0.000081710 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
         0.000077250 "shairport.c:1839" resync time is 0.050000 seconds.
         0.000074183 "shairport.c:1840" allow a session to be interrupted: 0.
         0.000081359 "shairport.c:1841" busy timeout time is 120.
         0.000072931 "shairport.c:1842" drift tolerance is 0.001995 seconds.
         0.000086328 "shairport.c:1843" password is "(null)".
         0.000069715 "shairport.c:1844" ignore_volume_control is 0.
         0.000079444 "shairport.c:1848" volume_max_db is not set
         0.000074314 "shairport.c:1849" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000072581 "shairport.c:1851" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000083392 "shairport.c:1855" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000072861 "shairport.c:1857" disable_synchronization is 0.
         0.000083373 "shairport.c:1858" use_mmap_if_available is 1.
         0.000073352 "shairport.c:1859" output_format automatic selection is enabled.
         0.000099906 "shairport.c:1863" output_rate automatic selection is enabled.
         0.000088824 "shairport.c:1867" audio backend desired buffer length is 1.000000 seconds.
         0.000084475 "shairport.c:1869" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000076639 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
         0.000073161 "shairport.c:1873" audio backend silence lead-in time is "auto".
         0.000074064 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
         0.000085978 "shairport.c:1878" decoders_supported field is 1.
         0.000072520 "shairport.c:1879" use_apple_decoder is 0.
         0.000082481 "shairport.c:1880" alsa_use_hardware_mute is 0.
         0.000073893 "shairport.c:1884" no special mdns service interface was requested.
         0.000088373 "shairport.c:1887" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000076949 "shairport.c:1894" metadata enabled is 1.
         0.000073743 "shairport.c:1895" metadata pipename is "/tmp/shairmeta.1482.5000".
         0.000087541 "shairport.c:1896" metadata socket address is "(null)" port 0.
         0.000071568 "shairport.c:1898" metadata socket packet size is "500".
         0.000082591 "shairport.c:1899" get-coverart is 1.
         0.000072691 "shairport.c:1902" mqtt is disabled.
         0.000072480 "shairport.c:1903" mqtt hostname is (null), port is 1883.
         0.000072851 "shairport.c:1904" mqtt topic is /Airplay1.
         0.000084665 "shairport.c:1905" mqtt will not publish raw metadata.
         0.000073121 "shairport.c:1906" mqtt will not publish parsed metadata.
         0.000079535 "shairport.c:1907" mqtt will not publish cover Art.
         0.000075226 "shairport.c:1908" mqtt remote control is disabled.
         0.000082902 "shairport.c:1912" convolution is 0.
         0.000073151 "shairport.c:1913" convolution IR file is "(null)"
         0.000072340 "shairport.c:1914" convolution max length 8192
         0.000087601 "shairport.c:1915" convolution gain is 0.000000
         0.000071478 "shairport.c:1917" loudness is 0.
         0.000082150 "shairport.c:1918" loudness reference level is -20.000000
         0.000129989 "rtsp.c:1665" metadata pipe name is "/tmp/shairmeta.1482.5000".
         0.002013089 "mdns_avahi.c:209" avahi: service '5073E6783275@Airplay1' group is not yet committed.
         0.000482980 "mdns_avahi.c:244" avahi: request to add "_raop._tcp" service with metadata
         0.000335905 "mdns_avahi.c:375" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000166325 "rtsp.c:158" Creating metadata queue "mqtt".
         0.000634434 "rtsp.c:158" Creating metadata queue "hub".
         0.000142294 "rtsp.c:158" Creating metadata queue "multicast".
         0.000134549 "mdns_avahi.c:213" avahi: service '5073E6783275@Airplay1' group is registering.
         0.000619242 "rtsp.c:158" Creating metadata queue "pipe".
         0.000704639 "dbus-service.c:548" >> setting loudness threshold to -20.000000.
         0.000111260 "dbus-service.c:561" >> setting drift tolerance to 0.001995 seconds
         0.000102002 "dbus-service.c:909" >> ALACDecoder set to "hammerton"
         0.000095137 "dbus-service.c:914" >> Active set to "false"
         0.000086779 "dbus-service.c:919" >> disable standby mode set to "off"
         0.000097222 "dbus-service.c:940" >> interpolation set to "auto" (soxr support built in)
         0.000088884 "dbus-service.c:456" >> deactivating disable standby
         0.000096008 "dbus-service.c:538" >> deactivating loudness
         0.000084305 "dbus-service.c:472" >> deactivating convolution
         0.000100819 "dbus-service.c:441" >> log verbosity set to 3.
         0.000086539 "dbus-service.c:428" >> stop logging statistics
         0.000092632 "dbus-service.c:390" >> stop including elapsed time in logs
         0.000084936 "dbus-service.c:400" >> start including delta time in logs
         0.000096039 "dbus-service.c:413" >> start including file and line in logs
         0.000096249 "dbus-service.c:1045" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
         0.000687904 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
         0.878244769 "mdns_avahi.c:180" avahi: service '5073E6783275@Airplay1' successfully added.
         0.622466555 "shairport.c:194" soxr_delay_index: 0.
         0.000079865 "shairport.c:200" "soxr" interpolation has been chosen.

Environment details

• OS: Debian Testing (bullseye) in VM
• Snapcast version [e.g. 0.21.0]: Debian package 0.23.0+dfsg1-1
• Shairport-Sync version: Debian Package 3.3.7-1

[Drizzt321]

Just tried updating to Snapserver 0.25.0 from https://github.com/badaix/snapcast/releases/tag/v0.25.0, and compiled/installed Shairport-sync 3.3.8 from sources. Still getting the exact same metadata log errors.

Also was just keeping an eye on the logs when connecting/playing music through Shairport-sync from my phone, and the messages went away as soon as I started playing, since then there was some amount of metadata. Even after I disconnected, the messages didn't return. So looks like when it's first starting up, if nothing connects to the Airplay endpoint(s), it assumes because nothing has come in yet, there's no metadata and keeps checking and erroring. Not sure how, if possible, to fix this so it doesn't fill up any log files.

[badaix]

This exact behavior is commented in the source:

                // For some reason, EOF is returned until the first metadata is written to the pipe.
                // If shairport-sync has not finished setting up the pipe, bad file descriptor is returned.
                LOG(INFO, LOG_TAG) << "Waiting for metadata, retrying in 2500ms\n";
                wait(pipe_open_timer_, 2500ms, [this] { pipeReadLine(); });

Whoever uses Shairpoint with metadata will eventually get rid of this message, so I don't think that the log severity must be lowered.

[capocasa]

I would request the log severity be lowered after all- I mostly use other sources than shairport so my logs get spammed up pretty good until eventually someone listens to something over airplay.

[mill1000]

I would also like to see this log severity changed.

[MJochim]

@capocasa @mill1000 I’ve had the same issue and now I’m using this configuration in /etc/snapserver.conf:

[logging]
filter = *:info,AirplayStream:notice

Suppresses all INFO-level messages, but only those from Airplay. Since I rarely use Airplay, that’s a good compromise for me. Maybe it works for you as well.

[mill1000]

Nice trick! 👍

[badaix]

Could be fixed in v0.28.0-beta.1 with fcac07b

As I don't have a Shairportsync setup running, I didn't test it.

[badaix]

@mill1000 @capocasa @Drizzt321 @MJochim
Can anyone try it out please?

[mill1000]

I've been running 0.28.1 for a few days now. It looks to be working OK.

I have noticed that logseverity is declared static and thus the Waiting for metadata, retrying in message is only emitted once per-execution at INFO level. This may have been unintentional as it would seem reasonable to expect this message per-stream

2024-03-28 13-46-35.189 [Info] (Snapserver) Version 0.28.0.1
2024-03-28 13-46-35.224 [Error] (AirplayStream) Error opening metadata pipe, retrying in 500ms. Error: assign: Bad file descriptor [system:9 at /usr/include/boost/asio/detail/impl/reactive_descriptor_service.ipp:120 in function 'assign']
2024-03-28 13-46-35.226 [Error] (AirplayStream) Error opening metadata pipe, retrying in 500ms. Error: assign: Bad file descriptor [system:9 at /usr/include/boost/asio/detail/impl/reactive_descriptor_service.ipp:120 in function 'assign']
2024-03-28 13-46-35.229 [Error] (AirplayStream) Error opening metadata pipe, retrying in 500ms. Error: assign: Bad file descriptor [system:9 at /usr/include/boost/asio/detail/impl/reactive_descriptor_service.ipp:120 in function 'assign']
2024-03-28 13-46-35.725 [Info] (AirplayStream) Metadata pipe opened: /tmp/shairmeta.7.5000
2024-03-28 13-46-35.726 [Info] (AirplayStream) Waiting for metadata, retrying in 2500ms
2024-03-28 13-46-35.727 [Info] (AirplayStream) Metadata pipe opened: /tmp/shairmeta.7.5001
2024-03-28 13-46-35.729 [Info] (AirplayStream) Metadata pipe opened: /tmp/shairmeta.7.5002

[badaix]

Thanks for testing @mill1000, good catch, there could indeed be more than one instance of the airplay stream. Should be fixed now.

[badaix]

Fixed in version 0.28.0