issue with the shairport - no sound

[heapxor]

the latest dietpi version doesnt make any sound when using shairport-sync

last 3 comments here describe the issues.

https://github.com/mikebrady/shairport-sync

[MichaIng]

Many thanks for your report.

last 3 comments here describe the issues.

Please fix the link. Also a brief explanation here would not be bad, including which SBC/device is used etc 😉.

[Joulinar]

I guess this is a related forum post https://dietpi.com/phpbb/viewtopic.php?t=9028

[heapxor]

hello, what link do u mean? internet connection? SCB used is odroid xu4; https://www.amazon.com/Reiyin-WT-04-Bluetooth-Transmitter-Technology/dp/B077D4RKFD => bluetooth transmitter

[MichaIng]

You said "last 3 comments here" above but gave a link to the repository root.

Okay there is a lot of multiple issues linked, with very different problems/questions, so I lost the overview of what your particular issue or question is now.

It seems you try to get it working with Bluetooth speakers? Does it work when playing an audio file from the DietPi system itself? Since setting up Bluetooth speakers with ALSA is not trivial: #3456

[Joulinar]

@MichaIng The requestor posted some additional info on our forum. Probably you can have a look. I would recommend to continue the discussion on GitHub to avoid working on both Forum + GitHub.

[heapxor]

@MichaIng what i am trying to do is to stream (using roonlabs.com roon-bridge app) via airplay to dietpi and dietpi will forward it to the the bluetooth transmitter plugged into it ... so music will be playbacked on the bluetooth speaker (bose mini) connected to the dietpi via bluetooth transmitter. This doesnt work; sound is chopping or there is no sound.

When i tried more simple scenario to stream (using roonlabs.com) using roon-bridge to dietpi and let it forward sound bluetooth transmitter connected to bose bluetooth spekaer all works fine.

[MichaIng]

Okay, so generally playing through the Bluetooth speakers works.

Is the regular USB disconnects in dmesg still a thing and does it also happen when going with the second scenario, skipping airplay?

And how did you set up the ALSA (if so) to use the Bluetooth transmitter/speakers?

[heapxor]

Hi, yes; you are correct, only once streaming via airplay doesnt work.

Yes it sometimes show up in dmesg. i dont know why / and how often, mostly if pc is idling.

I didnt do any setup of ALSA, I assume it happened somehow using roon-bridge.

[MichaIng]

The USB disconnects is what I'd take care of first. That's on a level where audio is not involved at all but different players handle such disconnects differently. I saw some of the Shairport Sync errors were about device "in use"/"busy", probably Shairport Sync blocks on a disconnect while Roon alone releases immediately, or so.

Bad that the XU4 had a single USB port only. dmesg does not report any voltage/power issues, does it? Not sure if applicable, but aside of verifying that the BT transmitter sits tight and connector clean, probably you have another USB device that you can test on that port, just to see whether it get's disconnected regularly as well?

I didnt do any setup of ALSA, I assume it happened somehow using roon-bridge.

Probably Roon Bridge accesses audio devices directly somehow. I've no experience with it but will have a look into its config files.

[heapxor]

@michalng you are right, i also tried Banana Pi BPI-M1 and there are also disconnects. But at least on bpi-m1 i can get some sound via airplay - chopped one. I just plugged usb BT to rpi4 to leave it on for 24h if there will be any disconnect in dmesg.

What do you mean by single usb port only - it has 3 usb ports i think. No, no issue with voltage/power i have original adaptors - enought Ampers so by that way all is stable.

The device sits tight and all is clean; i can guarantee ... so maybe its issue of the vendor who created that BT - some incompatibility with drivers/kernel? Do I have to try other BT? I found https://avantree.com/dg60-bluetooth-usb-audio-transmitter#spec-tab and seller confirmed it can handle more then 44k sample rate and its compatible with linux.

Yes, so many "in use"/"busy" so i have no clue why? Disconnects happened lets say 4x in 24hours... so i dont believe the disconnects are connected with "in use"/"busy"

" Probably Roon Bridge accesses audio devices directly somehow. " -> i think so, or can get confirmed from roon folks.

Any idea what to do now?

[heapxor]

@MichaIng so running rpi4 with ropiee 30min ... here u can see also disconnects

[    9.839397] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
[    9.839453] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   29.329144] sched: RT throttling activated
[  603.424978] usb 1-1.4: USB disconnect, device number 3
[  603.742443] usb 1-1.4: new full-speed USB device number 4 using xhci_hcd
[  603.886274] usb 1-1.4: New USB device found, idVendor=0a12, idProduct=1004, bcdDevice=36.06
[  603.886282] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  603.886290] usb 1-1.4: Product: REIYIN Bluetooth Audio WT04
[  603.886297] usb 1-1.4: SerialNumber: ABCDEF0123456789
[  603.967748] input: REIYIN Bluetooth Audio WT04 Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0003/input/input2
[  604.032660] input: REIYIN Bluetooth Audio WT04 as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0003/input/input3
[  604.032962] hid-generic 0003:0A12:1004.0003: input,hiddev96,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input3
[  604.040262] hid-generic 0003:0A12:1004.0004: hiddev97,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input4
[ 1205.373182] usb 1-1.4: USB disconnect, device number 4
[ 1205.825629] usb 1-1.4: new full-speed USB device number 5 using xhci_hcd
[ 1205.970782] usb 1-1.4: New USB device found, idVendor=0a12, idProduct=1004, bcdDevice=36.06
[ 1205.970790] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1205.970797] usb 1-1.4: Product: REIYIN Bluetooth Audio WT04
[ 1205.970804] usb 1-1.4: SerialNumber: ABCDEF0123456789
[ 1206.065249] input: REIYIN Bluetooth Audio WT04 Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0005/input/input4
[ 1206.125843] input: REIYIN Bluetooth Audio WT04 as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0005/input/input5
[ 1206.126130] hid-generic 0003:0A12:1004.0005: input,hiddev96,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input3
[ 1206.131516] hid-generic 0003:0A12:1004.0006: hiddev97,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input4
[ 1807.065202] usb 1-1.4: USB disconnect, device number 5
[ 1807.484074] usb 1-1.4: new full-speed USB device number 6 using xhci_hcd
[ 1807.627740] usb 1-1.4: New USB device found, idVendor=0a12, idProduct=1004, bcdDevice=36.06
[ 1807.627749] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1807.627756] usb 1-1.4: Product: REIYIN Bluetooth Audio WT04
[ 1807.627764] usb 1-1.4: SerialNumber: ABCDEF0123456789
[ 1807.711959] input: REIYIN Bluetooth Audio WT04 Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0007/input/input6
[ 1807.774263] input: REIYIN Bluetooth Audio WT04 as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:0A12:1004.0007/input/input7
[ 1807.774552] hid-generic 0003:0A12:1004.0007: input,hiddev96,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input3
[ 1807.780254] hid-generic 0003:0A12:1004.0008: hiddev97,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-0000:01:00.0-1.4/input4

