Shairport-sync: beta is crashing sometimes: Player: packets out of sequence

[a-x-]

shairport-sync --version
3.3rc7-OpenSSL-Avahi-ALSA-metadata-sysconfdir

logs from 1 device

-- Logs begin at Wed 2019-05-15 16:17:01 MSK, end at Sun 2019-05-19 10:47:35 MSK. --
May 18 22:54:16 rpi1 shairport-sync[356]:          3.371893368|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:    26579.4,   358388
May 18 22:54:34 rpi1 shairport-sync[356]:         17.952032900|Time ping turnaround time: 1074387 us -- it looks like a timing ping was lost.
May 18 22:54:36 rpi1 shairport-sync[356]:          2.047125123|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7996.0,    16260
May 18 22:54:41 rpi1 shairport-sync[356]:          5.127216033|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:41 rpi1 shairport-sync[356]:          0.047825601|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:53 rpi1 shairport-sync[356]:         12.113193707|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:54 rpi1 shairport-sync[356]:          1.027194957|Player: packets out of sequence: expected: 38955, got: 38968, with ab_read: 38969 and ab_write: 39170.
May 18 22:54:55 rpi1 shairport-sync[356]:          0.520060789|Large positive sync error: 536900.
May 18 22:54:56 rpi1 shairport-sync[356]:          0.589930746|Player: packets out of sequence: expected: 39107, got: 39108, with ab_read: 39109 and ab_write: 39170.
May 18 22:54:58 rpi1 shairport-sync[356]:          2.200495640|alsa: underrun while writing 352 samples to alsa device.
May 18 22:55:00 rpi1 shairport-sync[356]:          2.169265554|Aliasing of buffer index -- reset.
May 18 22:55:00 rpi1 shairport-sync[356]:          0.005188848|Player: packets out of sequence: expected: 39535, got: 40559, with ab_read: 40560 and ab_write: 40979.
May 18 22:55:00 rpi1 shairport-sync[356]:          0.000378989|Large positive sync error: 218528.
May 18 22:55:04 rpi1 shairport-sync[356]:          4.261920349|Time ping turnaround time: 1180176 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpi1 shairport-sync[356]:          0.005400842|Time ping turnaround time: 1185580 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpi1 shairport-sync[356]:          0.000312991|Time ping turnaround time: 1185896 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpi1 shairport-sync[356]:          0.019665425|Time ping turnaround time: 1205556 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpi1 shairport-sync[356]:          0.101660027|Time ping turnaround time: 1307217 us -- it looks like a timing ping was lost.
May 18 22:55:05 rpi1 shairport-sync[356]:          0.275114954|Player: packets out of sequence: expected: 41145, got: 41186, with ab_read: 41187 and ab_write: 41952.
May 18 22:55:05 rpi1 shairport-sync[356]:          0.021590368|Large positive sync error: 203647.
May 18 22:55:07 rpi1 systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV
May 18 22:55:07 rpi1 systemd[1]: shairport-sync.service: Unit entered failed state.
May 18 22:55:07 rpi1 systemd[1]: shairport-sync.service: Failed with result 'signal'.

logs from 2th device

