search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.3k stars 574 forks source link

Alsa and wifi broken with shairport-sync #32

Closed joerg-krause closed 9 years ago

joerg-krause commented 9 years ago

Hi Mike,

I've an ARM-based wireless audio device running shairport-sync 2.1.11. Mostly, it plays very solid. However, I've investigated a problem which occurs rarely, but is very annoying. I stream the music from my iPhone to the wireless audio device. This runs for a while and suddenly playback stops. I've restarted the device and the iPhone can see the audio device, but after selecting it as playback device it disappears.

I've logged the output from shairport-sync -vvv -t 0. It's a lot of output and I've cut after the kernel dump. The brcmfmac is the wifi driver:

# shairport-sync -vvv -t 0 &
# daemon status is 0.
rtsp listening port is 5000.
Audio Output name is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
latency is 0.
AirPlayLatency is 88200.
iTunesLatency is 99400.
stuffing option is "(null)".
resync time is 2205.
busy timeout time is 0.
Successful startup.
avahi: avahi_register.
avahi: register_service.
[  610.643727] cfg80211: Calling CRDA to update world regulatory domain
[  618.174092] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  618.181538] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  618.211642] cfg80211: Calling CRDA for country: DE
culling threads.
new RTSP connection.
    CSeq: 0.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    Apple-Challenge: knyoKOumYzlXqYOG3y/ODQ==.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
rsa_apply encrypt
rsa_apply exit
    Apple-Response: iX/301G2XCF+qZtEuRbVGgNGi8FPMUoFAzf3GkEF6JwQpx7hzKCSQvpqAkSXYRjQpLcqSgT7qelVJSnfvTaocLeclDxYmw177uGGLKpuhuzr4KWjULTD2V5wxYd5T8c+SDXaTj4EFWxRJQsWAEYM3pJZAgN+Ok2mJfQLg1rDds45hruHshu8jtd58rg4NpjnL/gBJ8hcC3UueoT8cc7zsNq3uK2tEde511A4zWVM9xXVZJY4S5JmHAH5V8AF5G5VxyvwUs6WAs8Av9ce67JLcc0qLINZtp/82Sq1RNrfZnfDlt/BFYbCtay+vcw8xBgUKEzTP5Z5HsOisRKrd9WmtQ.
    CSeq: 0.
    Audio-Jack-Status: connected; type=analog.
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER.
    X-Apple-Client-Name: iPhone.
    CSeq: 1.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    Content-Type: application/sdp.
    Content-Length: 656.
    User-Agent: AirPlay/211.3.
rsa_apply decrypt
rsa_apply exit
Play connection from "iPhone".
    CSeq: 1.
    Audio-Jack-Status: connected; type=analog.
    Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=53964;x-events;control_port=56318.
    CSeq: 2.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
rtp_setup: cport=56318 tport=53964.
Connection from IPv4: 192.168.178.35:50028
listening for audio, control and timing on ports 48823, 36089, 39113.
    CSeq: 2.
    Audio-Jack-Status: connected; type=analog.
    Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=36089;timing_port=39113;server_port=48823.
    Session: 1.
    Range: npt=0-.
    X-Apple-Durations: b=16; c=165; au=529; an=482; sa=77.
    CSeq: 3.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
    CSeq: 3.
    Audio-Jack-Status: connected; type=analog.
    Audio-Latency: 88200.
    CSeq: 4.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    Content-Type: text/parameters.
    Content-Length: 19.
    User-Agent: AirPlay/211.3.
    CSeq: 4.
    Audio-Jack-Status: connected; type=analog.
    RTP-Info: seq=21031;rtptime=645592839.
    CSeq: 5.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
    CSeq: 5.
    Audio-Jack-Status: connected; type=analog.
