iOS Dropouts: Error in Action Callback?

[Wawsax]

Hello. I've started having trouble streaming to my Sonos Play:1. Can connect and start playing, but it disconnects usually within about a minute or less. Did something change?

Seems to have started about the time I updated my phone to iOS 13. Tested with my iPad, which is still on iOS 12, and had the exact same problem, though. So I really have no idea why I'm suddenly not able to hold a connection.

Pasted the log for the error below, please let me know if you require any more info. My config settings haven't changed, but I pasted them below too. I pulled the latest from git as I noticed you made some changes recently, but still getting this error. Using the aarch64 binary.

[20:07:02.093322] handle_rtsp:392 [0xffff78003180]: received SET_PARAMETER
[20:07:02.093570] handle_rtsp:557 [0xffff78003180]: SET PARAMETER volume -25.775602
[20:07:02.099039] CtrlSetVolume:282 [0x48f0a0]: uPNP volume 14 (cookie 0x22)
[20:07:02.099625] callback:375 [0x48f0a0]: Volume[0..100] 14:8
[20:07:02.099829] handle_rtsp:589 [0xffff78003180]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 29

[20:07:04.786972] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:39808 R:39808]
[20:07:04.787595] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:0 gap:969] [W:39808 R:39808] [R:0 S:0 F:0]
[20:07:08.869324] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:4] [W:40320 R:40317]
[20:07:08.871146] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:1 gap:972] [W:40321 R:40320] [R:0 S:0 F:0]
[20:07:12.977891] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:40832 R:40832]
[20:07:12.987197] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:4 gap:942] [W:40836 R:40832] [R:0 S:0 F:0]
[20:07:17.056910] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:41344 R:41344]
[20:07:17.071039] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:1 gap:945] [W:41345 R:41344] [R:0 S:0 F:0]
[20:07:21.137088] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:41856 R:41856]
[20:07:21.152019] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:1 gap:951] [W:41857 R:41856] [R:0 S:0 F:0]
[20:07:25.219058] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:4] [W:42368 R:42365]
[20:07:25.233296] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:1 gap:956] [W:42369 R:42368] [R:0 S:0 F:0]
[20:07:29.327925] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:42880 R:42880]
[20:07:29.329282] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:2 gap:947] [W:42882 R:42880] [R:0 S:0 F:0]
[20:07:33.407270] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:1] [W:43392 R:43392]
[20:07:33.407881] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:0 gap:955] [W:43392 R:43392] [R:0 S:0 F:0]
[20:07:37.401198] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:4] [W:43904 R:43901]
[20:07:37.404176] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:5 gap:1046] [W:43909 R:43904] [R:0 S:0 F:0]
[20:07:41.481367] buffer_put_packet:614 [0xffff5c01aca0]: fill [level:4] [W:44416 R:44413]
[20:07:41.485089] _buffer_get_frame:954 [0xffff5c01aca0]: drain [level:6 gap:1052] [W:44422 R:44416] [R:0 S:0 F:0]
[20:07:48.421068] ActionHandler:535 Error in action callback -- -204 (cookie 0x68)
[20:07:48.421841] ActionHandler:535 Error in action callback -- -204 (cookie 0x67)
[20:07:49.006186] MasterHandler:623 [0x48f0a0]: Auto-renewal failed, re-subscribing
[20:07:49.624264] ActionHandler:535 Error in action callback -- -204 (cookie 0x69)
[20:07:49.924500] ActionHandler:535 Error in action callback -- -204 (cookie 0x6a)
[20:07:50.425295] ActionHandler:535 Error in action callback -- -204 (cookie 0x6b)
[20:07:51.426083] ActionHandler:535 Error in action callback -- -204 (cookie 0x6d)
[20:07:51.426316] ActionHandler:535 Error in action callback -- -204 (cookie 0x6c)
[20:07:52.427655] ActionHandler:535 Error in action callback -- -204 (cookie 0x6e)
[20:07:52.928415] ActionHandler:535 Error in action callback -- -204 (cookie 0x6f)
[20:07:53.425976] ActionHandler:535 Error in action callback -- -204 (cookie 0x70)
[20:07:54.011765] MasterHandler:648 [0x48f0a0]: subscribe fail, re-trying 1
[20:07:54.012533] MasterHandler:648 [0x48f0a0]: subscribe fail, re-trying 2
[20:07:54.013046] MasterHandler:648 [0x48f0a0]: subscribe fail, re-trying 3
[20:07:54.013405] MasterHandler:652 [0x48f0a0]: subscribe fail, volume feedback will not work
[20:07:54.429395] ActionHandler:535 Error in action callback -- -204 (cookie 0x71)
[20:07:54.429742] ActionHandler:535 Error in action callback -- -204 (cookie 0x72)
[20:07:55.430531] ActionHandler:535 Error in action callback -- -204 (cookie 0x73)
[20:07:55.931051] ActionHandler:535 Error in action callback -- -204 (cookie 0x74)
[20:07:56.427314] ActionHandler:535 Error in action callback -- -204 (cookie 0x75)
[20:08:04.000221] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:08:04.031049] http_thread_func:1210 [0xffff5c01aca0]: terminating
[20:08:04.035258] rtp_thread_func:819 [0xffff5c01aca0]: terminating
[20:08:24.477206] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:08:24.482025] MasterHandler:646 [0x48f0a0]: subscribe success
[20:08:24.491596] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:08:44.002555] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:08:44.123448] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:08:44.127954] MasterHandler:646 [0x48f0a0]: subscribe success
[20:08:44.138180] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:09:04.002547] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:09:04.251881] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:09:04.254641] MasterHandler:646 [0x48f0a0]: subscribe success
[20:09:04.266449] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:09:24.002896] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:09:24.482902] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:09:24.485848] MasterHandler:646 [0x48f0a0]: subscribe success
[20:09:24.497291] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:09:44.002621] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:09:44.492661] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:09:44.494933] MasterHandler:646 [0x48f0a0]: subscribe success
[20:09:44.506666] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:10:04.002454] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:10:04.500503] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:10:04.504841] MasterHandler:646 [0x48f0a0]: subscribe success
[20:10:04.514612] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:10:24.002466] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:10:24.315882] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:10:24.318665] MasterHandler:646 [0x48f0a0]: subscribe success
[20:10:24.330179] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:10:44.002835] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:10:44.467929] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:10:44.470838] MasterHandler:646 [0x48f0a0]: subscribe success
[20:10:44.482247] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)
[20:11:04.002441] UpdateThread:711 [0x48f0a0]: removing unresponsive player (Sonos)
[20:11:04.396617] AddMRDevice:978 [0x48f0a0]: adding renderer (Bedroom)
[20:11:04.399453] MasterHandler:646 [0x48f0a0]: subscribe success
[20:11:04.410847] ProcessEvent:445 [0x48f0a0]: UPnP Volume local change 14:14 (master)