[heapxor]

these resets are increassing ... since the previous post its already on number

[24363.604074] usb 1-1.2: USB disconnect, device number 43 [24364.053061] usb 1-1.2: new full-speed USB device number 44 using xhci_hcd

[MichaIng]

So it seems to be an issue with the BT transmitter itself then. Interesting is that the disconnects are quite precisely every 10 minutes (600 seconds), with a little shift that fits to the ~0.5 seconds disconnect time and ~1 second reconnect/setup time. Is it the same on the BPi?

[heapxor]

hi, it looks like its neverending even on bpi

[75223.758384] generic-usb 0003:0A12:1004.00FC: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[75824.316641] usb 2-1: USB disconnect, device number 127
[75824.346878] ehci_irq: port change detect
[75824.795330] ehci_irq: port change detect
[75824.855367] The port change to OHCI now!
[75825.158279] usb 2-1: new full-speed USB device number 2 using sw-ohci
[75825.372311] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[75825.392423] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[75825.411146] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[75825.427580] usb 2-1: SerialNumber: ABCDEF0123456789
[75825.585980] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input128
[75825.619420] generic-usb 0003:0A12:1004.00FD: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[75825.663320] generic-usb 0003:0A12:1004.00FE: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[76426.201288] usb 2-1: USB disconnect, device number 2
[76426.231625] ehci_irq: port change detect
[76426.671534] ehci_irq: port change detect
[76426.731583] The port change to OHCI now!
[76427.034385] usb 2-1: new full-speed USB device number 3 using sw-ohci
[76427.248320] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[76427.284734] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[76427.310353] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[76427.327727] usb 2-1: SerialNumber: ABCDEF0123456789
[76427.498881] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input129
[76427.551923] generic-usb 0003:0A12:1004.00FF: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[76427.612337] generic-usb 0003:0A12:1004.0100: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[77028.085923] usb 2-1: USB disconnect, device number 3
[77028.116280] ehci_irq: port change detect
[77028.537520] ehci_irq: port change detect
[77028.598031] The port change to OHCI now!
[77028.900346] usb 2-1: new full-speed USB device number 4 using sw-ohci
[77029.115331] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[77029.135697] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[77029.154608] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[77029.171104] usb 2-1: SerialNumber: ABCDEF0123456789
[77029.331694] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input130
[77029.369079] generic-usb 0003:0A12:1004.0101: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[77029.422255] generic-usb 0003:0A12:1004.0102: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[77629.970599] usb 2-1: USB disconnect, device number 4
[77630.000908] ehci_irq: port change detect
[77630.443422] ehci_irq: port change detect
[77630.503466] The port change to OHCI now!
[77630.806245] usb 2-1: new full-speed USB device number 5 using sw-ohci
[77631.020309] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[77631.040640] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[77631.059571] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[77631.076153] usb 2-1: SerialNumber: ABCDEF0123456789
[77631.238660] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input131
[77631.273321] generic-usb 0003:0A12:1004.0103: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[77631.320440] generic-usb 0003:0A12:1004.0104: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[78231.855227] usb 2-1: USB disconnect, device number 5
[78231.885602] ehci_irq: port change detect
[78232.309639] ehci_irq: port change detect
[78232.369668] The port change to OHCI now!
[78232.672428] usb 2-1: new full-speed USB device number 6 using sw-ohci
[78232.886309] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[78232.906736] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[78232.927364] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[78232.931319] usb 2-1: SerialNumber: ABCDEF0123456789
[78233.076838] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input132
[78233.106819] generic-usb 0003:0A12:1004.0105: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[78233.150335] generic-usb 0003:0A12:1004.0106: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4
[78833.739934] usb 2-1: USB disconnect, device number 6
[78833.770336] ehci_irq: port change detect
[78834.195830] ehci_irq: port change detect
[78834.255884] The port change to OHCI now!
[78834.558644] usb 2-1: new full-speed USB device number 7 using sw-ohci
[78834.772312] usb 2-1: New USB device found, idVendor=0a12, idProduct=1004
[78834.792469] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[78834.811197] usb 2-1: Product: REIYIN Bluetooth Audio WT04
[78834.827639] usb 2-1: SerialNumber: ABCDEF0123456789
[78834.985535] input: REIYIN Bluetooth Audio WT04 as /devices/platform/sw-ohci.1/usb2/2-1/2-1:1.3/input/input133
[78835.021319] generic-usb 0003:0A12:1004.0107: input,hiddev0,hidraw0: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input3
[78835.074215] generic-usb 0003:0A12:1004.0108: hiddev0,hidraw1: USB HID v1.11 Device [REIYIN Bluetooth Audio WT04] on usb-sw-ohci-1/input4

[heapxor]

even there are these disconnects i dont believe thats the issue why there is no sound/or sound is chopping.

[MichaIng]

Even if those disconnects were not related to the choppy audio, it would break playback every 10 minutes for 1-2 seconds, which isn't great either. So before assuming a general issue with Shairport Sync, I'd definitely test a new BT transmitter first, that has no regular disconnects.

But I'll also rebuild our Shairport Sync packages as a new version is available: https://github.com/mikebrady/shairport-sync/releases/tag/3.3.8

[heapxor]

@MichaIng do i have to compile it?

[MichaIng]

Sorry for the late reply. I'll recompile our Shairport Sync packages the next days and inform you once done and how to upgrade.

[MichaIng]

New packages are ready:

cd /tmp
curl -sSfLO https://dietpi.com/downloads/binaries/$G_DISTRO_NAME/shairport-sync_$G_HW_ARCH_NAME.deb
apt install ./shairport-sync_$G_HW_ARCH_NAME.deb
rm shairport-sync_$G_HW_ARCH_NAME.deb

[heapxor]

@MichaIng not working at all; no sound. Even i bought completely new BT avantree dg60.

I can get chopping sound on ropieee or banana but no sound from dietpi.

How can i see / access logs from shairport running on dietpi?

[heapxor]

root@DietPi:/tmp# shairport-sync -d "hw:DG60" -vvu
         0.000313542 "shairport.c:461" looking for configuration file at full path "/usr/local/etc/shairport-sync.conf"
shairport-sync was built without libdaemon, so does not support daemonisation using the -d, --daemon, -j or --justDaemoniseNoPIDFile options
         0.000685750 "shairport.c:1327" exit function called...
         0.000123083 "dbus-service.c:1089" stopping dbus service
         0.000023417 "dbus-service.c:1093" Zero OwnerID for "org.gnome.ShairportSync".
         0.000015458 "shairport.c:1355" Stopping DACP Monitor
         0.000027833 "shairport.c:1360" Stopping metadata hub
         0.000023917 "shairport.c:1421" exit
