search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.03k stars 567 forks source link

Shairport-sync refuses Airplay connections. #521

Closed sergiuburian closed 4 years ago

sergiuburian commented 7 years ago

Hi,

After a while (in my case, until the next day) of running on piCorePlayer, the shairport-sync does no longer accept sessions. Also, other software running on the box is not able to play audio anymore - squeezelite complains of not being able to get access to the sound card. It is probably the same for the sub-processes forked by shairport-sync.

Unfortunately, I cannot turn the log on on the piCoreplayer (yes, I followed the instructions, but no logfile under /var/log; id I start it in foreground, I see log messages on the console). So here is a strace output - you see I am trying from different devices Apple and hTC Connect - same thing.

tc@rpiHobby:~$ sudo strace -p 2857
strace: Process 2857 attached
_newselect(4, [3], NULL, NULL, {184, 312614}) = 1 (in [3], left {170, 389781})
**accept(3, {sa_family=AF_INET, sin_port=htons(59727), sin_addr=inet_addr("192.168.178.117")}, [128->16]) = 11**
getsockname(11, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("192.168.178.55")}, [128->16]) = 0
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
nanosleep({0, 500000000}, NULL)         = 0
clone(child_stack=0xb30fef68, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb30ff498, tls=0xb30ff8f0, child_tidptr=0xb30ff498) = 7688
_newselect(4, [3], NULL, NULL, {300, 0}) = 1 (in [3], left {275, 375652})
**accept(3, {sa_family=AF_INET, sin_port=htons(57019), sin_addr=inet_addr("192.168.178.117")}, [128->16]) = 11**
getsockname(11, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("192.168.178.55")}, [128->16]) = 0
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
nanosleep({0, 500000000}, NULL)         = 0
clone(child_stack=0xb30fef68, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb30ff498, tls=0xb30ff8f0, child_tidptr=0xb30ff498) = 7690
_newselect(4, [3], NULL, NULL, {300, 0}) = 1 (in [3], left {123, 732453})
**accept(3, {sa_family=AF_INET, sin_port=htons(49416), sin_addr=inet_addr("192.168.178.139")}, [128->16]) = 11**
getsockname(11, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("192.168.178.55")}, [128->16]) = 0
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
nanosleep({0, 500000000}, NULL)         = 0
clone(child_stack=0xb30fef68, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb30ff498, tls=0xb30ff8f0, child_tidptr=0xb30ff498) = 7698
_newselect(4, [3], NULL, NULL, {300, 0}) = 0 (Timeout)
_newselect(4, [3], NULL, NULL, {300, 0}

Killing and restarting the process solves the problem. For a while ... :) Any idea ?

Thanks,

Sergiu

sergiuburian commented 7 years ago

Hi again,

I can reproduce this now also with the log turned on. This is how it looks like:

Output device name is "hw:CARD=sndrpihifiberry".
The processor is running little-endian.
Version: "3.0.2-OpenSSL-tinysvcmdns-ALSA-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "Rpi".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 0.000000 seconds.
allow a session to be interrupted: 0.
busy timeout time is 3.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 1.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 1.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
no special mdns service interface was requested.
configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
New RTSP connection from 192.168.178.117:53815 to self at 192.168.178.95:5000.
Play connection from user agent "iTunes/10.6 (Macintosh; Intel Mac OS X 10.7.3) AppleWebKit/535.18.5".
Active-Remote string seen: "1986535575".
DACP-ID string seen: "56B29BB6CB904862".
User-Agent is iTunes 10 or better, (actual version is 10); selecting the iTunes latency of 0 frames.
rtp_setup: cport=55119 tport=58772.
Set up play connection from 192.168.178.117 to self at 192.168.178.95.
listening for audio, control and timing on ports 6001, 6002, 6003.
Output sample ratio is 1.
Output frame bytes is 4.
Output bit depth is 16.
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
unrecognised parameter: "SET_PARAMETER rtsp://192.168.178.117/1621535937 RTSP/1.0" (56)

unrecognised parameter: "User-Agent: iTunes/10.6 (Macintosh; Intel Mac OS X 10.7.3) AppleWebKit/535.18.5" (79)

unrecognised parameter: "Client-Instance: bb717cc7f74c43e2" (33)