May 18 22:52:20 rpz shairport-sync[396]:         20.224708452|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8079.1,    11034.
May 18 22:52:40 rpz shairport-sync[396]:         20.159736644|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8059.5,    12231.
May 18 22:53:01 rpz shairport-sync[396]:         20.284037343|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8109.3,     9476.
May 18 22:53:31 rpz shairport-sync[396]:         30.906844807|alsa: underrun while writing 352 samples to alsa device.
May 18 22:53:32 rpz shairport-sync[396]:          0.443087851|Player: packets out of sequence: expected: 28719, got: 28732, with ab_read: 28733 and ab_write: 28733.
May 18 22:53:32 rpz shairport-sync[396]:          0.003684990|Large positive sync error: 523021.
May 18 22:53:32 rpz shairport-sync[396]:          0.111535711|Player: packets out of sequence: expected: 28762, got: 28764, with ab_read: 28765 and ab_write: 28765.
May 18 22:53:32 rpz shairport-sync[396]:          0.126817671|Player: packets out of sequence: expected: 28788, got: 28792, with ab_read: 28793 and ab_write: 28793.
May 18 22:53:32 rpz shairport-sync[396]:          0.255692337|Large positive sync error: 522820.
May 18 22:53:33 rpz shairport-sync[396]:          0.597507450|Player: packets out of sequence: expected: 28898, got: 28899, with ab_read: 28900 and ab_write: 28966.
May 18 22:53:33 rpz shairport-sync[396]:          0.232645396|Large positive sync error: 522463.
May 18 22:53:45 rpz shairport-sync[396]:         11.746192536|alsa: underrun while writing 352 samples to alsa device.
May 18 22:53:48 rpz shairport-sync[396]:          2.519139468|Aliasing of buffer index -- reset.
May 18 22:53:48 rpz shairport-sync[396]:          0.004364988|Player: packets out of sequence: expected: 29468, got: 31516, with ab_read: 31517 and ab_write: 31517.
May 18 22:53:48 rpz shairport-sync[396]:          0.146673620|Player: packets out of sequence: expected: 31534, got: 31535, with ab_read: 31536 and ab_write: 31548.
May 18 22:53:48 rpz shairport-sync[396]:          0.005194987|Large positive sync error: 240742.
May 18 22:53:52 rpz shairport-sync[396]:          4.366489677|alsa: underrun while writing 352 samples to alsa device.
May 18 22:53:56 rpz shairport-sync[396]:          4.101005367|Player: packets out of sequence: expected: 32245, got: 32248, with ab_read: 32249 and ab_write: 33043.
May 18 22:53:56 rpz shairport-sync[396]:          0.101724736|Large positive sync error: 363470.
May 18 22:54:04 rpz shairport-sync[396]:          7.344614959|Player: packets out of sequence: expected: 33182, got: 33294, with ab_read: 33295 and ab_write: 33881.
May 18 22:54:04 rpz shairport-sync[396]:          0.034167912|Large positive sync error: 323691.
May 18 22:54:05 rpz shairport-sync[396]:          1.684574633|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:    25888.5,   355429.
May 18 22:54:07 rpz shairport-sync[396]:          1.804209323|Time ping turnaround time: 1260898 us -- it looks like a timing ping was lost.
May 18 22:54:07 rpz shairport-sync[396]:          0.066381828|Time ping turnaround time: 1327280 us -- it looks like a timing ping was lost.
May 18 22:54:07 rpz shairport-sync[396]:          0.005288986|Time ping turnaround time: 1332569 us -- it looks like a timing ping was lost.
May 18 22:54:09 rpz shairport-sync[396]:          2.249470169|Player: packets out of sequence: expected: 34026, got: 34218, with ab_read: 34219 and ab_write: 35039.
May 18 22:54:10 rpz shairport-sync[396]:          0.151528607|Large positive sync error: 255710.
May 18 22:54:11 rpz shairport-sync[396]:          1.451677237|Player: packets out of sequence: expected: 34421, got: 34965, with ab_read: 34966 and ab_write: 35243.
May 18 22:54:11 rpz shairport-sync[396]:          0.022429942|Large positive sync error: 63859.
May 18 22:54:12 rpz shairport-sync[396]:          1.365629461|Player: packets out of sequence: expected: 34969, got: 35159, with ab_read: 35160 and ab_write: 35417.
May 18 22:54:25 rpz shairport-sync[396]:         12.799341828|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7961.9,    24828.
May 18 22:54:34 rpz shairport-sync[396]:          8.877816996|Time ping turnaround time: 1246446 us -- it looks like a timing ping was lost.
May 18 22:54:41 rpz shairport-sync[396]:          7.176619406|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:41 rpz shairport-sync[396]:          0.050458869|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:53 rpz shairport-sync[396]:         12.077069715|alsa: underrun while writing 352 samples to alsa device.
May 18 22:54:54 rpz shairport-sync[396]:          0.278402279|Player: packets out of sequence: expected: 38954, got: 38968, with ab_read: 38969 and ab_write: 38985.
May 18 22:54:54 rpz shairport-sync[396]:          0.046713879|Large positive sync error: 535057.
May 18 22:54:54 rpz shairport-sync[396]:          0.191634504|Player: packets out of sequence: expected: 38998, got: 39000, with ab_read: 39001 and ab_write: 39017.
May 18 22:54:54 rpz shairport-sync[396]:          0.064060834|Large positive sync error: 534703.
May 18 22:54:54 rpz shairport-sync[396]:          0.080937790|Player: packets out of sequence: expected: 39016, got: 39019, with ab_read: 39020 and ab_write: 39035.
May 18 22:54:54 rpz shairport-sync[396]:          0.111758711|Large positive sync error: 534345.
May 18 22:54:54 rpz shairport-sync[396]:          0.126827671|Player: packets out of sequence: expected: 39047, got: 39050, with ab_read: 39051 and ab_write: 39170.
May 18 22:54:55 rpz shairport-sync[396]:          0.423489903|Large positive sync error: 533990.
May 18 22:54:55 rpz shairport-sync[396]:          0.359875068|Large positive sync error: 533638.
May 18 22:54:55 rpz shairport-sync[396]:          0.150865610|Player: packets out of sequence: expected: 39168, got: 39169, with ab_read: 39170 and ab_write: 39411.
May 18 22:54:55 rpz shairport-sync[396]:          0.232445397|Large positive sync error: 533283.
May 18 22:54:57 rpz shairport-sync[396]:          1.561151957|Large positive sync error: 532926.
May 18 22:54:57 rpz shairport-sync[396]:          0.104358730|Player: packets out of sequence: expected: 39408, got: 39409, with ab_read: 39410 and ab_write: 39411.
May 18 22:54:59 rpz shairport-sync[396]:          2.340242938|alsa: underrun while writing 352 samples to alsa device.
May 18 22:55:02 rpz shairport-sync[396]:          2.321916987|Aliasing of buffer index -- reset.
May 18 22:55:02 rpz shairport-sync[396]:          0.004979987|Player: packets out of sequence: expected: 39888, got: 40912, with ab_read: 40913 and ab_write: 41208.
May 18 22:55:02 rpz shairport-sync[396]:          0.018455952|Large positive sync error: 208955.
May 18 22:55:04 rpz shairport-sync[396]:          2.384323825|Time ping turnaround time: 1348903 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpz shairport-sync[396]:          0.005426986|Time ping turnaround time: 1354331 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpz shairport-sync[396]:          0.000299000|Time ping turnaround time: 1354634 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpz shairport-sync[396]:          0.019942948|Time ping turnaround time: 1374573 us -- it looks like a timing ping was lost.
May 18 22:55:04 rpz shairport-sync[396]:          0.101958736|Time ping turnaround time: 1476535 us -- it looks like a timing ping was lost.
May 18 22:55:06 rpz shairport-sync[396]:          1.597832862|Player: packets out of sequence: expected: 41431, got: 41509, with ab_read: 41510 and ab_write: 42119.
May 18 22:55:06 rpz shairport-sync[396]:          0.023022940|Large positive sync error: 181130.
May 18 22:55:06 rpz shairport-sync[396]:          0.528970630|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:    16500.9,   242182.
May 18 22:55:07 rpz shairport-sync[396]:          0.763106024|Player: packets out of sequence: expected: 41541, got: 42027, with ab_read: 42028 and ab_write: 42285.
May 18 22:55:07 rpz shairport-sync[396]:          0.023338940|Large positive sync error: 9701.
May 18 22:55:08 rpz shairport-sync[396]:          0.294894236|Player: packets out of sequence: expected: 42031, got: 42067, with ab_read: 42068 and ab_write: 42325.
May 18 22:55:08 rpz systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV
May 18 22:55:08 rpz systemd[1]: shairport-sync.service: Unit entered failed state.
May 18 22:55:08 rpz systemd[1]: shairport-sync.service: Failed with result 'signal'.

