Huge latency

[mabrodeur]

Hi, I can start the server and everything is working fine but there is a big 10 seconds of latency from the time I press play on my iOS device and I can hear the sound from my Sonos speaker.

For listening to music it's not so bad (but you need to wait 10 seconds for the sound to stop when you press pause). But for watching a video it is simply unusable.

is there a way to make the the video in sync or it is how AirPlay / the protocol works?

Thanks

[philippe44]

Unfortunately, you can't sync video and audio due to the nature of such bridge (RTP to HTTP, it's asynchronous).

[edit]: about delay, you can always reduce the [http] value, it will start sooner, at the expense of potentially more rebuffering

[edit2]: you should not have to wait for the pause to be acted upon. It should be less than a sec, no matter what

[mabrodeur]

That makes total sense. Thanks Weird though that when I press pause it really takes a long time to actually pause the sound.

[philippe44]

Can you log that? I have an idea but would need to confirm

[mabrodeur]

Can you give me an example of command to get the log you want?

[philippe44]

airupnp-[your_platform] -l 1000:2000 -f [some_log_file]

[mabrodeur]

Well I tried it again and now the pause takes ~1 sec so I guess it is working fine. Here is the log anyway:

[16:22:15.908348] main:1176 Starting airupnp version: v0.1.3.1 (Dec  4 2017 @ 11:55:48)
[16:22:15.909939] Start:959 Binding to 192.168.0.106:49153
[16:22:30.015385] AddMRDevice:829 [0x100077530]: adding renderer (192.168.0.154 - Sonos CONNECT:AMP)
[16:22:30.042890] HandleStateEvent:309 [0x100077530]: UPnP Volume local change 46
[16:22:35.887272] rtsp_thread:284 got RTSP connection 11
[16:22:35.920004] handle_rtsp:328 [0x100112be0]: challenge DgXQbXHSLwN/F5CWXWErSg==
[16:22:35.932141] handle_rtsp:321 [0x100112be0]: received ANNOUNCE
[16:22:35.936142] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 2

[16:22:35.942498] handle_rtsp:321 [0x100112be0]: received SETUP
[16:22:35.942607] hairtunes_init:270 [0x102805000]: Using FLAC
[16:22:35.942835] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=49940;timing_port=64448;server_port=53200
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 3

[16:22:35.950515] handle_rtsp:321 [0x100112be0]: received RECORD
[16:22:35.950544] callback:202 [0x100077530]: Stream
[16:22:35.950575] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Latency: 44100
Audio-Jack-Status: connected; type=analog
CSeq: 4

[16:22:35.955590] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:22:35.955624] handle_rtsp:476 [0x100112be0]: SET PARAMETER volume -12.343430
[16:22:35.955645] CtrlSetVolume:246 uPNP volume 58 for http://192.168.0.154:1400/MediaRenderer/RenderingControl/Control (cookie 0x0)
[16:22:35.955762] callback:242 [0x100077530]: Volume[0..100] 58
[16:22:35.955800] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 5

[16:22:35.963718] rtp_thread_func:565 [0x102805000]: 1st sync packet received
[16:22:35.994255] rtp_thread_func:565 [0x102805000]: 1st sync packet received
[16:22:36.000820] handle_rtsp:321 [0x100112be0]: received FLUSH
[16:22:36.000840] hairtunes_flush:342 [0x102805000]: FLUSH ignored as seqno (38560) <= ab_read (0)
[16:22:36.000882] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[16:22:36.025498] buffer_put_packet:433 [0x102805000]: buffer fill status [level:65535] [W:38559 R:38560]
[16:22:36.055327] AVTSetURI:92 uPNP setURI http://192.168.0.106:62489/stream.flac for http://192.168.0.154:1400/MediaRenderer/AVTransport/Control (cookie 0x1)
[16:22:36.055645] AVTPlay:152 uPNP play for http://192.168.0.154:1400/MediaRenderer/AVTransport/Control (cookie 0x2)
[16:22:36.055689] CtrlSetVolume:246 uPNP volume 58 for http://192.168.0.154:1400/MediaRenderer/RenderingControl/Control (cookie 0x2)
[16:22:36.082350] http_thread_func:809 [0x102805000]: got HTTP connection 18 (silent frames 250)
[16:22:36.083192] handle_http:929 [0x102805000]: received GET
[16:22:36.083241] handle_http:938 [0x102805000]: responding:
HTTP/1.0 200 OK
Server: HairTunes
Connection: close
Content-Type: audio/flac

[16:22:36.087181] buffer_get_frame:753 [0x102805000]: buffer drain status [level:10] [W:38570 R:38560]
[16:22:36.250432] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:22:36.250572] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7

[16:22:36.281855] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:22:36.281925] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8

[16:22:36.304313] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:22:36.304388] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 9