unrecognised parameter: "DACP-IDIDcc7f74c43e2
DACP-ID
DACP-IDance: bb717cc7f74c43e2
DACP-ID3e2
DACP-ID: bb717cc7f74c43e2
DACP-ID: bb717cc7f74c43e2
DACP-IDInstance: bb717cc7f74c43e2
DACP-IDMac OS X 10.7.3) AppleWebKit/535.18.5
Client-Instance: bb717cc7f74c43e2
DACP-IDebKit/535.18.5
Client-Instance: bb717cc7f74c43e2
DACP-I" (311)

no RTSP header received
rtsp_read_request error 2, packet ignored.
syncing to seqno 21571.
Hammerton Decoder used on unencrypted audio.
Sync packet received before we got a timing packet back.
Sync packet received before we got a timing packet back.
Sync packet received before we got a timing packet back.
Output sample ratio is 1
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 21951.
syncing to seqno 21952.
Output sample ratio is 1
Output written using MMAP
PCM handle name = 'hw:CARD=sndrpihifiberry'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 5804 us (>).
  period_size = 256 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 512 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7093.8,    15853.8,   105595.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7144.3,    14878.7,   102549.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7122.0,    14795.0,   127432.0.
. . .
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7142.0,    14952.5,   116174.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7133.1,    14800.2,   110623.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.8,    14887.5,   105069.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7108.7,    14880.8,   100467.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7134.5,    14844.9,   111261.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7154.6,    14727.2,   107314.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7117.0,    13718.6,   101876.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7127.8,    10375.7,    84746.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.0,    10236.1,    67299.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7109.9,    10800.0,   189230.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7124.9,    18229.7,   500238.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7135.0,    10354.9,    72075.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7123.8,    10208.8,    59649.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7135.7,    19415.4,   212570.0.
**Buffers exhausted.
As Yeats almost said, "Too long a silence / can make a stone of the heart"**
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.

I understand that the client stopped playing, and the RTSP threads are closed. However, to me it looks like the shairport-sync is left in an inconsistent state. Repeated reconnect attempts from an Apple client device produces even a segmentation fault.

Any idea ?

Thanks,

Sergiu

mikebrady commented 7 years ago

Thanks for the posts.

First thing is – what are you sending from?

Second, the mean packet reception interval is pretty far off. It should be 7981.85 microseconds – something radically wrong there. Could it be that the clock on your device is off by about 10%?

Third, some unrecognized parameter – I wonder what that is, and what app it's coming from.

sergiuburian commented 7 years ago

Me again ... digging more into details.

First, answering your questions:

  1. The 192.168.178.117 device is a HTC U Play with Android 6 and HTC Connect. In the post with the strace, you also see the 192.168.178.139 - this is an iPad.

  2. Do you mean, the mean packet rx interval is too low ? I am not sure how to check the clock deviation. The RPi does not have an RTC clock, and gets the time from NTP. The date command looks good, however it is difficult to compare with a mobile device time at millisecond level. Any hint how to check what you are asking for?

  3. As I said, the unrecognized params come from HTC.

I also want to say that with my current settings, the player works beautifully. No pops, 8% CPU load constantly, just some delay in reaction, but this is not annoying. However, at some point after playing stops (sometimes stops on its own, somtimes because the playlist is finished) I cannot connect to it anymore.

Now, I was doing further testing - please see below:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7194.0,    15568.7,   153068.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7043.5,    15607.0,   129269.0.
Closing down RTSP conversation thread...
New RTSP connection from 192.168.178.51:49484 to self at 192.168.178.95:5000.
Try to get the player now
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
New RTSP connection from 192.168.178.51:49642 to self at 192.168.178.95:5000.
Try to get the player now
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.

This happens after the playing stopped because the playlist is finished, and the RPi stays for some time. I cannot reconnect because it tells it is still playing. I realize from the code that there is an issue acquiring the play_lock, so I was checking whether the lock was released in this case before. I guess this is the problem - when the thread is closed under "certain" conditions, the lock is not released properly. The clients tell that the player is in use, despite of the setting that allows interruption.

Last but not least: I do not mean to spam you with my issues. I am terribly thankful for all the time you spend for myself and other users. I am also willing to test and help fixing those as well; do you have any instructions on how to compile on piCorePlayer / tiny core linux?

Thanks a lot,

Sergiu

sergiuburian commented 7 years ago