Dropping flushed packet in player_put_packet, seqno 21031, timestamp 645588649, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21032, timestamp 645589001, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21033, timestamp 645589353, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21034, timestamp 645589705, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21035, timestamp 645590057, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21036, timestamp 645590409, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21037, timestamp 645590761, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21038, timestamp 645591113, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21039, timestamp 645591465, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21040, timestamp 645591817, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21041, timestamp 645592169, flushing to timestamp: 645592839.
Dropping flushed packet in player_put_packet, seqno 21042, timestamp 645592521, flushing to timestamp: 645592839.
syncing to seqno 21043.
[  630.905601] WM8524: Sampling Rate=44100Hz
[  630.909838] WM8524: MCLK=16.934MHz
RTP: Packets out of sequence: expected: 21179, got 21187.
requesting resend on 8 packets starting at 21179.
RTP: Packets out of sequence: expected: 21191, got 21179.
RTP: Packets out of sequence: expected: 21187, got 21191.
+++++++++
+++++++++
    CSeq: 6.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
    CSeq: 6.
    Audio-Jack-Status: connected; type=analog.
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER.
+++++++++
+++++++++
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21292, got 21294.
RTP: Packets out of sequence: expected: 21295, got 21292.
RTP: Packets out of sequence: expected: 21294, got 21295.
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
    CSeq: 7.
    X-Apple-Device-ID: 0xc86f1dca95e2.
    DACP-ID: DF510BDF6B5E6630.
    Active-Remote: 508739709.
    User-Agent: AirPlay/211.3.
    CSeq: 7.
    Audio-Jack-Status: connected; type=analog.
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER.
RTP: Packets out of sequence: expected: 21574, got 21575.
+++++++++
RTP: Packets out of sequence: expected: 21589, got 21574.
RTP: Packets out of sequence: expected: 21575, got 21589.
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21679, got 21687.
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21691, got 21679.
+++++++++
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21683, got 21684.
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21687, got 21691.
+++++++++
+++++++++
RTP: Packets out of sequence: expected: 21699, got 21700.
+++++++++
RTP: Packets out of sequence: expected: 21714, got 21699.
RTP: Packets out of sequence: expected: 21700, got 21714.
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
[  662.176344] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  662.185919] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  662.210854] cfg80211: Calling CRDA to update world regulatory domain
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 3082; late packets 19; too late packets 0; resend requests 8; min DAC queue size 5619, min and max buffer occupancy 0 and 233.
[  663.897530] cfg80211: Calling CRDA to update world regulatory domain
Error sendto-ing to timing socket: Network is unreachable
[  683.779869] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  683.801745] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  683.819398] cfg80211: Calling CRDA to update world regulatory domain
[  685.505203] cfg80211: Calling CRDA to update world regulatory domain
[  685.581831] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  685.595654] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  685.607862] cfg80211: Calling CRDA for country: DE
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 6840; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 10598; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 14356; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
[  758.195573] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  758.208210] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  758.237955] cfg80211: Calling CRDA for country: DE
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 18114; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
[  806.205639] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  806.227530] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  806.244206] cfg80211: Calling CRDA to update world regulatory domain
[  807.880283] cfg80211: Calling CRDA to update world regulatory domain
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 21872; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 25630; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
[  843.127782] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  843.134232] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  843.167562] cfg80211: Calling CRDA to update world regulatory domain
[  844.847262] cfg80211: Calling CRDA to update world regulatory domain
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
[  855.225117] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  855.234596] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  855.248122] cfg80211: Calling CRDA for country: DE
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Error sendto-ing to timing socket: Network is unreachable
Sync error: -102.2 (frames); net correction: 470.7 (ppm); corrections: 470.7 (ppm); missing packets 29388; late packets 19; too late packets 0; resend requests 8; min DAC queue size 1000000, min and max buffer occupancy 512 and 0.
[  899.624759] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  899.649874] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  899.678066] cfg80211: Calling CRDA to update world regulatory domain
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
Error getting dac_delay at start of loop.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
Error getting dac_delay at start of loop.
[  901.387321] cfg80211: Calling CRDA to update world regulatory domain
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
Error -- ALSA device in incorrect state (4) for play.
[  901.799454] ------------[ cut here ]------------
[  901.804332] WARNING: CPU: 0 PID: 104 at drivers/net/wireless/brcm80211/brcmfmac/dhd_linux.c:1076 brcmf_netdev_wait_pend8021x+0xe0/0xf4 [brcmfmac]()
Error -- ALSA device in incorrect state (4) for play.
[  901.866565] Modules linked in:
ALSA lib pcm.c:7843:(snd_pcm_recover) un[  901.876083]  brcmfmacderrun occurred

[  901.880586]  brcmutilError -32 writing 352 samples in play() Broken pipe.
[  901.907705] 
[  901.909298] CPU: 0 PID: 104 Comm: wpa_supplicant Not tainted 3.18.3 #1
Error -- ALSA device in incorrect state (4) for play.
[  901.959287] [<c000de40>] (unwind_backtrace) from [<c000c1f4>] (show_stack+0x10/0x14)
[  901.993628] [<c000c1f4>] (show_stack) from [<c0016400>] (warn_slowpath_common+0x68/0x88)
[  902.016243] [<c0016400>] (warn_slowpath_common) from [<c00164bc>] (warn_slowpath_null+0x1c/0x24)
[  902.040249] [<c00164bc>] (warn_slowpath_null) from [<bf016304>] (brcmf_netdev_wait_pend8021x+0xe0/0xf4 [brcmfmac])
[  902.067408] [<bf016304>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf0061d8>] (brcmf_cfg80211_get_key+0x1a8/0x374 [brcmfmac])
[  902.098434] [<bf0061d8>] (brcmf_cfg80211_get_key [brcmfmac]) from [<bf00770c>] (brcmf_cfg80211_del_key+0x1d8/0x2e0 [brcmfmac])
Error -- ALSA device in incorrect state (4) for play.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
[  902.164527] [<bf00770c>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf0078ec>] (brcmf_cfg80211_add_key+0xd8/0x248 [brcmfmac])
[  902.213096] [<bf0078ec>] (brcmf_cfg80211_add_key [brcmfmac]) from [<c037f368>] (nl80211_new_key+0x108/0x144)
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
[  902.253581] [<c037f368>] (nl80211_new_key) from [<c02ccb98>] (genl_rcv_msg+0x22c/0x39c)
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
Error getting dac_delay at start of loop.
[  902.290997] [<c02ccb98>] (genl_rcv_msg) from [<c02cc12c>] (netlink_rcv_skb+0xb4/0xd8)
Error -- ALSA device in incorrect state (4) for play.
[  902.325813] [<c02cc12c>] (netlink_rcv_skb) from [<c02cc958>] (genl_rcv+0x20/0x34)
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
[  902.363540] [<c02cc958>] (genl_rcv) from [<c02cbaa8>] (netlink_unicast+0x14c/0x1cc)
[  902.399402] [<c02cbaa8>] (netlink_unicast) from [<c02cbe98>] (netlink_sendmsg+0x2b8/0x39c)
Error -- ALSA device in incorrect state (4) for play.
[  902.435798] [<c02cbe98>] (netlink_sendmsg) from [<c0297860>] (sock_sendmsg+0x84/0xa8)
Error -- ALSA device in incorrect state (4) for play.
[  902.477184] [<c0297860>] (sock_sendmsg) from [<c0298d28>] (___sys_sendmsg.part.32+0x284/0x290)
[  902.486197] [<c0298d28>] (___sys_sendmsg.part.32) from [<c0299d34>] (__sys_sendmsg+0x4c/0x7c)
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
[  902.555011] [<c0299d34>] (__sys_sendmsg) from [<c0009620>] (ret_fast_syscall+0x0/0x44)
Error -- ALSA device in incorrect state (4) for play.
[  902.591178] ---[ end trace 93a9f5360e80c5ca ]---

brcmfmac is the wifi driver, cfg80211 is the wifi API driver. The messages:

[  610.643727] cfg80211: Calling CRDA to update world regulatory domain
[  618.174092] brcmfmac: brcmf_cfg80211_del_key: invalid key index (4)
[  618.181538] brcmfmac: brcmf_cfg80211_del_key: invalid key index (5)
[  618.211642] cfg80211: Calling CRDA for country: DE

are caused by avahi.

Any idea what's going on here?

mikebrady commented 9 years ago

Hi Jörg. This looks like a WiFi problem to me:

If you search the internet for the phrase cfg80211: Calling CRDA to update world regulatory domain, you'll get lots of hits – and BTW these messages are are definitely not coming from Avahi; they seem to be generated by the WiFi driver. Similarly, a search for the phrase brcmfmac: brcmf_cfg80211_del_key: invalid key index might be rewarding – there's lots of stuff out there.

So, I'd be looking to see what is causing the cfg80211: Calling CRDA to update world regulatory domain messages in the first place. Could it be bad or incompatible WiFi drivers or devices, as seems to be the consensus on the web (though there is more heat than light out there, TBH)? Another, more remote, possibility is the WiFi and/or the USB systems are going into a standby or power-down mode (see one of the closed issues here – https://github.com/mikebrady/shairport-sync/issues/29 – for a conversation about this possibility, but in a different context). Another possibility is a sudden external event, like a microwave oven being used in the vicinity. But it really looks to me like shairport-sync is not the cause of the problem. Let me know what you think.

joerg-krause commented 9 years ago

Hi Mike,

many thanks for your feedback!

I found the reason for the collapse. I've a second audio device with same hostname and same MAC address. It's a test device which repeatedly turns on and off.

If this second device connects to the network router, the router drops the connection for the running audio device and sends the UDP packets to the second device. The device running shairport reconnects, but connection is dropped almost immediately by the network router. That's why the cfg80211 messages. At some point the wifi driver is dying which produces the Error sendto-ing to timing socket: Network is unreachable.

So, in this case it's not a problem caused by shairport. But what I would like to see is that shairport stops playing to the alsa device so that the alsa device stops running and producing the underrun interrupts. What do you think?

mikebrady commented 9 years ago

That is good news indeed. Regarding your last point, if I remember correctly, once underrun has occurred once, shairport sync stops playing to the ALSA device until it gets more packets. So, if the link had broken "cleanly" with no further packets, you'd see just one underrun message. AFAIK, from the device's point of view, underrun is harmless. If shairport-sync was modified to stop playing permanently after an underrun, I think it would cause major problems.

joerg-krause commented 9 years ago

I'm not sure if I understand you correctly.

What I can see from the debug log above is that shairport-sync is receiving an audio stream and starts to send the audio packets to the alsa device.At some point later the connection trouble begins. What I've seen from the kernel log is that the shairport device gets connected to the network router, but authentification is refused (because of the second device with the same name and MAC) and the connection is disconnected. The cfg80211 message is caused by wpa_supplicant (this I learned for now) and has something to do with authentification. The wiireless driver kernel stacktrace is a warning and has also something to do with authentification. So far, so good.

My question is why shairport does not stop to write data to the alsa device? For my it looks like shairport does not stop reading data from the audio buffer and as a consequence the alsa device permantly underruns. If the audio buffer pointer returned by buffer_get_frame is null then nothing will happens. But it seems it is not. Looking at buffer_get_frame() shows that curframe is not initialized with null (or 0). Maybe that's causing the trouble here?

mikebrady commented 9 years ago

buffer_get_frame will sleep on the pthread_cond_wait if no packet frame is available. It will only return a frame to its caller if a frame becomes available, or if a silent frame should be provided. It will only supply a silent frame if there are some non-empty frames later on. If there are no new frames, it will not supply any frames at all. So, the thing is, shairport-sync actually does stop sending data to the alsa device if there is no incoming data. If there is at least some incoming data, it will try to continue by supplying silent frames to make up for missing ones. In the case you have described, it seems that at least some frames are getting through, making shairport-sync continue to try to stream the very-broken-up audio stream.

mikebrady commented 9 years ago

Okay to close this?

joerg-krause commented 9 years ago

It's okay! I was a little bit busy... Thanks for clarification!

mikebrady commented 9 years ago

Thanks.