[16:22:36.337684] CallbackActionHandler:381 [0x100077530]: uPNP playing
[16:22:36.360027] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:22:36.360100] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 10

[16:22:40.106837] buffer_put_packet:433 [0x102805000]: buffer fill status [level:3] [W:39071 R:39068]
[16:22:40.112279] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:39073 R:39072]
[16:22:40.984749] search_remote:539 [0x100112be0]: found ActiveRemote for 37B4532052AA0B7F at 192.168.0.143:60756
[16:22:44.216926] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:39583 R:39583]
[16:22:44.225025] buffer_get_frame:753 [0x102805000]: buffer drain status [level:4] [W:39588 R:39584]
[16:22:48.294076] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:40095 R:40095]
[16:22:48.297824] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:40097 R:40096]
[16:22:52.374236] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:40607 R:40607]
[16:22:52.383209] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:40609 R:40608]
[16:22:56.455343] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:41119 R:41119]
[16:22:56.464702] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:41121 R:41120]
[16:23:00.537526] buffer_put_packet:433 [0x102805000]: buffer fill status [level:3] [W:41631 R:41628]
[16:23:00.543220] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:41633 R:41632]
[16:23:04.644836] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:42143 R:42143]
[16:23:04.653585] buffer_get_frame:753 [0x102805000]: buffer drain status [level:4] [W:42148 R:42144]
[16:23:06.144146] handle_rtsp:321 [0x100112be0]: received SET_PARAMETER
[16:23:06.144195] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 25

[16:23:08.723836] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:42655 R:42655]
[16:23:08.727997] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:42657 R:42656]
[16:23:12.803933] buffer_put_packet:433 [0x102805000]: buffer fill status [level:0] [W:43167 R:43167]
[16:23:12.811512] buffer_get_frame:753 [0x102805000]: buffer drain status [level:1] [W:43169 R:43168]
[16:23:13.105908] handle_rtsp:321 [0x100112be0]: received TEARDOWN
[16:23:13.111584] http_thread_func:886 [0x102805000]: terminating
[16:23:13.125459] rtp_thread_func:643 [0x102805000]: terminating
[16:23:13.125701] callback:207 [0x100077530]: Stop
[16:23:13.125715] AVTStop:218 uPNP stop for http://192.168.0.154:1400/MediaRenderer/AVTransport/Control (cookie 0x70)
[16:23:13.125812] handle_rtsp:492 [0x100112be0]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 30

[16:23:13.135300] rtsp_thread:299 RTSP close 11
[16:23:13.398447] CallbackActionHandler:377 [0x100077530]: uPNP stopped
exit
[16:23:22.629307] main:1267 stopping squeelite devices ...
[16:23:22.629322] main:1268 stopping UPnP devices ...
[16:23:22.629326] Stop:992 terminate search thread ...
[16:23:22.629329] Stop:995 flush renderers ...
[16:23:22.732396] Stop:998 terminate main thread ...
[16:23:23.945743] main:1270 all done

[philippe44]

If it happens again, don't hesitate to take a log and send it to me. I know there is a case where the "flush" (=stop) request is ignored (and in that case the stop/pause will only happen once the Sonos internal buffer is empty), but I've not been able so far to reproduce it and identify the reason why

[Ninalexa]

Hi, I also have a significant audio/video delay. You said that this could be improved by "reducing the [http] value". Could you please help explain the steps how that can be done (and possibly undone if it makes things worse)? My question probably reveals that I have no idea how I managed to install this airconnect...but it was thanks to your really good instructions and posts that it finally works now!

[philippe44]

it's the option on the command line -l [rtp]:[http]. You can set it to -l 250:500 and see

[Ninalexa]

Thanks for your quick reply. One more (dumb) question then. How do I 'set' that, I just type "-l 250:500" in the terminal (which doesn't seem to do anything)?

[philippe44]

How do you launch the application? In a terminal, you should just type "./airupnp-[your OS] -l 250:500"

[mrtropicguy]

I think I am experiencing this same issue with the current version of AirConnect. The first song I play always start immediately, but it will take about 10 seconds when I skip a track until I begin hearing the next track. Also the audio at the beginning of the track is missed and the song will be about 5 to 6 seconds past the beginning. When I actually start hearing audio I see this in the log.

HTTP/1.0 200 OK Server: HairTunes Content-Type: audio/flac Connection: close

Are there any logs I could provide to help track down this issue?

[philippe44]

Where are you streaming to and from?

[mrtropicguy]

I was using Airplay to stream from an iPhone to a Sonos Play:1 speaker.

[Maercle]

I have changed in the airconnect.service file on my raspberry 3+ the line with 1000:2000 to 250:500. But there is no effect before the change it takes 4 seconds and after the change it takes 4 seconds until the music starts. I use an iPhone and a Sonos Play1. Have I done somesthing wrong?