Just happened again. The HTC device was playing over Ethernet; playlist has finished, and I had other Audio notifications coming up on device. I started playing again after some time, no audio. I have explicitly disconnected the session from the HTC device, the shairplay-sync still does not accept any connection. Log file:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.7,     9590.7,    59998.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7107.0,     9449.1,    53511.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.9,     9451.3,    69715.0.
Error -- ALSA device in incorrect state (4) for play.                                                                                            
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 -32 writing 352 samples in play(): "Broken pipe".                                                                                          
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7346.7,    28373.1,  1215009.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.3,     9243.6,    47186.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7123.6,     9631.4,    75064.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7117.2,     9758.8,    60961.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7138.7,    15028.8,   589092.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7134.8,    21578.3,   798911.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7127.7,     9656.7,   107306.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7107.5,     9422.4,    52111.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7120.3,     9502.4,    47686.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7105.0,     9366.8,    48216.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7127.8,    13292.4,   483392.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7106.8,     9939.4,    99058.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7119.3,     9496.9,    49438.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7114.3,     9467.4,    46060.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7119.2,     9389.3,    59948.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7112.2,     9461.4,    62756.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7115.1,     9955.8,   143306.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7105.7,     9497.2,    57571.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7118.0,     9458.1,    48922.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7115.4,     9554.5,    93365.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7125.7,    15520.2,   255164.0.
RTSP shutdown requested.                                                                                                                         
Closing down RTSP conversation thread...                                                                                                         
New RTSP connection from 192.168.178.51:49719 to self at 192.168.178.137:5000.                                                                   
Already playing.                                                                                                                                 
Closing down RTSP conversation thread...                                                                                                         
RTSP conversation thread terminated.

Looking at the strace output when trying to connect, first from the same HTC , second from iPad:

strace: Process 5951 attached
_newselect(4, [3], NULL, NULL, {236, 170969}) = 1 (in [3], left {225, 642177})
accept(3, {sa_family=AF_INET, sin_port=htons(49721), sin_addr=inet_addr("192.168.178.51")}, [128->16]) = 11
getsockname(11, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("192.168.178.137")}, [128->16]) = 0
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
write(2, "New RTSP connection from 192.168"..., 78) = 78
write(2, "\n", 1)                       = 1
nanosleep({0, 500000000}, NULL)         = 0
clone(child_stack=0xb30fef68, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb30ff498, tls=0xb30ff8f0, child_tidptr=0xb30ff498) = 6030
_newselect(4, [3], NULL, NULL, {300, 0}) = 1 (in [3], left {284, 738806})
accept(3, {sa_family=AF_INET, sin_port=htons(43427), sin_addr=inet_addr("192.168.178.117")}, [128->16]) = 11
getsockname(11, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("192.168.178.137")}, [128->16]) = 0
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x12ccfc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x12ccf8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x12cce0, FUTEX_WAKE_PRIVATE, 1)  = 1
write(2, "New RTSP connection from 192.168"..., 79) = 79
write(2, "\n", 1)                       = 1
nanosleep({0, 500000000}, NULL)         = 0
clone(child_stack=0xb30fef68, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb30ff498, tls=0xb30ff8f0, child_tidptr=0xb30ff498) = 6031
_newselect(4, [3], NULL, NULL, {300, 0}

Looking into the code, it looks like in handle_announce, the new thread cannot get the player (because of the lock not being somehow freed before, I guess). Since my config does not allow session interruption, it bailed out with "Already playing". I will activate session interruption, maybe this will solve at least getting the lock back since the code executed when interruption allowed kills the previous thread (sorry for explaining your own code, was more for showing my train of thoughts :) ).

Will keep you posted.

Sergiu

sergiuburian commented 7 years ago

Hi again, Unfortunately, this setting did not help. Whereas switching between devices during "normal" state works very well, as soon as this ALSA device state issue occurs, I cannot reconnect at all anymore. Here's again :) the new log:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7122.9,    10714.2,    71461.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7134.8,    14910.3,   199117.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7123.2,    10543.6,    89358.0.
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 352 samples in play(): "Broken pipe".
Error -32 writing 237 samples in play(): "Broken pipe".
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7146.6,    11397.5,   108634.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7138.9,    10237.4,    96354.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7111.7,    19897.4,   513989.0.
RTSP shutdown requested.
Closing down RTSP conversation thread...
New RTSP connection from 192.168.178.117:56517 to self at 192.168.178.137:5000.
Try to get the player now
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
New RTSP connection from 192.168.178.51:49767 to self at 192.168.178.137:5000.
Try to get the player now
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
New RTSP connection from 192.168.178.117:34536 to self at 192.168.178.137:5000.
Try to get the player now
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.

The situations have occurred after a 2-3 hours of not playing. Start playing again did work for 1 minute, then it went into this state.

Any suggestions?

Thanks,

Sergiu

sergiuburian commented 7 years ago

Hi,

Just wanted to confirm that the issue still occurs with 3 different RPis 1, both via WiFi as well as via Ethernet. Same pattern, ALSA erroneous state, "Broken pipe" and then "Already playing" when newly connecting ...

I hope you can give me some hints ....

Thanks,

Sergiu

mikebrady commented 7 years ago

Hi Sergiu. Thanks for all the updates. It would be good to get some complete clarity on this. If you start up an RPi with piCorePlayer and Shairport Sync and play only from the iPad (never from the HTC), does everything work properly?

mikebrady commented 7 years ago

I am still very curious about the packet reception interval. This should be 7981.859 microseconds, and on your logs it's coming in at around 7140 microseconds. That needs explanation. It's related to the device's own clock, and has nothing to do with NTP or the time of day.

Here are some logs from an RPi running Raspian:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,     1144.3,    35261.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.9,     1045.6,    21782.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.3,     1050.2,    29508.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.9,     1062.9,    30299.0.

What is going on, I wonder? Could it be something the piCorePlayer is doing?

sergiuburian commented 7 years ago

Hi Mike,

Thanks for your reply! I am running top in parallel for quite some time, and the cpu load of ~ 8% only comes from shairport-sync. Here it is, from top

Mem: 102432K used, 342116K free, 11292K shrd, 7952K buff, 41156K cached
CPU:  2.8% usr  6.3% sys  0.0% nic 89.5% idle  0.0% io  0.0% irq  1.2% sirq
Load average: 0.04 0.10 0.08 1/156 5297
  PID  PPID USER     STAT   VSZ %VSZ CPU %CPU COMMAND
 5272  5243 tc       S    64820 14.5   0  7.7 shairport-sync
 5297  5243 tc       R     3180  0.7   0  0.8 top
 5241  5032 root     S     4732  1.0   0  0.4 sshd: tc@pts/0
    3     2 root     SW       0  0.0   0  0.4 [ksoftirqd/0]
 5023     1 root     S    11184  2.5   0  0.2 /usr/local/bin/squeezelite -n Hobby -o hw:CARD=sndrpihifiberry -a
    6     2 root     SW       0  0.0   0  0.2 [kworker/u2:0]
 5032     1 root     S     4732  1.0   0  0.0 /usr/local/sbin/sshd
...

Regarding the microseconds, I have done a couple of tests, that I hope will help. In fact, it depends on the client! - see below:

iPad local player via Airplay: 

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    1465
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.6,    1358
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7983.9,    1355
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    1343
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7960.3,    1341

iPad Synology DS Audio player via Synology AudioStation 5.2 Airplay client (not! the native iPad one):

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7757.2,    1658
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8010.6,    1607
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7952.6,    1592
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.6,    1602
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.3,    1608
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7947.9,    1601
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7996.1,    1595
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    1602
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7984.5,    1608

HTC U Play with local player via HTC Connect as Airplay client: 

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7044.6,    1350
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7151.6,    1037
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7140.8,    1147
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7113.8,    1046
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7143.2,    1048
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7115.9,    1015
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.6,    1027
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7111.5,    1030
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7113.4,     988
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7125.4,    1000

HTC U Play with DS Audio player via Synology AudioStation 5.2 Airplay client (not! the native HTC Connect one):

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7760.5,    1650
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8013.3,    1607
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7995.2,    1595
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7949.1,    1598
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7995.2,    1607
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7947.7,    1601
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7992.9,    1594
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.4,    1600
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.3,    1607
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.8,    1605
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7993.5,    1594

So, it is good you insisted on it. Whereas in all the cases, the CPU load of the RPi is very similar as what I have pasted above, it seems like the strange number comes from the HTC Connect client ... anything we can do about it at all?

Thanks a lot for your time you put into this,

Sergiu

mikebrady commented 7 years ago

Thanks for the investigations. I think the results mean that the packets are of a different size coming from HTC Connect, which should be fine. What I was concerned about was that piCorePlayer somehow completely wrecked timing on the Pi, but now I am reassured.

Your situation is quite unusual, in that you are using an unusual OS (piCorePlayer), two unusual clients – HTC Connect and the DS Audio player via Synology AudioStation 5.2 Airplay client. I have no experience of any of these, and it's nice to see that Shairport Sync works at all :)

All that said, to make progress, it would be great to try to isolate the issues by modifying just one thing at a time with respect to the standard setup – a native Apple client running into Shairport Sync on Raspbian Jessie. So, using basic interpolation to minimise processor load, selecting the output device and mixer, if appropriate, changing the operating system from Raspbian to piCorePlayer, and changing nothing else, does Shairport Sync work well with an iPad using its native AirPlay client? If that can be established, then one could tentatively eliminate piCorePlayer as a cause of problems.

sergiuburian commented 7 years ago

Hi Mike, Sure, I will try to do step by step analysis to see what happens. For the tests, I have tried several combinations in order to see how the system behaves, but the "usual" use-case for me is:

I understand, I go beyond the "wanna hear my iPhone on speakers" case, but I guess most of the shairport users do ;) . And your software allows us to do so :) . And I am glad to help in making it more compatible to various clients, so it will be even wider used and make even more people happy ;)

So let me do some tests now, I'll come back to you.

Thanks again a lot!

Sergiu

mikebrady commented 7 years ago

Thanks. BTW, I'm not casting any aspersions on any of these programs, just that I haven't got [recent] experience of them. I will try out piCorePLayer for sure – I think I tried it in the past and found it lacking, but that might just have been me...

Meantime, if you could switch over to the development branch of Shairport Sync, that would be great, because it has ongoing fixes and updates, and it's where any changes would first appear.

More generally, one of the problems with solutions like Shairport Sync is that the AirPlay protocol is not public, so it has to be discovered by observation. HTC Connect is, AFAIK, an Apple-licensed implementation. Presumably they have access to the full protocol and so are doing things that are compliant with the protocol but new to us "observers". So, it would be necessary for us to determine what is new and deal with it.

sergiuburian commented 7 years ago

Hi Mike, Kindly thank you for your answer. piCorePlayer is worth looking at because from the user perspective, this is a hassle-free, robust system once it is working. I was assuming that you were in active contact with them, as they include your software in their distribution; I have requested them to update to your latest version, include conf-file based configuration, and they were quite supportive.

As I have mentioned above, I would like to help :) So I have started the tests in a more systematic manner, so we can figure out the issue.

I have also cloned the master branch already and compiled in Eclipse on Ubuntu, but I will move to the /development then. I still need to compile it on piCorePlayer myself - that's a bit of work. I am happy to help "observing" the HTC Connect and contribute, in the limits of my time.

I will keep you posted. Please let me know whether we should continue the comm thread in this post, or you prefer other ways.

Thanks,

Sergiu

sergiuburian commented 7 years ago

Hi Mike,

Baseline test no 1: RPi 1, piCoreplayer, Ethernet, only Apple controllers (iPad, iPhone), interpolation "basic", resync disabled, alsa disable_synchronization is "yes".

Summary: Everything OK. No sound interruptions, no bad alsa state, no refused re-connections after finishing playlists and waiting a while before plying again. Mean packet reception interval is around 7980 microsec. CPU load 8-12%

Next test: Same config, HTC Connect controller.

mikebrady commented 7 years ago

Cool, thanks.

sergiuburian commented 7 years ago

Test no 2: RPi 1, piCoreplayer, Ethernet, only HTC Connect controller (U Play), interpolation "basic", resync disabled, alsa disable_synchronization is "yes".

Summary:

Differences that I have observed between Apple and HTC Connect

I guess we spotted more or less the cause, however, I will continue now with the next test: back to Apple controller, but via WiFi.

Thanks,

Sergiu

PS: Sorry, forgot to mention: interpolation was basic in both cases.

mikebrady commented 7 years ago

Good work, thanks, and interesting results. BTW, I am ok with continuing this conversation here, if that's okay. Others might jump in with observations and ideas.

sergiuburian commented 7 years ago

Test no 3: RPi 1, piCoreplayer, WiFi, only Apple controllers (iPad, iPhone), interpolation "basic", resync disabled, alsa disable_synchronization is "yes".

Summary after 8 hours: Everything OK. No sound interruptions, no bad alsa state. However, I see Buffer exhausted many times(hundreds of time)in the log, but not followed by Bad ALSA state (4) (there was once a loss of WiFi for the iPad client, maybe this is the case). I had once a 1 minute of not being visible, but then it became visible again without myself restarting. Mean packet reception interval is around 7980 microsec (same as with Ethernet). CPU load: 8-12% - same as with Ethernet