root@DietPi:/tmp# shairport-sync  "hw:DG60" -vvu
         0.000197708 "shairport.c:461" looking for configuration file at full path "/usr/local/etc/shairport-sync.conf"
         0.000790833 "shairport.c:1729" Started!
         0.000048417 "shairport.c:1756" software version: "3.3.8-OpenSSL-Avahi-ALSA-soxr-metadata-mqtt-dbus-mpris-sysconfdir:/usr/local/etc"
         0.000023625 "shairport.c:1762" log verbosity is 2.
         0.000124250 "audio_alsa.c:998" alsa: init() -- alsa_backend_state => abm_disconnected.
         0.000019750 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000039500 "audio_alsa.c:1302" alsa: disable_standby_mode is "never".
         0.000017833 "audio_alsa.c:1304" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000020834 "audio_alsa.c:1306" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000023750 "audio_alsa.c:1345" alsa: output device name is "default".
         0.000149875 "shairport.c:1777" The processor is running little-endian.
         0.000026791 "shairport.c:1810" disable resend requests is off.
         0.000036167 "shairport.c:1814" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000003417 "audio_alsa.c:1968" keep_dac_busy is now "no"
         0.000035750 "shairport.c:1815" statistics_requester status is 0.
         0.000066750 "shairport.c:1820" rtsp listening port is 5000.
         0.000019625 "shairport.c:1821" udp base port is 6001.
         0.000016958 "shairport.c:1822" udp port range is 10.
         0.000019750 "shairport.c:1823" player name is "DietPi".
         0.000021125 "shairport.c:1824" backend is "alsa".
         0.000018125 "shairport.c:1825" run_this_before_play_begins action is "(null)".
         0.000018125 "shairport.c:1826" run_this_after_play_ends action is "(null)".
         0.000016708 "shairport.c:1827" wait-cmd status is 0.
         0.000020000 "shairport.c:1828" run_this_before_play_begins may return output is 0.
         0.000018875 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000018209 "shairport.c:1830" run_this_before_entering_active_state action is  "(null)".
         0.000017916 "shairport.c:1831" run_this_after_exiting_active_state action is  "(null)".
         0.000019584 "shairport.c:1832" active_state_timeout is  10.000000 seconds.
         0.000020166 "shairport.c:1833" mdns backend "(null)".
         0.000016750 "shairport.c:1834" userSuppliedLatency is 0.
         0.000018417 "shairport.c:1837" interpolation setting is "auto".
         0.000016875 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
         0.000016833 "shairport.c:1839" resync time is 0.050000 seconds.
         0.000017584 "shairport.c:1840" allow a session to be interrupted: 0.
         0.000016916 "shairport.c:1841" busy timeout time is 120.
         0.000017042 "shairport.c:1842" drift tolerance is 0.001995 seconds.
         0.000017542 "shairport.c:1843" password is "(null)".
         0.000016708 "shairport.c:1844" ignore_volume_control is 0.
         0.000016917 "shairport.c:1848" volume_max_db is not set
         0.000016833 "shairport.c:1850" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000017750 "shairport.c:1854" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000018583 "shairport.c:1856" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000019417 "shairport.c:1857" disable_synchronization is 0.
         0.000017125 "shairport.c:1858" use_mmap_if_available is 1.
         0.000017042 "shairport.c:1860" output_format automatic selection is enabled.
         0.000016875 "shairport.c:1864" output_rate automatic selection is enabled.
         0.000020708 "shairport.c:1868" audio backend desired buffer length is 0.200000 seconds.
         0.000018583 "shairport.c:1870" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000017917 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
         0.000019625 "shairport.c:1873" audio backend silence lead-in time is "auto".
         0.000018208 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
         0.000017167 "shairport.c:1878" decoders_supported field is 1.
         0.000018500 "shairport.c:1879" use_apple_decoder is 0.
         0.000016375 "shairport.c:1880" alsa_use_hardware_mute is 0.
         0.000018958 "shairport.c:1884" no special mdns service interface was requested.
         0.000039875 "shairport.c:1888" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
         0.000020417 "shairport.c:1894" metadata enabled is 1.
         0.000017917 "shairport.c:1895" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000016708 "shairport.c:1897" metadata socket address is "(null)" port 0.
         0.000018833 "shairport.c:1898" metadata socket packet size is "500".
         0.000017042 "shairport.c:1899" get-coverart is 1.
         0.000016667 "shairport.c:1902" mqtt is disabled.
         0.000016791 "shairport.c:1903" mqtt hostname is (null), port is 1883.
         0.000017250 "shairport.c:1904" mqtt topic is /DietPi.
         0.000018125 "shairport.c:1905" mqtt will not publish raw metadata.
         0.000016917 "shairport.c:1906" mqtt will not publish parsed metadata.
         0.000016250 "shairport.c:1907" mqtt will not publish cover Art.
         0.000025708 "shairport.c:1908" mqtt remote control is disabled.
         0.000025917 "shairport.c:1917" loudness is 0.
         0.000018417 "shairport.c:1918" loudness reference level is -20.000000
         0.000292583 "rtsp.c:1665" metadata pipe name is "/tmp/shairport-sync-metadata".
         0.000221542 "rtsp.c:158" Creating metadata queue "pipe".
         0.000231000 "rtsp.c:158" Creating metadata queue "multicast".
         0.000295333 "rtsp.c:158" Creating metadata queue "hub".
         0.000118375 "rtsp.c:158" Creating metadata queue "mqtt".
         0.008909125 "mdns_avahi.c:209" avahi: service '91A5B7EBE8A4@DietPi' group is not yet committed.
         0.001261458 "mdns_avahi.c:244" avahi: request to add "_raop._tcp" service with metadata
         0.000685959 "mdns_avahi.c:375" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000183458 "mdns_avahi.c:213" avahi: service '91A5B7EBE8A4@DietPi' group is registering.
         0.010597250 "dbus-service.c:548" >> setting loudness threshold to -20.000000.
         0.000111292 "dbus-service.c:561" >> setting drift tolerance to 0.001995 seconds
         0.000110958 "dbus-service.c:909" >> ALACDecoder set to "hammerton"
         0.000057792 "dbus-service.c:914" >> Active set to "false"
         0.000061083 "dbus-service.c:919" >> disable standby mode set to "off"
         0.000056917 "dbus-service.c:940" >> interpolation set to "auto" (soxr support built in)
         0.000080041 "dbus-service.c:456" >> deactivating disable standby
         0.000048542 "dbus-service.c:538" >> deactivating loudness
         0.000134708 "dbus-service.c:441" >> log verbosity set to 2.
         0.000056084 "dbus-service.c:428" >> stop logging statistics
         0.000048958 "dbus-service.c:390" >> stop including elapsed time in logs
         0.000049542 "dbus-service.c:400" >> start including delta time in logs
         0.000049041 "dbus-service.c:413" >> start including file and line in logs
         0.000113625 "dbus-service.c:1046" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
         0.001296042 "mpris-service.c:342" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.

         0.978161209 "mdns_avahi.c:180" avahi: service '91A5B7EBE8A4@DietPi' successfully added.

         0.497036166 "shairport.c:194" soxr_delay_index: 3.
         0.000039750 "shairport.c:201" "soxr" interpolation has been chosen.
        17.698874836 "rtsp.c:2982" Connection 1: new connection from 10.0.1.44:59228 to self at 10.0.1.117:5000.
         0.112127750 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
         0.000061041 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000025625 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000026667 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000025333 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000037250 "rtsp.c:507"   Type: "Content-Type", content: "application/sdp"
         0.000024167 "rtsp.c:507"   Type: "CSeq", content: "2"
         0.000038250 "rtsp.c:507"   Type: "Content-Length", content: "600"
         0.010798167 "rtsp.c:2225" Play connection from user agent "iTunes/12.6 (Macintosh; OS X 10.12.4)" on RTSP conversation thread 1.
         0.000168166 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000026917 "rtsp.c:507"   Type: "CSeq", content: "2"
         0.000026000 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.001165833 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SETUP":
         0.000021000 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000033375 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000022959 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000018166 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000017084 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
         0.000018083 "rtsp.c:507"   Type: "CSeq", content: "3"
         0.000022833 "rtsp.c:976" Connection 1: SETUP -- Active-Remote string seen: "637581677584076950".
         0.000065375 "rtsp.c:995" Connection 1: SETUP -- DACP-ID string seen: "0C8D27CF958446B6".
         0.000055209 "rtp.c:968" Connection 1: SETUP -- Connection from 10.0.1.44 to self at 10.0.1.117.
         0.000218708 "rtsp.c:1062" Connection 1: SETUP DACP-ID "0C8D27CF958446B6" from 10.0.1.44 to 10.0.1.117 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.000024625 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000025417 "rtsp.c:507"   Type: "CSeq", content: "3"
         0.000017833 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000019875 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000020500 "rtsp.c:507"   Type: "Session", content: "1"
         0.000453958 "metadata_hub.c:539" MH Client IP set to: "10.0.1.44"
         0.001773584 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "RECORD":
         0.000030125 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000036208 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000025292 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000023416 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000022917 "rtsp.c:507"   Type: "RTP-Info", content: "seq=12991;rtptime=1988149877"
         0.000020208 "rtsp.c:507"   Type: "Range", content: "npt=0-"
         0.000018667 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000020333 "rtsp.c:855" Connection 1: RECORD
         0.000031792 "activity_monitor.c:64" abeg
         0.000067458 "dbus-service.c:195" Build metadata
         0.001587500 "mpris-service.c:167" Build metadata
         0.000101250 "metadata_hub.c:556" MH Server IP set to: "10.0.1.117"
         0.000243500 "dbus-service.c:195" Build metadata
         0.002627125 "mpris-service.c:167" Build metadata
         0.000287500 "dbus-service.c:195" Build metadata
         0.000188542 "mpris-service.c:167" Build metadata
         0.008019667 "audio_alsa.c:529" alsa: output format chosen is "S32".
         0.000155833 "audio_alsa.c:569" alsa: output speed chosen is 44100.
         0.002305917 "audio_alsa.c:1504" alsa: update timestamps available
         0.000033500 "audio_alsa.c:230" alsa: precision delay timing is not available because it's not definitely a hardware device.
         0.000031083 "audio_alsa.c:738" PCM handle name = 'default'
         0.000023250 "audio_alsa.c:752" alsa device parameters:
         0.000025000 "audio_alsa.c:755"   access type = MMAP_INTERLEAVED
         0.000030375 "audio_alsa.c:759"   format = 'S32_LE' (Signed 32 bit Little Endian)
         0.000031625 "audio_alsa.c:763"   subformat = 'STD' (Standard)
         0.000020833 "audio_alsa.c:766"   number of channels = 2
         0.000020584 "audio_alsa.c:769"   number of significant bits = 32
         0.000022666 "audio_alsa.c:777"   rate = 44100 frames per second (precisely).
         0.000021917 "audio_alsa.c:786"   precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
         0.000024792 "audio_alsa.c:799"   period_time = 5804 us (>).
         0.000023666 "audio_alsa.c:809"   period_size = 256 frames (precisely).
         0.000023375 "audio_alsa.c:825"   buffer_time = 1486077 us (>).
         0.000018084 "audio_alsa.c:838"   buffer_size = 65536 frames (>).
         0.000020583 "audio_alsa.c:848"   periods_per_buffer = 256 (precisely).
         0.000020667 "audio_alsa.c:1841" alsa: prepare() -- opened output device
         0.000045500 "audio_alsa.c:1990" alsa: alsa_buffer_monitor_thread_code() -- closing the output device
         0.000128625 "player.c:3120" pbeg
         0.000103791 "player.c:3078" do_flush: flush to 1988149877.
         0.000046250 "player.c:3090" pfls
         0.000111667 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000026333 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000031417 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000036458 "rtsp.c:507"   Type: "Audio-Latency", content: "11025"
         0.001254084 "dbus-service.c:195" Build metadata
         0.001796000 "mpris-service.c:167" Build metadata
         0.000349541 "dbus-service.c:195" Build metadata
         0.000793042 "mpris-service.c:167" Build metadata
         0.000679417 "audio_alsa.c:1779" alsa: do_close() -- closing alsa handle
         0.000087875 "audio_alsa.c:1993" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnected
         0.001824041 "dacp.c:410" set_dacp_server_information set IP to "10.0.1.44" and DACP id to "0C8D27CF958446B6".
         0.000071084 "player.c:2004" Set initial volume to -18.000000.
         0.000216791 "loudness.c:47" Volume: -37.6 dB - Loudness gain @10Hz: 8.8 dB
         0.000100459 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -18.000000, software_attenuation: -3755.700000, hardware_attenuation: 0.000000, muting is disabled.
         0.000034541 "player.c:2007" Play begin
         0.000035292 "player.c:945" flush request: flush output device.
         0.000411708 "dbus-service.c:195" Build metadata
         0.000459709 "mpris-service.c:167" Build metadata
         0.073601166 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000024417 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000013167 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000033125 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000016041 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000025084 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000017125 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000026916 "rtsp.c:507"   Type: "Content-Length", content: "16"
         0.000047709 "loudness.c:47" Volume: -35.8 dB - Loudness gain @10Hz: 7.9 dB
         0.000077500 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -17.400000, software_attenuation: -3582.359890, hardware_attenuation: 0.000000, muting is disabled.
         0.000030500 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000013958 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000020667 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.001894291 "player.c:247" Hammerton Decoder used on encrypted audio.
         0.000157750 "player.c:1005" flush request: flush frame 1988149877 expired -- buffer contains 352 frames, from 1988149877 to 1988150228
         0.000032417 "player.c:1029" flush request: request dropped.
         0.000025792 "player.c:1068" pffr
         0.000103125 "player.c:1110" first_packet_time set for frame 1988149877.
         0.000525083 "dbus-service.c:195" Build metadata
         0.000599583 "mpris-service.c:167" Build metadata
         0.000335042 "dbus-service.c:195" Build metadata
         0.000655875 "mpris-service.c:167" Build metadata
         0.001182375 "audio_alsa.c:1805" alsa: play() -- opened output device
         0.000024208 "audio_alsa.c:1810" alsa: play() -- alsa_backend_state => abm_playing
         0.075576125 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000027625 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000021834 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000032000 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000031708 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000027125 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000035042 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988061677"
         0.000015458 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000026792 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000072041 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000023667 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000015250 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000224625 "metadata_hub.c:548" MH Progress String set to: "1988061677/1988061677/1988061677"
         0.000995583 "dbus-service.c:195" Build metadata
         0.000191375 "mpris-service.c:167" Build metadata
         0.145254167 "player.c:1175" Change in estimated first_packet_time:  -0.0925 milliseconds.
         0.064093750 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000022750 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000013875 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000030833 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000013959 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000021750 "rtsp.c:507"   Type: "Content-Type", content: "application/x-dmap-tagged"
         0.000015083 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988071181"
         0.000026167 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000014916 "rtsp.c:507"   Type: "Content-Length", content: "57"
         0.000095792 "metadata_hub.c:503" MH Metadata stream processing start.
         0.000037916 "metadata_hub.c:413" MH Track Name set to: "OFFradio"
         0.000034084 "metadata_hub.c:507" MH Metadata stream processing end.
         0.000012292 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000037416 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000021750 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.081233709 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000026541 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000014875 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000026459 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000034250 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000022958 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000026708 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988071181"
         0.000029750 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000024167 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000098417 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000031083 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000008083 "metadata_hub.c:548" MH Progress String set to: "1988071181/1988071181/1988071181"
         0.000019209 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000545291 "dbus-service.c:195" Build metadata
         0.000304000 "mpris-service.c:167" Build metadata
         0.468499584 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000068958 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000079959 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000065000 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000060166 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000070250 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988095117"
         0.000056125 "rtsp.c:507"   Type: "Content-Type", content: "image/jpeg"
         0.000051542 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000056750 "rtsp.c:507"   Type: "Content-Length", content: "18820"
         0.000172208 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000044792 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000028250 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.001353042 "metadata_hub.c:511" MH Picture received, length 18820 bytes.
         0.002121125 "dbus-service.c:195" Build metadata
         0.000966000 "mpris-service.c:167" Build metadata
         0.166793583 "player.c:1175" Change in estimated first_packet_time:  16.2494 milliseconds.
         0.101410042 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000071291 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000103334 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000057041 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000062459 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000068041 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000064750 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988107085"
         0.000067875 "rtsp.c:507"   Type: "CSeq", content: "10"
         0.000065084 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000168750 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000059666 "rtsp.c:507"   Type: "CSeq", content: "10"
         0.000067084 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000094625 "metadata_hub.c:548" MH Progress String set to: "1988062985/1988107085/1988062985"
         0.002168833 "dbus-service.c:195" Build metadata
         0.000560583 "mpris-service.c:167" Build metadata
         0.909232709 "player.c:1175" Change in estimated first_packet_time:  -0.8655 milliseconds.
         0.021516166 "player.c:1287" prsm
         0.089334625 "player.c:2288" first frame sync error (positive --> late): 3893 frames, 88.277 mS at 44100 frames per second output.
         0.022176792 "player.c:2349" Large positive sync error: 4847.
         0.000076417 "player.c:989" flush request: flush frame 1988158948 active -- buffer contains 90464 frames, from 1988154453 to 1988244916
         0.000049041 "player.c:1020" flush request: flush done.
         0.000084709 "player.c:1029" flush request: request dropped.
         0.013493666 "player.c:1068" pffr
         0.000386750 "player.c:1110" first_packet_time set for frame 1988244917.
         0.161891042 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000075792 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000096583 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000068333 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000066375 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000062834 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000064625 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988160941"
         0.000061500 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000052166 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000152917 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000058875 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000065583 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.001000959 "metadata_hub.c:548" MH Progress String set to: "1988072741/1988160941/1988072741"
         0.003144833 "dbus-service.c:195" Build metadata
         0.000537750 "mpris-service.c:167" Build metadata
         0.692631000 "player.c:1175" Change in estimated first_packet_time:   0.2857 milliseconds.
         0.341424084 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000077208 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000096708 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000069417 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000062833 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000065209 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000061541 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988205645"
         0.000064667 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000109208 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000164875 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000061834 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000061291 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000051292 "metadata_hub.c:548" MH Progress String set to: "1988073345/1988205645/1988073345"
         0.002138167 "dbus-service.c:195" Build metadata
         0.000535166 "mpris-service.c:167" Build metadata
         0.546484625 "player.c:1287" prsm
         0.227288042 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000107833 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000124292 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000099750 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000148542 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000089333 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000134083 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988241549"
         0.000090459 "rtsp.c:507"   Type: "CSeq", content: "13"
         0.000081708 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000347833 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000012625 "rtsp.c:507"   Type: "CSeq", content: "13"
         0.000082167 "metadata_hub.c:548" MH Progress String set to: "1988065149/1988241549/1988065149"
         0.000080583 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.002038167 "dbus-service.c:195" Build metadata
         0.000633500 "mpris-service.c:167" Build metadata
         0.161277750 "player.c:2349" Large positive sync error: 17045.
         0.000062500 "player.c:989" flush request: flush frame 1988266186 active -- buffer contains 90464 frames, from 1988249493 to 1988339956
         0.000039417 "player.c:1020" flush request: flush done.
         0.000063416 "player.c:1029" flush request: request dropped.
         0.007282125 "player.c:1068" pffr
         0.000141834 "player.c:1110" first_packet_time set for frame 1988339957.
         0.737650125 "player.c:1175" Change in estimated first_packet_time:   0.2857 milliseconds.
         0.313649833 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000026208 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000015875 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000031584 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000015250 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000014166 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000026334 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988295405"
         0.000016166 "rtsp.c:507"   Type: "CSeq", content: "14"
         0.000017250 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000097000 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000034417 "rtsp.c:507"   Type: "CSeq", content: "14"
         0.000015125 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000103125 "metadata_hub.c:548" MH Progress String set to: "1988074905/1988295405/1988074905"
         0.001812083 "dbus-service.c:195" Build metadata
         0.000267042 "mpris-service.c:167" Build metadata
         0.419956583 "player.c:1287" prsm
         0.544250542 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000121125 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000120042 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000097083 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000091917 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000092208 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000087500 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=1988337293"
         0.000081709 "rtsp.c:507"   Type: "CSeq", content: "15"
         0.000078916 "rtsp.c:507"   Type: "Content-Length", content: "44"
         0.000236917 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000094500 "rtsp.c:507"   Type: "CSeq", content: "15"
         0.000098417 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000027625 "metadata_hub.c:548" MH Progress String set to: "1988337293/1988337293/1988337293"
         0.001491916 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "FLUSH":
         0.000108834 "rtsp.c:507"   Type: "Client-Instance", content: "24d3386f66484c16"
         0.000085625 "rtsp.c:507"   Type: "DACP-ID", content: "0C8D27CF958446B6"
         0.000082791 "rtsp.c:507"   Type: "Active-Remote", content: "637581677584076950"
         0.000081917 "rtsp.c:507"   Type: "User-Agent", content: "iTunes/12.6 (Macintosh; OS X 10.12.4)"
         0.000082167 "rtsp.c:507"   Type: "RTP-Info", content: "seq=13774;rtptime=1988425493"
         0.000079791 "rtsp.c:507"   Type: "CSeq", content: "16"
         0.000097500 "player.c:3078" do_flush: flush to 1988425493.
         0.000115959 "player.c:3090" pfls
         0.000159541 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000068334 "rtsp.c:507"   Type: "CSeq", content: "16"
         0.000057291 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000952209 "dbus-service.c:195" Build metadata
         0.000797250 "audio_alsa.c:1861" alsa: flush() -- closing the output device
         0.000048333 "mpris-service.c:167" Build metadata
         0.001280958 "dbus-service.c:195" Build metadata
         0.002488834 "mpris-service.c:167" Build metadata
         0.002139041 "audio_alsa.c:1779" alsa: do_close() -- closing alsa handle
         0.000306709 "audio_alsa.c:1863" alsa: flush() -- alsa_backend_state => abm_disconnected.
         0.000135875 "player.c:945" flush request: flush output device.
         0.000092791 "player.c:997" flush request: flush frame 1988425493 pending -- buffer contains 85536 frames, from 1988339957 to 1988425492
         0.000099334 "player.c:1020" flush request: flush done.
^C
root@DietPi:/tmp#

[MichaIng]

Logs can be reviewed via: journalctl -u shairport-sync

But there are no regular disconnects anymore with the new Bluetooth adapter? Does it work when playing a local audio file, e.g. a wav file via aplay some.wav or MP3 via mpg123 some.mpg. Ah or speaker-test to run the general ALSA speaker test.

[heapxor]

everything plays fine while using roon-bridge ie streaming music from roon to roon-bridge installed on dietpi and from BT transmitted to bose mini speaker. When I stream to airplay even from roon or directly from my iphone no sound at all. :(

No more disconnect in dmesg.

[heapxor]

running on banana pi i have at least some sound; chopping but sound ... 0.431184292 "player.c:2364" Large negative sync error: -2323 with shoul d_be_frame_32 of 899954347, nt of 899874954 and current_delay of 6484.

but here nothing ;(

[heapxor]

root@DietPi:/tmp# journalctl -u shairport-sync -- Logs begin at Mon 2021-05-10 13:28:28 BST, end at Tue 2021-06-01 19:40:10 BST. -- Jun 01 19:03:04 DietPi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 01 19:03:04 DietPi shairport-sync[5629]: warning: could not acquire a Shairport Sync native D-Bus interface "org.gnome.ShairportSync.i5629" on t he system bus. Jun 01 19:03:04 DietPi shairport-sync[5629]: warning: could not acquire an MPRIS interface named "org.mpris.MediaPlayer2.ShairportSync.i5629" on the system bus. Jun 01 19:08:10 DietPi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 01 19:08:10 DietPi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jun 01 19:08:10 DietPi systemd[1]: shairport-sync.service: Succeeded. Jun 01 19:08:10 DietPi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 19:33:27 DietPi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 01 19:34:23 DietPi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 01 19:34:23 DietPi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jun 01 19:34:23 DietPi systemd[1]: shairport-sync.service: Succeeded. Jun 01 19:34:23 DietPi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 19:34:23 DietPi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. root@DietPi:/tmp#

[heapxor]

dunno how to run that test

root@DietPi:/tmp# speaker-test -D "hw:DG60"

speaker-test 1.1.8

Playback device is hw:DG60 Stream parameters are 48000Hz, S16_LE, 1 channels Using 16 octaves of pink noise Channels count (1) not available for playbacks: Invalid argument Setting of hwparams failed: Invalid argument

even BT is there aplay -L

hw:CARD=DG60,DEV=0 Avantree DG60, USB Audio Direct hardware device without any conversions

[MichaIng]

How did you actually configure ALSA? Did you use dietpi-config, or manually set it up? If so please share your cat /etc/asound.conf.

It seems you don't have the automatic conversion plugin enabled, which means best sound quality, but if the sound card/driver does not support the format of the audio source, it won't play something. If you used dietpi-config to setup ALSA, please try to enabled Auto-conversion.

[heapxor]

i didnt configure it; so there is not etc/asound.conf.

[heapxor]

i executed now dietpi-config for the conf of audio end enabled Auto-conversion.

root@DietPi:/tmp# cat /etc/asound.conf
pcm.!default {
        type plug
        slave.pcm {
                type hw
                card 1
                device 0
        }
}

ctl.!default {
        type hw
        card 1
}

hoala speaker-test now producing the sound!

[heapxor]

but still no sound from the speaker while connected via iphone to airplay device :(

also nothing inside the log

Jun 01 19:34:23 DietPi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 19:34:23 DietPi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 01 20:00:46 DietPi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 01 20:00:46 DietPi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jun 01 20:00:46 DietPi systemd[1]: shairport-sync.service: Succeeded. Jun 01 20:00:46 DietPi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 20:00:46 DietPi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.

[heapxor]

hows! it works now from iphone wou

[heapxor]

okay i can confirm that all works flawlessly! thank you so much

[MichaIng]

Can you check alsamixer whether there are controls muted or on low level. If speaker-test works this shouldn't be the case, but just to rule it out. Also you should be able to determine the main volume control name, shown at the bottom of the mixer GUI. In /usr/local/etc/shairport-sync.conf you can then uncomment and set mixer_control_name to have this control name, so it can adjust volume natively via ALSA instead of doing it software-wise. The config file contains many other options to look through. output_device and mixer_device should be fine, when commented, as the default is "default", which is the correct name of both, as named in asound.conf, but it could be tested to set it explicitly.

... ah okay, what was the final step? 😃

[heapxor]

i think that execution of > dietpi-config for the conf of audio end enabled Auto-conversion then restart of shairport helped.

[heapxor]

it also works fine with previous BT.

The issue was missing / off Automatic software conversions

Thats why sound was chopping.

[MichaIng]

Okay great. We should add a note to audio related software docs, that, if audio does not work, that software conversion plugin is always a good thing to test. Probably we should even enable it by default 🤔. If I understand it correctly, the conversion (and hence CPU usage + theoretical audio quality loss) is anyway only done when the card/driver does not support the format of the audio source, otherwise it is skipped.

[heapxor]

and what exactly is that software conversion plugin? how can i install it on other distribution? thanks

[heapxor]

seems like config param in alsa config file https://www.alsa-project.org/alsa-doc/alsa-lib/pcm_plugins.html

[MichaIng]

I'm everything else than an audio expert, but that suites quite well some experience I had on Windows, when changing the sampling rate or bit rate in audio control panel, sometimes audio was still playing, but horribly distorted.

That plugin is natively integrated in ALSA, at least it should be, on Debian it is. Check out the asound.conf:

pcm.!default {
        type plug
        slave.pcm {
                type hw
                card 1
                device 0
        }
}

This means the PCM called "default" is of type "plug", which is that software conversion plugin: https://www.alsa-project.org/alsa-doc/alsa-lib/pcm_plugins.html#pcm_plugins_plug It has the actual sound card driver (type "hw" with card and device index defined) as child/slave PCM, to pass the converted audio stream to. Without that plugin, the audio stream is directly passed to the driver:

pcm.!default {
        type hw
        card 1
        device 0
}

The link above lists many other plugins that can be used to do things to the audio stream, interesting also dmix, which mixes multiple input stream and hence allows to run audio from multiple players concurrently, which is not natively supported by the ALSA driver. Crazy is it when enabling the equalizer:

pcm.!default {
    type plug
    slave.pcm {
        type equal
        slave.pcm {
            type plug
            slave.pcm {
                type hw
                card 1
                device 0
            }
        }
        controls "/var/lib/dietpi/dietpi-config/.alsaequal.bin"
    }
}

"type equal" is the equalizer plugin (which needs to be installed, as it is not part of the core ALSA package). But it requires the audio stream as integer stream or so (some format that is never used in the audio source and nearly never supported by the sound card), so the auto conversion plugin is used first, which passes the converted stream to the equalizer, which passes the changed stream to a second conversion stage, which then passes the back-converted stream to the final audio driver 😄. Awesome is that "auto"-conversion really means auto, so that plugin determines quite reliable which format it needs to convert the input stream into, to satisfy its child/slave PCM.

So much about ALSA configuration which I also learned quite recently 😄.

[heapxor]

even i replicated /etc/asound.conf on bananian is still chopping ::( any idea where to take a look? thanks!

2 root@bananapi ~/shairport-sync (git)-[master] # cat /etc/asound.conf :(

pcm.!default {
        type plug
        slave.pcm {
                type hw
                card 1 # for headphone, turn 1 to 0
                device 0
        }
}

ctl.!default {
        type hw
        card 1 # for headphone, turn 1 to 0
}

[heapxor]

or maybe can you share me your shairport-sync source and what ./configuration parameters did u use to create package? so i can try to compile it on bananian? thanks

[MichaIng]

I use:

./configure --with-alsa --with-avahi --with-ssl=openssl --with-soxr --with-metadata --with-systemd --with-dbus-interface --with-mpris-interface --with-mqtt-client

Build dependencies accordingly:

apt install automake pkg-config make g++ libpopt-dev libconfig-dev libssl-dev libsoxr-dev libavahi-client-dev libasound2-dev libglib2.0-dev libmosquitto-dev

DBus, MPRIS and MQTT however should not play a role.

[heapxor]

and from which source do you compile?

[MichaIng]

From official Git master branch as well, which equals the latest release.

[heapxor]

hm thats strange... so i did git clone https://github.com/mikebrady/shairport-sync.git cd sh... autoreconf -fi ./configure --with-alsa --with-avahi --with-ssl=openssl --with-soxr --with-metadata --with-dbus-interface --with-mpris-interface --with-mqtt-client --with-libdaemon

[heapxor]

okay i make it works also on banana! pow! the mixer volume was completely off.

thanks for all your help!

[heapxor]

the only thing i do not understand is ... why there are constant disconnects of BT in dmesg... weird :(

[MichaIng]

Probably it is simply a hardware issue of that adapter, a broken cable, loose connection internally, or so.

[heapxor]

well its not a cable ;/ its something like usb stick; so its directly plugged into pc ;-(

[MichaIng]

I mean a cable or connection or broken solder inside of the sticks case.