<?xml version="1.0"?>
<airupnp>
<common>
<protocolInfo>
<pcm>http-get:*:audio/L16;rate=44100;channels=2:DLNA.ORG_PN=LPCM;DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d50000000$
<wav>http-get:*:audio/wav:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d500000000000000000000000000000</wav>
<flac>http-get:*:audio/flac:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d500000000000000000000000000000</flac>
<mp3>http-get:*:audio/mp3:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d500000000000000000000000000000</mp3>
</protocolInfo>
<enabled>1</enabled>
<max_volume>100</max_volume>
<codec>flc</codec>
<metadata>1</metadata>
<artwork></artwork>
<latency>1000:2000</latency>
<drift>0</drift>
</common>
<main_log>info</main_log>
<upnp_log>info</upnp_log>
<util_log>warn</util_log>
<raop_log>info</raop_log>
<log_limit>-1</log_limit>
<device>
<udn>uuid:RINCON_7828CA314B0801400</udn>
<name>Sonos</name>
<mac>bb:bb:ca:31:4b:08</mac>
<enabled>1</enabled>
</device>
</airupnp>

[philippe44]

The devices are disconnected so it looks like something network related. Usually it’s a router discarding multicast packets or doing IGMP snooping

[Wawsax]

Hmm. I didn't change any network settings though, and it was working fine before. Unfortunately, I don't know much of anything about networking. Maybe a bit out of place asking this here, but do you have any tips on how I could debug or figure this out?

I'm using Advanced Tomato on my router (Netgear R7000) and Armbian (Debian Stretch) on my Odroid C2. I'm also using this Armbian system as a DNS server through PiHole, maybe that's causing a problem? I tried turning on an option called 'Enable IGMPproxy' in Tomato, but it didn't seem to do anything. Any help you can offer is very much appreciated!

[philippe44]

it's probably around the IGMPProxy which should be off in fact

[Wawsax]

I only briefly enabled it for testing after you mentioned IGMP. AirUPNP was working before without dropouts and my network settings haven't changed, plus regular Airplay through an AirPort Express works fine. I have no idea how to debug this, so I'm just going to close it.