Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

issue with the shairport - no sound #4384

Closed
heapxor opened this issue May 17, 2021 · 69 comments
Closed

issue with the shairport - no sound #4384

heapxor opened this issue May 17, 2021 · 69 comments

Comments

@heapxor
Copy link

heapxor commented May 17, 2021

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
Copy link
Owner

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
Copy link
Collaborator

Joulinar commented May 17, 2021

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

@heapxor
Copy link
Author

heapxor commented May 17, 2021

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
Copy link
Owner

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
Copy link
Collaborator

@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
Copy link
Author

heapxor commented May 18, 2021

@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
Copy link
Owner

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
Copy link
Author

heapxor commented May 18, 2021

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
Copy link
Owner

MichaIng commented May 18, 2021

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
Copy link
Author

heapxor commented May 18, 2021

@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
Copy link
Author

heapxor commented May 18, 2021

@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
Copy link
Author

heapxor commented May 18, 2021

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
Copy link
Owner

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
Copy link
Author

heapxor commented May 19, 2021

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
Copy link
Author

heapxor commented May 20, 2021

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

@MichaIng
Copy link
Owner

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
Copy link
Author

heapxor commented May 22, 2021

@MichaIng do i have to compile it?

@MichaIng
Copy link
Owner

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
Copy link
Owner

MichaIng commented May 27, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

@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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Owner

MichaIng commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Owner

MichaIng commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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
Copy link
Author

heapxor commented Jun 1, 2021

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

thanks for all your help!

@heapxor
Copy link
Author

heapxor commented Jun 1, 2021

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

@MichaIng
Copy link
Owner

MichaIng commented Jun 1, 2021

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

@heapxor
Copy link
Author

heapxor commented Jun 1, 2021

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

@MichaIng
Copy link
Owner

MichaIng commented Jun 1, 2021

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

@heapxor
Copy link
Author

heapxor commented Jun 1, 2021

i see. its strange its happening regularly in intervals...also its not affecting playback.

@MichaIng
Copy link
Owner

MichaIng commented Jun 2, 2021

Ah true, I forgot the 10 minutes interval. Yeah that is doesn't fit to an internal connection issue, but more a firmware or driver bug. If you have a chance, I'd contact the manufacturer about it, in case of warranty, making use of it. Especially for audio applications, it's a no-go to have regular connection losses, of course, even if it's just for a very short time.

@heapxor
Copy link
Author

heapxor commented Jun 14, 2021