Next test: HTC and WiFi. I think the expected results are obvious, however I will do this. But only tomorrow. Today I stick with Apple, since I have guests and do not want to compromise the music listening experience ;)

Do you have a specific wish for a test scenario, based on what I have tested so far ? Can you explain under which circumstances is "Buffer exhausted" supposed to occur?

Thanks,

Sergiu

mikebrady commented 7 years ago

Thanks again for all this. Buffer exhausted happens when there is no more audio to output, and it should only happen, say, at the end of a play session.

A specific test I would like to see would be just like Test 3 above, but with disable_synchronization set to "no". My hope and expectation is that the number of Buffer Exhausted messages would be much less and that everything would work more-or-less normally.

sergiuburian commented 7 years ago

OK,

I'll set this to a higher prio. My observation is that Apple always closes the RTSP thread. Even when I change the album, or the song manually. I'm curious also.

Thanks,

Sergiu

mikebrady commented 7 years ago

Thanks s. I'm trying to locate a HTC Connect device here; not having a lot of joy though...

sergiuburian commented 7 years ago

Hi Mike,

The party is over here, so I can look in the log files :)

Test no 3.1 : RPi 1, piCoreplayer, WiFi, only Apple controllers (iPad, iPhone), interpolation "basic", resync disabled, alsa disable_synchronization is "no".

Well, in general it was OK, however, looking into the log files, there is still a lot of "Buffers exhausted". This time unfortunately also with Alsa error, after it played without interruption for 400+ lines of "Packet reception interval stats..." (sorry, i do not know how much real time that is):

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.1,    12408.7,   144308.0.
Buffers exhausted.                                                                                                                               
Error -- ALSA device in incorrect state (4) for play.                                                                                            
Buffers exhausted.                                                                                                                               
Error -- ALSA device in incorrect state (4) for play.                                                                                            
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.

And after this, buffers exhausted continued to appear, even in the following form:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7995.4,    18609.2,   151701.0.
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Error -- ALSA device in incorrect state (4) for play.                                                                                            
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.                                                                                 
Delay error -32 when checking running latency.                                                                                                   
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
Buffers exhausted.

It is just an impression, that running without interruption for a longer time may cause these messages/errors to occur. I will try tomorrow to turn off alsa_sync and let it run for very long, with no interruption, see if the error still happens.

Thanks,

Sergiu

PS: Regarding HTC Connect - if you want me to dump the conversation with shairport-sync, I could do so. However, next week I am on a business trip, so it will have to wait.

sergiuburian commented 7 years ago

... continued the 3.1 test: after running it again for a longer time, the error comes again:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7967.7,    18405.7,   141831.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7995.0,    16720.5,   180748.0.
Buffers exhausted.                                                                                                                               
Error -- ALSA device in incorrect state (4) for play.                                                                                            
Buffers exhausted.                                                                                                                               
Buffers exhausted.                                                                                                                               
As Yeats almost said, "Too long a silence / can make a stone of the heart"                                                                       
Request to shut down all rtsp conversation threads

This caused an interruption of play, however I could then reconnect.

Please note that WiFi should be OK, since I stream FLACs with Squeezebox on the same device (not in parallel though :) ) and it works without any hick-ups.

Regards,

Sergiu

mikebrady commented 7 years ago

Hi there. A colleague has a HTC 1 M8 with the native AirPlay client installed. It works without problems, but it never terminates the play session, even when there is no output. As the phone moves around in the WiFi coverage, it's inclined to drop packets, run out of buffers, and so on, but it continues to work – he was playing from Spotify.

mikebrady commented 6 years ago

Hi there. I'm not sure where we stand with this. Have there been any developments?

sergiuburian commented 6 years ago

Sorry for the long summer delay. I guess the conclusion is that the HTC AirPlay implementation is not fully compatible with shairport-sync. Streaming from an Apple device works for me now since a while. Streaming from HTC works for a while then stops - as explained above. Even if the phone is not moved at all ...

As I have mentioned above ans you have observed as well, the main differences observed so far are:

So I guess, we should classify this as a feature request.

Thanks a lot,

Sergiu

mikebrady commented 6 years ago

OK – thanks a lot. We'll keep an eye on it.

mikebrady commented 4 years ago

Pretty sure this has been fixed! Closing this inactive issue. Please open a new one if necessary.