[mikebrady]

Thanks for the report. If you could get it to happen reliably, that would be great. It looks like you have severe network problems, BTW. Also, the right-hand end of the logs is truncated. Could that be restored, because the maximum packet intervals data is missing, please?

[mikebrady]

I pushed out a slight update which checks for three divide-by-zero possibilities that might just be associated with very challenged networks – might be worth updating to.

[mikebrady]

As a matter of interest, what player are you using?

[a-x-]

Hey,

players I use:

• iTunes, currently Version 12.9.5.5
• iOS Apple Music

at a time of report I used previous version. macOS updated airplay protocol recently

I still not updated shairport. I observes stuttering episodically.

I'll update shairport and I'll try to grab more logs
thank you

[a-x-]

Update had not helped :-(

too much stuttering

audio fragment (at end): https://yadi.sk/d/cdODoQQIruUY3Q

I tried 3.3-OpenSSL-Avahi-ALSA-metadata-sysconfdir:/etc

[a-x-]

i'm going to try 3.3.1

[mikebrady]

Thanks. Could you have a look here to get an idea what kind of extra information would be useful.

[a-x-]

3.3.1 is a still buggy :-(

log

shairport verbosity: 3, statistics: true
https://gist.github.com/a-x-/0cc882f6457e8c6d67086db9445a2b19

timing fragment

18:19:45: stuttering caused
?: crash?
~18:37:30: stuttering
~18:38:14: stuttering
~18:39:44 stuttering twice
~18:40:29

[a-x-]

the same problems I have on all of my micro PCs: 2x rpi-zero, 1x rpi2, 1x rpi1, 1x orpi zero

problem started with some update (I don't remember exact recent version.
>= 3.0.0 as I can understand

[a-x-]

I'm streaming via both wifi and ethernet. from iOS (different apps) and macOS (iTunes). both are 'vulnerable'

macOS (stable): 10.14.5
iOS (beta): 12.4-latest-beta ?? (iOS does not provide exact beta version) (16G5046d)

every shairport host machine with on wire (100Mb ethernet)

[mikebrady]

Thanks. Could you set the verbosity to 2, not 3, and gather those logs again please? The verbosity if 3 is much too noisy and may actually slow the system down too much. What OS are you using on the Pis?

[mikebrady]

Just thinking about this: if the problem is occurring on all these machines, then wouldn't it be fair to assume that the cause is either (1) something common to all machines or (2) something in the environment.

For (1), apart from Shairport Sync, what else is common? For example, what Operating Systems are in use?

Most obviously for (2), a faulty network would be a good potential candidate. While all the connections are over a wire (including to the Pi Zeros?), a faulty router could be a potential cause. Is there any way of avoiding the router completely (or temporarily using a different one), just to test things out?

[a-x-]

What OS are you using on the Pis?

latest versions of raspbian (I cannot currently say actual versions)

Are all the connections over a wire including to the Pi Zeros?

yep =)

[a-x-]

I'm going to buy 1000Mbit/s router and to replace ethernet wires.

Currently I grabbed out the logs with verbosity 2:
https://gist.github.com/a-x-/96e7a0cc101260e4a0de8a5452ba2a62

stuttering caused on 07:10

it's wired orange pi again, stream over wi-fi from iOS this time.
My wifi currently is 1000mbps+ 5Ghz

[mikebrady]

Thanks. It may be that there is something a bit odd about the router. Some routers do funny things. It might be worth checking for firmware updates to the router, or are there any strange firewall or "multimedia" settings to play with on it?

[a-x-]

settings look good, though...

So, I'll try with better mikrotic 1gbps router next week

[a-x-]

and again with current router and current network setup w/o any changes my shairport setup worked pretty earlier.

problems started with some version update. I'll try to detect the first bad version in some future

[a-x-]

Looks like, problem with orange pi only currently

[mikebrady]

Thanks for this contribution. Closing the issue. Please open a new one if necessary.

[mikebrady]

As a postscript, I finally got to play with an Orange Pi Zero 512, setting it up with Armbian and getting WiFi going.

Linux orangepizero 4.19.62-sunxi #5.92 SMP Wed Jul 31 22:07:23 CEST 2019 armv7l GNU/Linux

1. I found it useful to set the interface property in the general section to the WiFi interface wlan0.
2. WiFi reception was spotty on a known good network, with errors showing in the system log like these:

   Nov 16 16:51:05 orangepizero kernel: xradio_wlan mmc1:0001:1: missed interrupt
   Nov 16 16:51:09 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status
   Nov 16 16:51:10 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status
   Nov 16 16:51:19 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status
   Nov 16 16:51:19 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status
   Nov 16 16:51:19 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status
   Nov 16 16:51:19 orangepizero kernel: xradio_wlan mmc1:0001:1: received frame has no key status

1. The alsa default device is not set, so alsamixer, aplay, etc. cannot find output devices by default. However the list of hardware output devices given at the end of the output from $ shairport-sync -h was useful, as it could be used to specify the card to be used by alsamixer:

$shairport-sync -h
Usage: shairport-sync [options...]
  or:  shairport-sync [options...] -- [audio output-specific options]

Options:
    -h, --help              show this help.
...
...
...
    hardware output devices:
      "hw:Device"

thus:

$ alsamixer -D "hw:Device"

worked.