hi @MichaIng, i reinstalled pc with armbian; and i am gettin lets say almost same issue as we started that thread... i am not getting disconnects in dmesg; but sound is chopping even via bluetooth or via airplay :(

thats the shairport-sync log
https://paste.debian.net/1201142/

alsa-info
https://file.io/ues9UkSbtZMi

The distro is based on the latest ubuntu; so thats why i am confused why its not working as expected ... as i replicated all the configuration, as we discussed here :(

if u mind to take a look...
thanks so much

One more observation; now i am running it on system with systemd, and in htop i can see so many shairport-sync processes; and it also looks like its consuming almost 90% of CPU on both cores, strange. Bc before with OS bananian it worked fine on the same HW.

And also i found in syslog
Jun 14 02:07:15 bananapi shairport-sync: warning: Invalid output rate "48000". It should be "auto", 44100, 88200, 176400 or 352800. It remains set to "auto".

Jun 14 02:07:32 bananapi shairport-sync: warning: Speed requested: 44100. Speed available: 48000.

Maybe that alsa plugin type plug is not working properly on that ubuntu, dunno. Also looks like its shairport-sync is consuming ~99% of cpu ... while streaming. Maybe it requires some tuning in conf file.

Linux bananapi 5.4.88-sunxi
Armbian 21.05.2 Focal with Linux 5.4.88-sunxi

@MichaIng
Copy link
Owner

Please check your /usr/local/etc/shairport-sync.conf. Is output_rate set (uncommented)? Not sure if Shairport Sync "sees" that the sound card supports/wants 48000 Hz, but as this is (for whatever reason) not valid value for Shairport Sync, is reverts to auto, effectively 44100 Hz, which then fails. Indeed the "plug" plugin should exactly solve such incompatibilities between input format and sound card/driver. And is output_device set?

And can you check which sampling rate is supported by that sound card?

@heapxor
Copy link
Author

heapxor commented Jun 15, 2021

hi,
i tried output_rate which is as u said not supported, i tried only auto, but card supports up to 48k.

no clue then.

@MichaIng
Copy link
Owner

And these "Speed requested: 44100. Speed available: 48000" stay even with the plug auto conversion plugin enabled?

0.000517586 "audio_alsa.c:1345" alsa: output device name is "hw:WT04".

It seems not to be used, as hw:WT04 is the final hardware PCM. Can you try to set output_device = "default"; explicitly in shairport-sync.conf, as defined in your asound.conf above.

@heapxor
Copy link
Author

heapxor commented Jun 17, 2021

@MichaIng hi,
i installed armbian debian instead of armbian ubuntu and it works... seems some issue in ubuntu?

I can try to do that and get it last shot as its crazily time consuming :( i will need to restore ubuntu edit conf as u suggested.
So using the plug hw:WT04 should not be used as the last device? or what will be achieved using output_device = "default"? thanks!

@MichaIng
Copy link
Owner

If this is your /etc/asound.conf

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

then output_device = "default"; will force Shairport Sync to use the intended parent PCM, which we actively called "default" with this !default syntax, more precisely this syntax overrides any possible existing "default" PCM. It is type plug, hence does the auto-conversion, when required, and passes the converted stream to it's slave PCM, which is the final type hw audio driver. Your logs seem to indicated that hw:WT04 was used as device name by Shairport Sync, which would be a type hw driver already, without any parent conversion plugin. plughw:WT04 would be a pre-defined PC name/shortcut, which is a parent plug PCM with a slave hw PCM. What I'm not sure about it the WT04 name. This needs to be defined somewhere in the ALSA config to be effective. Usually I'd expect hw:1,0, plughw:1,0 or similar, are known pre-defined PCM names with a final card "1" + device "0", hence would match the manual declaration above.

@heapxor
Copy link
Author

heapxor commented Jun 17, 2021

Hi @MichaIng
you were exactly right
i was set as

alsa =
{

output_device = "hw:WT04";

When i changed shairport-sync conf to

alsa =
{

output_device = "default";

All started to work flawlessly!

Great, so much appreciate all your help!

@heapxor
Copy link
Author

heapxor commented Jun 17, 2021

But on ubuntu there has to be one more problem... error...
i do use roonbridge; and shairport-sync... shairport-sync works OK now, but if i stop its playback... the issue is that when i execute playback via roonbridge the chooping is coming from roon bridge. When I dont do playback via shairport-sync before doing playback viac roonbridge; all the sound produced via roonbridge works fine.

It seem that issue in that comment is kind of random, sometimes it happens sometimes it does not.
Ok looks like it happening when i do playback via roonbridge; stop airplay ; roonbridge again -> chopping; but then i stopped roonbridge; waited a bit, executed playback and all worked fine. Scary.

@MichaIng
Copy link
Owner

Generally, running multiple players does not work OOTB. I'm not sure how fast/consequently audio devices are released when you stop playback in one player.

It could be tested if the dmix plugin makes a difference, which allows to mix multiple playback streams:

pcm.!default {
        type plug
        slave.pcm "dmix:1,0"
}
ctl.!default {
        type hw
        card 1
}

@heapxor
Copy link
Author

heapxor commented Jun 19, 2021

maybe almost same behavior? but it looks like if i do playback via roonbridge or shairport; if i stop one of these and way lets say 5 sec ; start the other one... all seems to be fine.

@MichaIng
Copy link
Owner

The dmix plugin should actually solve such transition issues, although the kind where one player fails with a "device is busy"-like error as long as the other didn't release it. With the dmix plugin you should be possible to play audio streams via Stairport Sync and Roon Bridge concurrently and they should be mixed together.

@heapxor
Copy link
Author

heapxor commented Jun 20, 2021

that doesnt work at all ... so seems its all messed. ;/

also shairport-sync requires volume management to be done on spekaer physicaly, roonbridge via its app ... maybe i have wrong alsa configs etc... hard to say.

@renaudl
Copy link

renaudl commented Oct 5, 2021

If that can help, I had not sound with just install and had to uncomment alsa section in shairport file and restart the services. Even thought that is probably obvious.

@MichaIng
Copy link
Owner

MichaIng commented Oct 7, 2021

@renaudl
The alsa = section should be uncommented by default. It contains the commented output_device = "default"; which should be default as well. So what exactly did you uncomment within?

@renaudl
Copy link

renaudl commented Oct 7, 2021

I encommented these llines from shaireport-sync config file. I guess output-device alone would have worked.

alsa =
{
==this===>//	output_device = "default"; // the name of the alsa output device. Use "shairport-sync -h" to discover the names of ALSA hardware devices. Use "alsamixer" or "aplay" to find out the names of devices, mixers, etc.
==this===>//	mixer_control_name = "PCM"; // the name of the mixer to use to adjust output volume. If not specified, volume in adjusted in software.
==this===>//	mixer_device = "default"; // the mixer_device default is whatever the output_device is. Normally you wouldn't have to use this.

==this===>//	output_rate = "auto"; // can be "auto", 44100, 88200, 176400 or 352800, but the device must have the capability.
==this===>//	output_format = "auto"; // can be "auto", "U8", "S8", "S16", "S16_LE", "S16_BE", "S24", "S24_LE", "S24_BE", "S24_3LE","S24_3BE", "S32", "S32_LE" or "S32_BE" but the device must have the capability. Except where stated using (*LE or *BE), endianness matches that of the processor.

//	disable_synchronization = "no"; // Set to "yes" to disable synchronization. Default is "no" This is really meant for troubleshootingG.

//	period_size = <number>; // Use this optional advanced setting to set the alsa period size near to this value
//	buffer_size = <number>; // Use this optional advanced setting to set the alsa buffer size near to this value
//	use_mmap_if_available = "yes"; // Use this optional advanced setting to control whether MMAP-based output is used to communicate  with the DAC. Default is "yes"
//	use_hardware_mute_if_available = "no"; // Use this optional advanced setting to control whether the hardware in the DAC is used for muting. Default is "no", for compatibility with other audio players.
//	maximum_stall_time = 0.200; // Use this optional advanced setting to control how long to wait for data to be consumed by the output device before considering it an error. It should never approach 200 ms.
//	use_precision_timing = "auto"; // Use this optional advanced setting to control how Shairport Sync gathers timing information. When set to "auto", if the output device is a real hardware device, precision timing will be used. Choose "no" for more compatible standard timing, choose "yes" to force the use of precision timing, which may cause problems.

//	disable_standby_mode = "never"; // This setting prevents the DAC from entering the standby mode. Some DACs make small "popping" noises when they go in and out of standby mode. Settings can be: "always", "auto" or "never". Default is "never", but only for backwards compatibility. The "auto" setting prevents entry to standby mode while Shairport Sync is in the "active" mode. You can use "yes" instead of "always" and "no" instead of "never".
//	disable_standby_mode_silence_threshold = 0.040; // Use this optional advanced setting to control how little audio should remain in the output buffer before the disable_standby code should start sending silence to the output device.
//	disable_standby_mode_silence_scan_interval = 0.004; // Use this optional advanced setting to control how often the amount of audio remaining in the output buffer should be checked.
};

@MichaIng
Copy link
Owner

MichaIng commented Oct 8, 2021

@renaudl
Interesting. Could you try to nail this down:

  • Comment everything but output_device, restart service and check whether it still works
  • Comment output_device, restart service and check whether it indeed breaks playback

These settings (aside of mixer_control_name = "PCM";) are supposed to be the defaults. If uncommenting these changes anything, than I'd currently see this as bug and we may rebuild our Shairport Sync packages onto current master, see whether it remains, otherwise report to the project maintainer.

@MichaIng
Copy link
Owner

I'll mark this as closed. Feel free to reopen if required.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants