Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Starting and stopping playback takes very long time to start #79

Closed
tariktokic opened this issue Sep 2, 2023 · 43 comments
Closed

Starting and stopping playback takes very long time to start #79

tariktokic opened this issue Sep 2, 2023 · 43 comments
Assignees
Labels
airconnect-bug Bug in the Airconnect binaries aircast and/or airupnp bug Something isn't working dsm7 DSM7 related issues work-in-progress Issue will not be stale

Comments

@tariktokic
Copy link

tariktokic commented Sep 2, 2023

Describe the bug

After selecting the SONOS Play 1 box in Apple Music and starting the playback it takes between 15-20 seconds until the music starts or stops.

To Reproduce

  1. Select SONOS player in the Apple Music App
  2. Play music

Expected behavior

The playback should start or stop at least 2-5 seconds later

Hardware

Device on which you are running AirConnect-Synology):

  • Synology NAS or Router model name: DS716+II
  • DSM Version: DSM 7.1.1-42962 Update 6

Package

Which package from the releases page have you downloaded):

  • package name: AirConnect-dsm7-x86_64-1.1.7-20230815.spk

Thank you for the good work!

@tariktokic tariktokic added the bug Something isn't working label Sep 2, 2023
@tariktokic tariktokic changed the title Playback takes very long time to start Starting and stopping playback takes very long time to start Sep 2, 2023
@eizedev eizedev added dsm7 DSM7 related issues airconnect-bug Bug in the Airconnect binaries aircast and/or airupnp labels Sep 5, 2023
@eizedev
Copy link
Owner

eizedev commented Sep 5, 2023

Hi @tariktokic

Thanks for filling out the issue template.

I could replicate your problem with your given information with latest airconnect version playing any song from Apple Music to my Sonos Play:1.
Also if i press the pause button, it also takes a few seconds until the music pauses.

This could be related to a problem with the latency config for airupnp. This could be tested using the command line arguments or the config file: https://github.com/eizedev/AirConnect-Synology#configuration

I will also check this in the next days, i am currently not able to access my NAS.

If you have time to test, could you please play a track from Apple Music on your Play:1, let it run a few seconds and then pause again and then upload the part from the airconnect.log here? If in doubt, clear the log shortly before. Thanks.

Also, it could be related to an old problem using default flac codec. Sonos has changed something in newer firmware versions. Before 15.3 it could help to change codec from flac to wav in den config file (see readme for info how to do this).
See also: philippe44/AirConnect#458
After 15.3, until now, it was working again. I am now on 15.7.

@eizedev
Copy link
Owner

eizedev commented Oct 1, 2023

Hi @tariktokic I have release the latest version of AirConnect in the Release. On my synology models, the problem still exists in the latest version.

I still have 2-3 ideas that I want to test (f.e. Change from flac to mp3), otherwise I'll open an issue with the AirConnect developer about it.
The problem can also be related to a Sonos Update, which Sonos Version are you running? 15.8?

@eizedev eizedev pinned this issue Oct 1, 2023
@Gandulf78
Copy link

Gandulf78 commented Oct 24, 2023

Hi @eizedev
I've got the same issue here. The Sonos Version is 15.9.
I believe the issue is also present with docker version of AirConnect (1activegeek/airconnect) where I just switched from.

@5trobl
Copy link
Contributor

5trobl commented Oct 30, 2023

Hi @eizedev

I've got the same (or related) issue for years actually.

Playback delay is ~10 sec, but stopping and volume control are immediate!

DS218+ with DSM 7.1.1-42962 Update 6
AirConnect version 1.1.7-20230815
Sonos iOS App v. 15.9
Sonos OS S2 v. 15.9 (Build 75146030)

I already touched the AIRUPNP_LATENCY="250:500" in the *conf with no effect -- I think it's not even being read, see log file below. Btw /volume1/airconnect/airconnect.conf exists but /volume1/airconnect/config.xml does not! The last time I got this line

2023-09-20T06:31:36+02:00 weg18 [10:59:55] Setting AIRUPNP_LATENCY="1000:2000" n "/volume1/@appstore/AirConnect/airconnect.conf"

was one month ago. Perhaps as a consequence of editing the *conf file?

In any case, the symptoms (~10 sec playback delay) are the same for years.
I will reinstall and reset the folders soon. Btw it's ok that the 1-year-old .log file is size 11G?

Log text since airconnect starts:

2023-10-30T13:43:01+01:00 weg18 [13:43:01] Starting AirConnect ...
2023-10-30T13:43:01+01:00 weg18 [13:43:01] Linking airconnect configuration to "/volume1/airconnect/airconnect.conf".
2023-10-30T13:43:01+01:00 weg18 [13:43:01] Linking airupnp configuration to "/volume1/airconnect/config.xml".
2023-10-30T13:43:01+01:00 weg18 [13:43:01] Starting airupnp on 192.168.178.100:49154
2023-10-30T13:43:01+01:00 weg18 [13:43:01.298205] main:1367 Starting airupnp version: v1.1.7 (May 20 2023 @ 06:12:02)
2023-10-30T13:43:01+01:00 weg18 [13:43:01.298311] main:1374 no config file, using defaults
2023-10-30T13:43:01+01:00 weg18 [13:43:01.300472] Start:1086 Binding to iface eth0@192.168.178.100:49154
2023-10-30T13:43:01+01:00 weg18 [13:43:01.303340] bind_socket:636 socket binding 7 on port 32811
2023-10-30T13:43:01+01:00 weg18 [13:43:01.303434] Start:1125 Starting pico HTTP server on port 32811
2023-10-30T13:43:01+01:00 weg18 [13:43:01] AirConnect successfully started on ip "192.168.178.100"!
2023-10-30T13:43:02+01:00 weg18 [13:43:01.654697] AddMRDevice:1012 [0x7f04a0dd5010]: adding renderer (Esszimmer) with mac BBBB38355637
2023-10-30T13:43:02+01:00 weg18 [13:43:01.654862] bind_socket:636 socket binding 12 on port 59489
2023-10-30T13:43:02+01:00 weg18 [13:43:01.685180] MasterHandler:643 [0x7f04a0dd5010]: subscribe success
2023-10-30T13:43:02+01:00 weg18 [13:43:01.738348] ProcessEvent:448 [0x7f04a0dd5010]: UPnP Volume local change 34:34 (master)
2023-10-30T13:43:14+01:00 weg18 [13:43:13.557269] rtsp_thread:338 got RTSP connection 13
2023-10-30T13:43:14+01:00 weg18 [13:43:13.623229] handle_rtsp:385 [0x7f048800bae0]: challenge sM847wRrISh1l+VW/8jIdQ==
2023-10-30T13:43:14+01:00 weg18 [13:43:13.633093] handle_rtsp:379 [0x7f048800bae0]: received ANNOUNCE
2023-10-30T13:43:14+01:00 weg18 [13:43:13.639056] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 4
2023-10-30T13:43:14+01:00 weg18 [13:43:13.644046] handle_rtsp:379 [0x7f048800bae0]: received SETUP
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645435] bind_socket:636 socket binding 15 on port 57494
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645512] raopst_init:378 [0x7f0474006d60]: UDP port-0 57494
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645537] bind_socket:636 socket binding 16 on port 40928
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645554] raopst_init:378 [0x7f0474006d60]: UDP port-1 40928
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645575] bind_socket:636 socket binding 17 on port 51728
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645591] raopst_init:378 [0x7f0474006d60]: UDP port-2 51728
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645617] bind_socket:636 socket binding 18 on port 59244
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645639] raopst_init:396 [0x7f0474006d60]: HTTP listening port 59244
2023-10-30T13:43:14+01:00 weg18 [13:43:13.645819] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Transport: RTP/AVP/UDP;unicast;mode=record;control_port=40928;timing_port=51728;server_port=57494
2023-10-30T13:43:14+01:00 weg18 Session: DEADBEEF
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 5
2023-10-30T13:43:14+01:00 weg18 [13:43:13.653370] handle_rtsp:379 [0x7f048800bae0]: received RECORD
2023-10-30T13:43:14+01:00 weg18 [13:43:13.653410] raopst_record:502 [0x7f0474006d60]: record 0 0
2023-10-30T13:43:14+01:00 weg18 [13:43:13.653427] HandleRAOP:291 [0x7f04a0dd5010]: Stream
2023-10-30T13:43:14+01:00 weg18 [13:43:13.653462] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Audio-Latency: 11025
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 6
2023-10-30T13:43:14+01:00 weg18 [13:43:13.658258] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:14+01:00 weg18 [13:43:13.658286] handle_rtsp:546 [0x7f048800bae0]: SET PARAMETER volume -20.000000
2023-10-30T13:43:14+01:00 weg18 [13:43:13.658311] CtrlSetVolume:232 [0x7f04a0dd5010]: uPNP volume 33 (cookie (nil))
2023-10-30T13:43:14+01:00 weg18 [13:43:13.658515] HandleRAOP:368 [0x7f04a0dd5010]: Volume[0..100] 33:34
2023-10-30T13:43:14+01:00 weg18 [13:43:13.658549] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 7
2023-10-30T13:43:14+01:00 weg18 [13:43:13.665759] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:14+01:00 weg18 [13:43:13.665783] handle_rtsp:546 [0x7f048800bae0]: SET PARAMETER volume -20.000000
2023-10-30T13:43:14+01:00 weg18 [13:43:13.665803] CtrlSetVolume:232 [0x7f04a0dd5010]: uPNP volume 34 (cookie 0x1)
2023-10-30T13:43:14+01:00 weg18 [13:43:13.666007] HandleRAOP:368 [0x7f04a0dd5010]: Volume[0..100] 33:33
2023-10-30T13:43:14+01:00 weg18 [13:43:13.666045] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 8
2023-10-30T13:43:14+01:00 weg18 [13:43:13.690219] flac_init:195 [0x7f0474006d60]: Using FLAC-0 (0x7f0468000b20)
2023-10-30T13:43:14+01:00 weg18 [13:43:13.690344] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:12164 R:12164]
2023-10-30T13:43:14+01:00 weg18 [13:43:13.691344] handle_rtsp:379 [0x7f048800bae0]: received FLUSH
2023-10-30T13:43:14+01:00 weg18 [13:43:13.691408] raopst_flush:470 [0x7f0474006d60]: FLUSH ignored as same as RECORD (12164 - 1995369444)
2023-10-30T13:43:14+01:00 weg18 [13:43:13.691424] raopst_flush:486 [0x7f0474006d60]: flush 12164 1995369444
2023-10-30T13:43:14+01:00 weg18 [13:43:13.691459] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:14+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:14+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:14+01:00 weg18 CSeq: 9
2023-10-30T13:43:15+01:00 weg18 [13:43:14.466980] search_remote_cb:636 [0x7f048800bae0]: found ActiveRemote for B4916A78DA32BC30 at 192.168.178.163:62504
2023-10-30T13:43:16+01:00 weg18 [13:43:15.701657] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:16+01:00 weg18 [13:43:15.701824] http_pico_add_source:747 source /0.jpg added
2023-10-30T13:43:16+01:00 weg18 [13:43:15.701843] handle_rtsp:573 [0x7f048800bae0]: received JPEG image of 96926 bytes
2023-10-30T13:43:16+01:00 weg18 [13:43:15.701881] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:16+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:16+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:16+01:00 weg18 CSeq: 10
2023-10-30T13:43:16+01:00 weg18 [13:43:15.712441] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:16+01:00 weg18 [13:43:15.712478] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:16+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:16+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:16+01:00 weg18 CSeq: 12
2023-10-30T13:43:16+01:00 weg18 [13:43:15.717042] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:16+01:00 weg18 [13:43:15.717077] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:16+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:16+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:16+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:16+01:00 weg18 [13:43:15.717103] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:16+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:16+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:16+01:00 weg18 CSeq: 13
2023-10-30T13:43:17+01:00 weg18 [13:43:16.500913] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:17+01:00 weg18 [13:43:16.500983] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:17+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:17+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:17+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:17+01:00 weg18 [13:43:16.501027] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:17+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:17+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:17+01:00 weg18 CSeq: 14
2023-10-30T13:43:17+01:00 weg18 [13:43:16.507146] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:17+01:00 weg18 [13:43:16.507179] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:17+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:17+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:17+01:00 weg18 CSeq: 15
2023-10-30T13:43:17+01:00 weg18 [13:43:16.596238] AVTSetURI:78 [0x7f04a0dd5010]: uPNP setURI http://192.168.178.100:59244/stream-0.flc (cookie 0x2)
2023-10-30T13:43:17+01:00 weg18 [13:43:16.596483] AVTPlay:138 [0x7f04a0dd5010]: uPNP play (cookie 0x3)
2023-10-30T13:43:17+01:00 weg18 [13:43:16.678119] http_thread_func:1060 [0x7f0474006d60]: got HTTP connection 19 (silent frames 0)
2023-10-30T13:43:17+01:00 weg18 [13:43:16.688549] handle_http:1236 [0x7f0474006d60]: received GET HTTP/1.1
2023-10-30T13:43:17+01:00 weg18 CONNECTION: close
2023-10-30T13:43:17+01:00 weg18 Host: 192.168.178.100:59244
2023-10-30T13:43:17+01:00 weg18 ACCEPT: */*
2023-10-30T13:43:17+01:00 weg18 USER-AGENT: Linux UPnP/1.0 Sonos/75.1-46030 (ZPS1)
2023-10-30T13:43:17+01:00 weg18 X-Sonos-SWGen: 2
2023-10-30T13:43:17+01:00 weg18 X-Sonos-Firmware: 75.1-46030
2023-10-30T13:43:17+01:00 weg18 X-Sonos-Muse-Api: 1.36.0
2023-10-30T13:43:17+01:00 weg18 X-Sonos-Id-Hash: FFBkYHzoAAAufz3EUU8owJt7QtS8GtrnVLkDPzbaA1I=
2023-10-30T13:43:17+01:00 weg18 [13:43:16.688584] handle_http:1281 [0x7f0474006d60]: responding: HTTP/1.0 200 OK
2023-10-30T13:43:17+01:00 weg18 Server: HairTunes
2023-10-30T13:43:17+01:00 weg18 Content-Type: audio/flac
2023-10-30T13:43:17+01:00 weg18 Connection: close
2023-10-30T13:43:17+01:00 weg18 [13:43:16.688603] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:374 gap:-2731] [W:12538 R:12164] [R:0 S:0 F:0]
2023-10-30T13:43:18+01:00 weg18 [13:43:17.591531] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:18+01:00 weg18 [13:43:17.591713] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:18+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:18+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:18+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:18+01:00 weg18 [13:43:17.591752] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:18+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:18+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:18+01:00 weg18 CSeq: 16
2023-10-30T13:43:18+01:00 weg18 [13:43:17.598289] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:18+01:00 weg18 [13:43:17.598324] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:18+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:18+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:18+01:00 weg18 CSeq: 17
2023-10-30T13:43:18+01:00 weg18 [13:43:17.776929] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:12676 R:12676]
2023-10-30T13:43:18+01:00 weg18 [13:43:17.786148] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:257] [W:12677 R:12676] [R:0 S:0 F:0]
2023-10-30T13:43:22+01:00 weg18 [13:43:21.682664] ActionHandler:511 [0x7f04a0dd5010]: uPNP transition
2023-10-30T13:43:22+01:00 weg18 [13:43:21.863858] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:13188 R:13188]
2023-10-30T13:43:22+01:00 weg18 [13:43:21.868398] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:261] [W:13189 R:13188] [R:0 S:0 F:0]
2023-10-30T13:43:26+01:00 weg18 [13:43:25.951630] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:13700 R:13700]
2023-10-30T13:43:26+01:00 weg18 [13:43:25.965871] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:253] [W:13701 R:13700] [R:0 S:0 F:0]
2023-10-30T13:43:29+01:00 weg18 [13:43:28.430197] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:29+01:00 weg18 [13:43:28.430264] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:29+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:29+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:29+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:29+01:00 weg18 [13:43:28.430314] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:29+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:29+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:29+01:00 weg18 CSeq: 24
2023-10-30T13:43:29+01:00 weg18 [13:43:28.440266] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:29+01:00 weg18 [13:43:28.440299] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:29+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:29+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:29+01:00 weg18 CSeq: 25
2023-10-30T13:43:29+01:00 weg18 [13:43:28.578605] http_thread_func:1196 [0x7f0474006d60]: spent 2081 ms in send for 2677 bytes (sent 2677)!
2023-10-30T13:43:29+01:00 weg18 [13:43:28.694858] http_thread_func:1196 [0x7f0474006d60]: spent 113 ms in send for 2472 bytes (sent 2472)!
2023-10-30T13:43:29+01:00 weg18 [13:43:28.743557] ActionHandler:520 [0x7f04a0dd5010]: uPNP playing
2023-10-30T13:43:30+01:00 weg18 [13:43:30.037521] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:14212 R:14212]
2023-10-30T13:43:30+01:00 weg18 [13:43:30.047794] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:256] [W:14213 R:14212] [R:0 S:0 F:0]
2023-10-30T13:43:34+01:00 weg18 [13:43:34.124296] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:14724 R:14724]
2023-10-30T13:43:34+01:00 weg18 [13:43:34.132217] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:258] [W:14725 R:14724] [R:0 S:0 F:0]
2023-10-30T13:43:38+01:00 weg18 [13:43:38.210970] buffer_put_packet:620 [0x7f0474006d60]: fill [level:1] [W:15236 R:15236]
2023-10-30T13:43:38+01:00 weg18 [13:43:38.214029] _buffer_get_frame:959 [0x7f0474006d60]: drain [level:1 gap:243] [W:15237 R:15236] [R:0 S:0 F:0]
2023-10-30T13:43:39+01:00 weg18 [13:43:39.010712] handle_rtsp:379 [0x7f048800bae0]: received FLUSH
2023-10-30T13:43:39+01:00 weg18 [13:43:39.010815] raopst_flush:486 [0x7f0474006d60]: flush 15334 1996491116
2023-10-30T13:43:39+01:00 weg18 [13:43:39.010834] HandleRAOP:305 [0x7f04a0dd5010]: Flush
2023-10-30T13:43:39+01:00 weg18 [13:43:39.010851] AVTStop:204 [0x7f04a0dd5010]: uPNP stop (cookie 0x22)
2023-10-30T13:43:39+01:00 weg18 [13:43:39.010956] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:39+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:39+01:00 weg18 CSeq: 31
2023-10-30T13:43:39+01:00 weg18 [13:43:39.011085] rtp_thread_func:738 [0x7f0474006d60]: 1st sync packet received
2023-10-30T13:43:39+01:00 weg18 [13:43:39.024643] flac_init:195 [0x7f0474006d60]: Using FLAC-0 (0x7f0468004fa0)
2023-10-30T13:43:39+01:00 weg18 [13:43:39.026660] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:39+01:00 weg18 [13:43:39.026780] http_pico_add_source:747 source /d7445e5a.jpg added
2023-10-30T13:43:39+01:00 weg18 [13:43:39.026799] handle_rtsp:573 [0x7f048800bae0]: received JPEG image of 96926 bytes
2023-10-30T13:43:39+01:00 weg18 [13:43:39.026832] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:39+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:39+01:00 weg18 CSeq: 32
2023-10-30T13:43:39+01:00 weg18 [13:43:39.032090] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:39+01:00 weg18 [13:43:39.032131] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:39+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:39+01:00 weg18 CSeq: 33
2023-10-30T13:43:39+01:00 weg18 [13:43:39.036641] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:39+01:00 weg18 [13:43:39.036668] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:39+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:39+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:39+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:39+01:00 weg18 [13:43:39.036707] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:39+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:39+01:00 weg18 CSeq: 34
2023-10-30T13:43:39+01:00 weg18 [13:43:39.038516] http_read_line:1027 fd: 19 read error: Connection reset by peer
2023-10-30T13:43:39+01:00 weg18 [13:43:39.038535] http_parse_simple:950 cannot read method
2023-10-30T13:43:39+01:00 weg18 [13:43:39.038567] http_thread_func:1079 HTTP close 19
2023-10-30T13:43:39+01:00 weg18 [13:43:39.038599] http_thread_func:1060 [0x7f0474006d60]: got HTTP connection 19 (silent frames 59)
2023-10-30T13:43:39+01:00 weg18 [13:43:39.039302] handle_http:1236 [0x7f0474006d60]: received HEAD HTTP/1.1
2023-10-30T13:43:39+01:00 weg18 CONNECTION: close
2023-10-30T13:43:39+01:00 weg18 Host: 192.168.178.100:59244
2023-10-30T13:43:39+01:00 weg18 USER-AGENT: Linux UPnP/1.0 Sonos/75.1-46030 (ZPS1)
2023-10-30T13:43:39+01:00 weg18 X-Sonos-SWGen: 2
2023-10-30T13:43:39+01:00 weg18 X-Sonos-Firmware: 75.1-46030
2023-10-30T13:43:39+01:00 weg18 X-Sonos-Muse-Api: 1.36.0
2023-10-30T13:43:39+01:00 weg18 X-Sonos-Id-Hash: FFBkYHzoAAAufz3EUU8owJt7QtS8GtrnVLkDPzbaA1I=
2023-10-30T13:43:39+01:00 weg18 [13:43:39.039334] handle_http:1281 [0x7f0474006d60]: responding: HTTP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Server: HairTunes
2023-10-30T13:43:39+01:00 weg18 Content-Type: audio/flac
2023-10-30T13:43:39+01:00 weg18 Connection: close
2023-10-30T13:43:39+01:00 weg18 [13:43:39.039361] http_thread_func:1079 HTTP close 19
2023-10-30T13:43:39+01:00 weg18 [13:43:39.046996] handle_rtsp:379 [0x7f048800bae0]: received SET_PARAMETER
2023-10-30T13:43:39+01:00 weg18 [13:43:39.047020] handle_rtsp:564 [0x7f048800bae0]: received metadata
2023-10-30T13:43:39+01:00 weg18 	artist: DJ Snake & J Balvin
2023-10-30T13:43:39+01:00 weg18 	album:  Loco Contigo (feat. Tyga) - Single
2023-10-30T13:43:39+01:00 weg18 	title:  Loco Contigo (feat. Tyga)
2023-10-30T13:43:39+01:00 weg18 [13:43:39.047046] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:39+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:39+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:39+01:00 weg18 CSeq: 35
2023-10-30T13:43:39+01:00 weg18 [13:43:39.196235] ActionHandler:516 [0x7f04a0dd5010]: uPNP stopped
2023-10-30T13:43:42+01:00 weg18 [13:43:42.297233] buffer_put_packet:620 [0x7f0474006d60]: fill [level:413] [W:15748 R:15336]
2023-10-30T13:43:46+01:00 weg18 [13:43:46.142405] handle_rtsp:379 [0x7f048800bae0]: received TEARDOWN
2023-10-30T13:43:46+01:00 weg18 [13:43:46.142475] HandleRAOP:296 [0x7f04a0dd5010]: Stop
2023-10-30T13:43:46+01:00 weg18 [13:43:46.148895] http_thread_func:1217 [0x7f0474006d60]: terminating
2023-10-30T13:43:46+01:00 weg18 [13:43:46.191418] rtp_thread_func:827 [0x7f0474006d60]: terminating
2023-10-30T13:43:46+01:00 weg18 [13:43:46.192143] handle_rtsp:592 [0x7f048800bae0]: responding:
2023-10-30T13:43:46+01:00 weg18 RTSP/1.0 200 OK
2023-10-30T13:43:46+01:00 weg18 Audio-Jack-Status: connected; type=analog
2023-10-30T13:43:46+01:00 weg18 CSeq: 40
2023-10-30T13:43:46+01:00 weg18 [13:43:46.205513] http_read_line:1032 disconnected on the other end 13
2023-10-30T13:43:46+01:00 weg18 [13:43:46.205545] rtsp_thread:353 RTSP close 13

Thank you!!

@eizedev
Copy link
Owner

eizedev commented Oct 30, 2023

Thank you for your feedback. Next weekend I'll find some time to take a closer look, at the moment I'm quite busy in my spare time.

@huleiEthan
Copy link

same issue

@eizedev
Copy link
Owner

eizedev commented Nov 19, 2023

We are expecting our child in the next 2-3 weeks, so unfortunately I don't have the time at the moment, even if I had planned to :-).

Sorry it's taking so long.
Maybe it will work for me in the next few days.

I'm pretty sure it's not the Synology package, we'll have to ask philippe44 if he has any ideas.

@5trobl
Copy link
Contributor

5trobl commented Nov 22, 2023

We are expecting our child in the next 2-3 weeks

Congratulations and our best wishes!

@eizedev
Copy link
Owner

eizedev commented Nov 30, 2023

Our child was born last weekend. Personally, it will be a while before I have time to look at it again :)
If there is anyone here in the community who would like to help, you are welcome to submit a pull request (or open an issue in the AirConnect repository with philipp44 with reference to this issue). I'll definitely take a look at it when I get the chance.

@Gandulf78
Copy link

Gandulf78 commented Nov 30, 2023 via email

Copy link

github-actions bot commented Jan 1, 2024

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@eizedev eizedev added work-in-progress Issue will not be stale and removed no-issue-activity labels Jan 1, 2024
@eizedev
Copy link
Owner

eizedev commented Jan 14, 2024

i have released a new version (PRE-release) with latest AirConnect binaries and a lot of fixes for airupnp.
Could someone please test it and give me feedback if the package works and/or if the problem still exists? https://github.com/eizedev/AirConnect-Synology/releases/tag/1.6.3-20240114

The pre-release version should basically work, but is not yet finalized as I would like it to be. However, the content of the package and the logic should not have changed.

Thanks!


@5trobl
Thank you for your feedback. I'll have a look at the log file size issue. The log file should actually be deleted when updating to a new package if it has more than 50MB. This is probably a logic error in my code .

I will also look into the problem with the config file not being recognized correctly. If you have time, please check whether uninstalling the package and then reinstalling it might solve the problem. All directories and files should be deleted and overwritten with the latest ones from the newest package that you install.


The file /volume1/airconnect/config.xml is the configuration file for airupnp, by default it does not exist until you create it. Please check: https://github.com/eizedev/AirConnect-Synology#airupnp-and-aircast-configuration.

Example for creating airupnp config file, change ip to your needs (will be fixed in README, found a typo): /volume1/@appstore/AirConnect/airupnp -b 192.168.1.249:49154 -l 1000:2000 -i "/volume1/@appstore/AirConnect/config.xml" -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -z -f "/volume1/@appstore/AirConnect/log/airconnect.log" -d all=info

After running this command the config file will be generated and linked to the correct location (it will take a few seconds/minutes to complete until airupnp recognizes all speakers etc.)

root@box:~# ls -l /volume1/@appstore/AirConnect/config.xml
lrwxrwxrwx+ 1 airconnect airconnect 30 Jan 15 00:04 /volume1/@appstore/AirConnect/config.xml -> /volume1/airconnect/config.xml

root@box:~# ls -l /volume1/airconnect/config.xml
----------+ 1 root root 1094 Jan 14 23:58 /volume1/airconnect/config.xml

You could change the log level from info to error f.e. in airconnect.conf, that will dramatically decrease the size. But 11G is way too much.

Log Levels: -d <log>=<level> Set logging level, logs: all|raop|main|util|upnp, level: error|warn|info|debug|sdebug

config.xml:

AIRUPNP_LOGLEVEL="all=error"


Example Config file with adjusted log level on one of my own devices (change ip!):

cat /volume1/airconnect/airconnect.conf

AIRCAST_ENABLED=1
AIRCAST_LATENCY="1000:2000"
AIRCAST_LOGLEVEL="all=error"
AIRUPNP_ENABLED=1
AIRUPNP_LATENCY="1000:2000"
AIRUPNP_LOGLEVEL="all=error"
AIRUPNP_PORT=49154
FILTER_AIRPLAY2_DEVICES="<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless"
SYNO_IP="192.168.1.249"

@Gandulf78
Copy link

Gandulf78 commented Jan 15, 2024

Hi!
Welcome back and happy new year! Thank you for this new beta. I just tested it on my DS220+: the start still takes ~15s, the stop is instantaneous. There's definitely a change for the stop.

@eizedev
Copy link
Owner

eizedev commented Jan 15, 2024

Thanks! I wish you a happy new year too!
Thanks for the feedback. Another try, could you please test the new pre-release 1.7.0? There is a fix applied for starting airupnp: https://github.com/eizedev/AirConnect-Synology/releases/tag/1.7.0-20240115

I cannot test it at the moment (Since I have "broken" my network by rebuilding my local network ;)), could you please upload the log during playback if it is still not working?
Then there's not much left for us to test and I open an issue for us together in the AirConnect repository.

Thanks!

Edit: Issue opened: philippe44/AirConnect#517

@Gandulf78
Copy link

Gandulf78 commented Jan 16, 2024

Hello René.
I have tested the new version but it is the same behavior at the starting.
Please find attached the log file.
Laurent

airconnect.log

@eizedev
Copy link
Owner

eizedev commented Jan 19, 2024

Hi all, Hi @Gandulf78

We are a few steps further and the developer has released a new version for testing (not yet official) which I have packaged for you here. Can you please test it and give me some feedback? Or even better, post it directly in this issue (with logs if you can). It should work better, but I can't reproduce it on my end.

Thanks!

(Not all packages can be found in this zip, get back to me if you miss the right version)

AirConnect-Synology-1.8.1.zip

@huleiEthan
Copy link

huleiEthan commented Jan 19, 2024

Hi all, Hi @Gandulf78

We are a few steps further and the developer has released a new version for testing (not yet official) which I have packaged for you here. Can you please test it and give me some feedback? Or even better, post it directly in this issue (with logs if you can). It should work better, but I can't reproduce it on my end.

Thanks!

(Not all packages can be found in this zip, get back to me if you miss the right version)

AirConnect-Synology-1.8.1.zip

Hi~
I just tested the version 1.8.1 on DS218+, but sorry it's same behavior, starting about takes 15s, stoping is immediate.
airconnect (2).log

@eizedev
Copy link
Owner

eizedev commented Jan 19, 2024

ok, thanks! that is exactly the same behavior than on my NAS -I will pass it on

@philippe44
Copy link

philippe44 commented Jan 20, 2024

I've done some verification with my own system

=> A brief review of your system

2024-01-19T23:09:44+08:00 xanadu [23:09:44.391] rtp_thread_func:746 [0x7f4604006c70]: 1st NTP packet received
2024-01-19T23:09:44+08:00 xanadu [23:09:44.393] handle_rtsp:374 [0x7f4618003770]: received RECORD
2024-01-19T23:09:44+08:00 xanadu [23:09:44.393] raopst_record:371 [0x7f4604006c70]: record 0 - 0
... request to play received
2024-01-19T23:09:44+08:00 xanadu [23:09:44.428] handle_rtsp:374 [0x7f4618003770]: received FLUSH
2024-01-19T23:09:44+08:00 xanadu [23:09:44.428] raopst_flush:356 [0x7f4604006c70]: FLUSH packets below 53813 - 1236848519
... cleanup order received
2024-01-19T23:09:44+08:00 xanadu [23:09:44.431] buffer_put_packet:446 [0x7f4604006c70]: 1st accepted packet:53813, now playing
2024-01-19T23:09:44+08:00 xanadu [23:09:44.750] AVTSetURI:69 [0x7f463141d010]: uPNP setURI http://10.8.8.8:37487/stream-0.flac (cookie 0x2)
2024-01-19T23:09:44+08:00 xanadu [23:09:44.750] AVTPlay:123 [0x7f463141d010]: uPNP play (cookie 0x3)
... play order given
2024-01-19T23:09:45+08:00 xanadu [23:09:44.785] handle_http:1097 [0x7f4604006c70]: received GET HTTP/1.1
... Sonos requests the audio file
2024-01-19T23:09:45+08:00 xanadu [23:09:44.785] handle_http:1142 [0x7f4604006c70]: responding: HTTP/1.0 200 OK
2024-01-19T23:09:45+08:00 xanadu [23:09:44.785] http_thread_func:979 [0x7f4604006c70]: sending 242 silence frames
2024-01-19T23:09:45+08:00 xanadu [23:09:44.913] buffer_put_packet:531 [0x7f4604006c70]: fill [level:26] [W:53876 R:53851]
...
2024-01-19T23:09:46+08:00 xanadu [23:09:46.354] rtp_thread_func:652 [0x7f4604006c70]: 1st RTP packet received
... now fully operational 2s after AirPlay request, here data is sent over HTTP to Sonos. You can see it being drained fast, so Sonos is gobbling it quickly.
2024-01-19T23:09:46+08:00 xanadu [23:09:46.362] _buffer_get_frame:908 [0x7f4604006c70]: drain [level:205 gap:-615] [W:54056 R:53851] [R:0 S:0 F:0]
2024-01-19T23:09:46+08:00 xanadu [23:09:46.365] _buffer_get_frame:908 [0x7f4604006c70]: drain [level:142 gap:-115] [W:54056 R:53914] [R:0 S:0 F:0]
2024-01-19T23:09:46+08:00 xanadu [23:09:46.367] _buffer_get_frame:908 [0x7f4604006c70]: drain [level:78 gap:393] [W:54056 R:53978] [R:0 S:0 F:0]
2024-01-19T23:09:49+08:00 xanadu [23:09:49.173] ActionHandler:505 [0x7f463141d010]: uPNP transition
... finally the Sonos is showing sign of life (3s after receiving 1st data packet)
2024-01-19T23:09:57+08:00 xanadu [23:09:56.933] ActionHandler:514 [0x7f463141d010]: uPNP playing
... and it waits 7.5s to start to actually play, so a total of 12s

==> Here is what happens on my system with a PLAY:3 that is still on S1 (never moved to S2) and using iTunes

[22:40:15.897] rtp_thread_func:746 [04F3B998]: 1st NTP packet received
[22:40:15.898] handle_rtsp:374 [015396E0]: received RECORD
[22:40:15.898] raopst_record:371 [04F3B998]: record 42456 - 703906597
[22:40:15.899] rtp_thread_func:652 [04F3B998]: 1st RTP packet received
[22:40:15.899] rtp_thread_func:658 [04F3B998]: 1st sync packet received
[22:40:15.899] rtp_thread_func:628 [04F3B998]: 1st audio packet received 42456
[22:40:15.899] buffer_put_packet:446 [04F3B998]: 1st accepted packet:42456, now playing
[22:40:15.900] buffer_put_packet:531 [04F3B998]: fill [level:1] [W:42456 R:42456]
[22:40:15.900] HandleRAOP:320 [015718C8]: uPNP setURI http://192.168.2.10:64146/stream-0.flac (cookie 00000001)
[22:40:15.900] AVTSetURI:69 [015718C8]: uPNP setURI http://192.168.2.10:64146/stream-0.flac (cookie 00000001)
[22:40:15.900] AVTPlay:123 [015718C8]: uPNP play (cookie 00000002)
[22:40:16.276] http_thread_func:956 [04F3B998]: got HTTP connection 1404
[22:40:16.291] handle_http:1097 [04F3B998]: received GET HTTP/1.1
[22:40:16.291] handle_http:1142 [04F3B998]: responding: HTTP/1.0 200 OK
[22:40:16.291] http_thread_func:979 [04F3B998]: sending 200 silence frames
[22:40:16.294] _buffer_get_frame:910 [04F3B998]: drain [level:50 gap:604] [W:42506 R:42456] [R:0 S:0 F:0]
[22:40:19.021] ActionHandler:514 [015718C8]: uPNP playing

In total 4s between beginning and playing

==> And same with iPhone iOS 17.x

[22:47:25.640] rtp_thread_func:746 [01FF8050]: 1st NTP packet received
[22:47:25.640] handle_rtsp:374 [01469968]: received RECORD
[22:47:25.640] raopst_record:371 [01FF8050]: record 0 - 0
[22:47:25.645] rtp_thread_func:652 [01FF8050]: 1st RTP packet received
[22:47:25.645] rtp_thread_func:658 [01FF8050]: 1st sync packet received
[22:47:25.672] buffer_put_packet:449 [01FF8050]: 1st accepted packet:40956, waiting for FLUSH
[22:47:25.672] buffer_put_packet:531 [01FF8050]: fill [level:1] [W:40956 R:40956]
[22:47:25.674] handle_rtsp:374 [01469968]: received FLUSH
[22:47:25.674] raopst_flush:356 [01FF8050]: FLUSH packets below 40956 - 2814806524
[22:47:25.713] buffer_put_packet:461 [01FF8050]: done waiting for FLUSH with packet:40958, now playing starting:40956
[22:47:25.907] HandleRAOP:320 [014A5788]: uPNP setURI http://192.168.2.10:58222/stream-0.flac (cookie 00000000)
[22:47:25.907] AVTSetURI:69 [014A5788]: uPNP setURI http://192.168.2.10:58222/stream-0.flac (cookie 00000000)
[22:47:25.907] AVTPlay:123 [014A5788]: uPNP play (cookie 00000001)
[22:47:26.182] buffer_put_packet:531 [01FF8050]: fill [level:52] [W:41019 R:40968]
[22:47:26.518] http_thread_func:956 [01FF8050]: got HTTP connection 1368
[22:47:26.519] handle_http:1097 [01FF8050]: received GET HTTP/1.1
[22:47:26.519] handle_http:1142 [01FF8050]: responding: HTTP/1.0 200 OK
[22:47:26.519] http_thread_func:979 [01FF8050]: sending 155 silence frames
[22:47:26.520] _buffer_get_frame:910 [01FF8050]: drain [level:94 gap:254] [W:41062 R:40968] [R:0 S:0 F:0]
[22:47:26.521] _buffer_get_frame:910 [01FF8050]: drain [level:31 gap:755] [W:41062 R:41031] [R:0 S:0 F:0]
[22:47:28.684] ActionHandler:514 [014A5788]: uPNP playing

You can see there is 3 sec between command and playing

It seems to me that the issue is your version of Sonos buffering much more than mine. The other difference you can see is the 1st sync packet arriving later. But that has no impact on playback. The exact role of that sync packet is unclear in AirPlay because I've seen it used differently across iOS and macOS versions.

@eizedev
Copy link
Owner

eizedev commented Jan 20, 2024

ok, @philippe44 I think, after doing some troubleshooting, I was able to narrow down the problem and have found a workaround. I have a few devices, all with latest apple software/firmware (iPad Pro, iPhone, macOS) and all old speakers (mostly Play:1) are on latest SONOS firmware. airupnp is running on different Synology NAS Servers with different kernel versions (from really old to "new"). All with the same behavior.
But if I tell airupnp to use wav as codec -c wav and set http content-length to fixed (-g 0), playback, pause, stop and volume change is nearly instant. Not even 1 second delay after pressing play on my device.

Any idea what Sonos (again) did to break it? We had a similar problem a few month back with older Sonos releases.

Should I switch the default settings of airupnp for the Synology package to these settings or do you have any idea what could be changed to leave the default settings? I think I will integrate a config setting to make it changeable for the Synology users.

./airupnp-linux-x86_64 -b 192.168.1.10:49159 -l 1000:2000 -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -d all=debug -c wav -g 0

Click to expand - From MacBook Pro using Spotify App - 1.8.1 Log (Loglevel DEBUG):
root@box:/volume1/airconnect/test#

./airupnp-linux-x86_64 -b 192.168.1.10:49159 -l 1000:2000 -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -d all=debug -c wav -g 0

[13:21:18.407] main:1383 Starting airupnp version: v1.8.1 (Jan 16 2024 @ 21:47:44)
[13:21:18.407] main:1390 no config file, using defaults
[13:21:18.409] Start:1094 Binding to iface 192.168.1.10:49159 [ovs_bond0]
[13:21:18.413] bind_socket:701 socket binding 7 on port 45995
[13:21:18.413] Start:1133 Starting pico HTTP server on port 45995
[13:21:18.587] AddMRDevice:1003 [0x7ff15643e010]: creating MAC
[13:21:18.587] AddMRDevice:1020 [0x7ff15643e010]: adding renderer (Küche) with mac BBBB18ECE22D
[13:21:18.587] bind_socket:701 socket binding 12 on port 54361
[13:21:18.598] MasterHandler:638 [0x7ff15643e010]: subscribe success
[13:21:18.676] ProcessEvent:447 [0x7ff15643e010]: UPnP Volume local change 3:3 (master)
[13:21:18.734] AddMRDevice:1003 [0x7ff15643ffd0]: creating MAC
[13:21:18.734] AddMRDevice:1020 [0x7ff15643ffd0]: adding renderer (Flur) with mac BBBB30A98145
[13:21:18.735] bind_socket:701 socket binding 15 on port 44896
[13:21:18.751] MasterHandler:638 [0x7ff15643ffd0]: subscribe success
[13:21:18.834] ProcessEvent:447 [0x7ff15643ffd0]: UPnP Volume local change 34:34 (master)
[13:21:18.972] AddMRDevice:1003 [0x7ff156441f90]: creating MAC
[13:21:18.972] AddMRDevice:1020 [0x7ff156441f90]: adding renderer (Büro) with mac BBBB1553729B
[13:21:18.972] bind_socket:701 socket binding 16 on port 35939
[13:21:18.984] MasterHandler:638 [0x7ff156441f90]: subscribe success
[13:21:19.066] ProcessEvent:447 [0x7ff156441f90]: UPnP Volume local change 34:34 (master)
[13:21:20.636] AddMRDevice:1003 [0x7ff156443f50]: creating MAC
[13:21:20.636] AddMRDevice:1020 [0x7ff156443f50]: adding renderer (Kello_D4567C) with mac BBBB1FE1E692
[13:21:20.636] bind_socket:701 socket binding 18 on port 38016
[13:21:20.637] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:21:20.661] MasterHandler:638 [0x7ff156443f50]: subscribe success
[13:21:20.664] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:21:21.173] ProcessEvent:447 [0x7ff156443f50]: UPnP Volume local change 50:-1 (master)
[13:21:32.083] rtsp_thread:333 got RTSP connection 19
[13:21:32.083] http_parse_simple:1030 sock: 19, received CSeq: 0
[13:21:32.083] http_parse_simple:1030 sock: 19, received DACP-ID: BB7BF26411E50034
[13:21:32.083] http_parse_simple:1030 sock: 19, received Active-Remote: 1233195519
[13:21:32.083] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:21:46.109] http_read_line:1101 disconnected on the other end 19
[13:21:46.109] rtsp_thread:348 RTSP close 19
[13:21:48.001] UpdateThread:690 Presence checking
[13:21:48.126] UpdateThread:750 [0x7ff15643e010] UPnP keep alive: Küche+
[13:21:48.490] UpdateThread:750 [0x7ff15643e010] UPnP keep alive: Küche+
[13:21:48.522] UpdateThread:750 [0x7ff15643ffd0] UPnP keep alive: Flur+
[13:21:48.554] UpdateThread:750 [0x7ff156441f90] UPnP keep alive: Büro+
[13:21:48.575] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:21:48.584] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:21:48.590] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:08.525] rtsp_thread:333 got RTSP connection 19
[13:22:08.527] http_parse_simple:1030 sock: 19, received CSeq: 0
[13:22:08.527] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:08.527] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:08.527] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.015] http_parse_simple:1030 sock: 19, received CSeq: 1
[13:22:09.015] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.015] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.015] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.051] http_parse_simple:1030 sock: 19, received CSeq: 2
[13:22:09.051] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.051] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.051] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.056] http_parse_simple:1030 sock: 19, received Apple-Challenge: SCyFS2Yr2rvdLPKItK9zrg==
[13:22:09.056] http_parse_simple:1030 sock: 19, received CSeq: 3
[13:22:09.056] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.056] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.056] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.056] handle_rtsp:380 [0x7ff13c025730]: challenge SCyFS2Yr2rvdLPKItK9zrg==
[13:22:09.067] http_parse_simple:1030 sock: 19, received Content-Length: 642
[13:22:09.067] http_parse_simple:1030 sock: 19, received Content-Type: application/sdp
[13:22:09.067] http_parse_simple:1030 sock: 19, received CSeq: 4
[13:22:09.067] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.068] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.068] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.068] handle_rtsp:374 [0x7ff13c025730]: received ANNOUNCE
[13:22:09.088] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4


[13:22:09.092] http_parse_simple:1030 sock: 19, received Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=49957;control_port=64891
[13:22:09.092] http_parse_simple:1030 sock: 19, received CSeq: 5
[13:22:09.092] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.092] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.092] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.092] handle_rtsp:374 [0x7ff13c025730]: received SETUP
[13:22:09.099] bind_socket:701 socket binding 22 on port 44959
[13:22:09.099] raopst_init:260 [0x7ff118006c80]: UDP port-0 44959
[13:22:09.099] bind_socket:701 socket binding 23 on port 42921
[13:22:09.099] raopst_init:260 [0x7ff118006c80]: UDP port-1 42921
[13:22:09.099] bind_socket:701 socket binding 24 on port 41397
[13:22:09.099] raopst_init:260 [0x7ff118006c80]: UDP port-2 41397
[13:22:09.099] bind_socket:701 socket binding 25 on port 40593
[13:22:09.099] raopst_init:278 [0x7ff118006c80]: HTTP listening port 40593
[13:22:09.099] handle_rtsp:470 [0x7ff13c025730]: http=(40593) audio=(0:44959), timing=(49957:41397), control=(64891:42921)
[13:22:09.099] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651312587 (port: 49957)
[13:22:09.099] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=42921;timing_port=41397;server_port=44959
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 5


[13:22:09.099] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651312587 (port: 49957)
[13:22:09.099] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651312587 (port: 49957)
[13:22:09.103] rtp_thread_func:746 [0x7ff118006c80]: 1st NTP packet received
[13:22:09.103] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651312587, remote: 83adaf19d06b2097 (delta : 0, sum : 0, adjust : 0, gaps :  0)
[13:22:09.103] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651312587, remote: 83adaf19d06ebcf2 (delta : -1, sum : -1, adjust : 0, gaps :  0)
[13:22:09.104] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651312587, remote: 83adaf19d06f4b8e (delta : -1, sum : -2, adjust : 0, gaps :  0)
[13:22:09.105] http_parse_simple:1030 sock: 19, received CSeq: 6
[13:22:09.105] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.105] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.105] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.105] handle_rtsp:374 [0x7ff13c025730]: received RECORD
[13:22:09.105] raopst_record:371 [0x7ff118006c80]: record 0 - 0
[13:22:09.105] HandleRAOP:285 [0x7ff15643ffd0]: Stream
[13:22:09.105] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Latency: 44100
Audio-Jack-Status: connected; type=analog
CSeq: 6


[13:22:09.109] http_parse_simple:1030 sock: 19, received Content-Length: 20
[13:22:09.109] http_parse_simple:1030 sock: 19, received Content-Type: text/parameters
[13:22:09.109] http_parse_simple:1030 sock: 19, received CSeq: 7
[13:22:09.109] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.109] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.109] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.109] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:09.109] handle_rtsp:541 [0x7ff13c025730]: SET PARAMETER volume -20.000000
[13:22:09.109] CtrlSetVolume:205 [0x7ff15643ffd0]: uPNP volume 33 (cookie (nil))
[13:22:09.109] HandleRAOP:367 [0x7ff15643ffd0]: Volume[0..100] 33:34
[13:22:09.109] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7


[13:22:09.117] rtp_thread_func:652 [0x7ff118006c80]: 1st RTP packet received
[13:22:09.117] rtp_thread_func:658 [0x7ff118006c80]: 1st sync packet received
[13:22:09.117] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2875843396 rtp:2875920571 remote ntp:83adaf19d4168efc, local time 651312601(now: 651312605)
[13:22:09.117] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651312605 (port: 49957)
[13:22:09.119] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651312605, remote: 83adaf19d47f5978 (delta : 2, sum : 0, adjust : 0, gaps :  0)
[13:22:09.122] http_parse_simple:1030 sock: 19, received Content-Length: 20
[13:22:09.123] http_parse_simple:1030 sock: 19, received Content-Type: text/parameters
[13:22:09.123] http_parse_simple:1030 sock: 19, received CSeq: 8
[13:22:09.123] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.123] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.123] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.123] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:09.123] handle_rtsp:541 [0x7ff13c025730]: SET PARAMETER volume -20.000000
[13:22:09.123] CtrlSetVolume:205 [0x7ff15643ffd0]: uPNP volume 34 (cookie 0x1)
[13:22:09.123] HandleRAOP:367 [0x7ff15643ffd0]: Volume[0..100] 33:33
[13:22:09.123] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8


[13:22:09.157] buffer_put_packet:449 [0x7ff118006c80]: 1st accepted packet:19078, waiting for FLUSH
[13:22:09.157] buffer_put_packet:531 [0x7ff118006c80]: fill [level:1] [W:19078 R:19078]
[13:22:09.158] http_parse_simple:1030 sock: 19, received RTP-Info: seq=19078;rtptime=2875921679
[13:22:09.158] http_parse_simple:1030 sock: 19, received CSeq: 9
[13:22:09.158] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:09.158] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:09.158] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:09.158] handle_rtsp:374 [0x7ff13c025730]: received FLUSH
[13:22:09.158] raopst_flush:356 [0x7ff118006c80]: FLUSH packets below 19078 - 2875921679
[13:22:09.158] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 9


[13:22:09.185] buffer_put_packet:461 [0x7ff118006c80]: done waiting for FLUSH with packet:19082, now playing starting:19080
[13:22:09.537] search_remote_cb:631 [0x7ff13c025730]: found ActiveRemote for 511B6249FD1E5F1C at 192.168.1.96:49198
[13:22:10.978] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2875924108 rtp:2876001283 remote ntp:83adaf1ba89dbb96, local time 651314433(now: 651314466)
[13:22:10.980] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=2875912679
[13:22:10.980] http_parse_simple:1030 sock: 19, received Content-Length: 0
[13:22:10.980] http_parse_simple:1030 sock: 19, received Content-Type: image/none
[13:22:10.980] http_parse_simple:1030 sock: 19, received CSeq: 10
[13:22:10.980] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:10.980] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:10.980] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:10.980] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:10.980] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 10


[13:22:10.982] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=2875914087
[13:22:10.982] http_parse_simple:1030 sock: 19, received Content-Length: 82
[13:22:10.982] http_parse_simple:1030 sock: 19, received Content-Type: application/x-dmap-tagged
[13:22:10.983] http_parse_simple:1030 sock: 19, received CSeq: 11
[13:22:10.983] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:10.983] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:10.983] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:10.983] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:10.983] handle_rtsp:559 [0x7ff13c025730]: received metadata
	artist:
	album:
	title:
[13:22:10.983] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 11


[13:22:11.135] http_parse_simple:1030 sock: 19, received CSeq: 12
[13:22:11.135] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:11.135] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:11.136] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:11.154] http_parse_simple:1030 sock: 19, received CSeq: 13
[13:22:11.154] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:11.154] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:11.154] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:11.154] handle_rtsp:374 [0x7ff13c025730]: received TEARDOWN
[13:22:11.154] HandleRAOP:290 [0x7ff15643ffd0]: Stop
[13:22:11.186] rtp_thread_func:757 [0x7ff118006c80]: terminating
[13:22:11.203] http_thread_func:1081 [0x7ff118006c80]: terminating
[13:22:11.203] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 13


[13:22:11.219] http_read_line:1101 disconnected on the other end 19
[13:22:11.219] rtsp_thread:348 RTSP close 19
[13:22:16.406] rtsp_thread:333 got RTSP connection 19
[13:22:16.406] http_parse_simple:1030 sock: 19, received CSeq: 0
[13:22:16.406] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.406] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.406] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.411] http_parse_simple:1030 sock: 19, received CSeq: 1
[13:22:16.411] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.411] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.411] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.415] http_parse_simple:1030 sock: 19, received Apple-Challenge: aY/872xReebRXvOTZlia4w==
[13:22:16.415] http_parse_simple:1030 sock: 19, received CSeq: 2
[13:22:16.415] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.415] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.415] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.415] handle_rtsp:380 [0x7ff13c025730]: challenge aY/872xReebRXvOTZlia4w==
[13:22:16.427] http_parse_simple:1030 sock: 19, received Content-Length: 642
[13:22:16.427] http_parse_simple:1030 sock: 19, received Content-Type: application/sdp
[13:22:16.427] http_parse_simple:1030 sock: 19, received CSeq: 3
[13:22:16.428] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.428] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.428] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.428] handle_rtsp:374 [0x7ff13c025730]: received ANNOUNCE
[13:22:16.438] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 3


[13:22:16.445] http_parse_simple:1030 sock: 19, received Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=65450;control_port=59593
[13:22:16.445] http_parse_simple:1030 sock: 19, received CSeq: 4
[13:22:16.445] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.445] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.445] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.445] handle_rtsp:374 [0x7ff13c025730]: received SETUP
[13:22:16.448] bind_socket:701 socket binding 22 on port 57075
[13:22:16.448] raopst_init:260 [0x7ff118006c80]: UDP port-0 57075
[13:22:16.448] bind_socket:701 socket binding 23 on port 56218
[13:22:16.448] raopst_init:260 [0x7ff118006c80]: UDP port-1 56218
[13:22:16.448] bind_socket:701 socket binding 24 on port 45331
[13:22:16.448] raopst_init:260 [0x7ff118006c80]: UDP port-2 45331
[13:22:16.448] bind_socket:701 socket binding 25 on port 43375
[13:22:16.448] raopst_init:278 [0x7ff118006c80]: HTTP listening port 43375
[13:22:16.448] handle_rtsp:470 [0x7ff13c025730]: http=(43375) audio=(0:57075), timing=(65450:45331), control=(59593:56218)
[13:22:16.448] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651319936 (port: 65450)
[13:22:16.448] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=56218;timing_port=45331;server_port=57075
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 4


[13:22:16.448] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651319936 (port: 65450)
[13:22:16.448] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651319936 (port: 65450)
[13:22:16.452] rtp_thread_func:746 [0x7ff118006c80]: 1st NTP packet received
[13:22:16.452] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651319936, remote: 83adaf2129869505 (delta : 0, sum : 0, adjust : 0, gaps :  0)
[13:22:16.453] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651319936, remote: 83adaf2129976787 (delta : -1, sum : -1, adjust : 0, gaps :  0)
[13:22:16.453] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651319936, remote: 83adaf2129a0af62 (delta : -1, sum : -2, adjust : 0, gaps :  0)
[13:22:16.454] search_remote_cb:631 [0x7ff13c025730]: found ActiveRemote for 511B6249FD1E5F1C at 192.168.1.96:49198
[13:22:16.462] http_parse_simple:1030 sock: 19, received CSeq: 5
[13:22:16.463] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.463] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.463] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.463] handle_rtsp:374 [0x7ff13c025730]: received RECORD
[13:22:16.463] raopst_record:371 [0x7ff118006c80]: record 0 - 0
[13:22:16.463] HandleRAOP:285 [0x7ff15643ffd0]: Stream
[13:22:16.463] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Latency: 44100
Audio-Jack-Status: connected; type=analog
CSeq: 5


[13:22:16.475] rtp_thread_func:652 [0x7ff118006c80]: 1st RTP packet received
[13:22:16.475] rtp_thread_func:658 [0x7ff118006c80]: 1st sync packet received
[13:22:16.475] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385464600 rtp:2385541775 remote ntp:83adaf212fae6ff3, local time 651319959(now: 651319963)
[13:22:16.475] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651319963 (port: 65450)
[13:22:16.477] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651319963, remote: 83adaf213036136f (delta : 1, sum : -1, adjust : 0, gaps :  0)
[13:22:16.519] buffer_put_packet:449 [0x7ff118006c80]: 1st accepted packet:6560, waiting for FLUSH
[13:22:16.519] buffer_put_packet:531 [0x7ff118006c80]: fill [level:1] [W:6560 R:6560]
[13:22:16.534] http_parse_simple:1030 sock: 19, received RTP-Info: seq=6560;rtptime=2385542874
[13:22:16.534] http_parse_simple:1030 sock: 19, received CSeq: 6
[13:22:16.534] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:16.534] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:16.535] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:16.535] handle_rtsp:374 [0x7ff13c025730]: received FLUSH
[13:22:16.535] raopst_flush:356 [0x7ff118006c80]: FLUSH packets below 6560 - 2385542874
[13:22:16.535] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6


[13:22:16.547] buffer_put_packet:461 [0x7ff118006c80]: done waiting for FLUSH with packet:6564, now playing starting:6560
[13:22:16.547] HandleRAOP:320 [0x7ff15643ffd0]: uPNP setURI http://192.168.1.10:43375/stream-0.wav (cookie 0x2)
[13:22:16.547] AVTSetURI:69 [0x7ff15643ffd0]: uPNP setURI http://192.168.1.10:43375/stream-0.wav (cookie 0x2)
[13:22:16.547] AVTSetURI:70 [0x7ff15643ffd0]: DIDL header: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/">
<item id="1" parentID="0" restricted="1">
<dc:title>Streaming from AirConnect</dc:title>
<dc:creator></dc:creator>
<upnp:genre></upnp:genre>
<upnp:artist></upnp:artist>
<upnp:album></upnp:album>
<upnp:class>object.item.audioItem.musicTrack</upnp:class>
<res duration="0:00:00.001" protocolInfo="http-get:*:audio/wav:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d500000000000000000000000000000">http://192.168.1.10:43375/stream-0.wav</res>
</item>
</DIDL-Lite>

[13:22:16.547] AVTPlay:123 [0x7ff15643ffd0]: uPNP play (cookie 0x3)
[13:22:16.577] ActionHandler:480 [0x7ff15643ffd0]: Waited action SetAVTransportURIResponse
[13:22:16.590] ActionHandler:480 [0x7ff15643ffd0]: Waited action PlayResponse
[13:22:16.594] http_thread_func:956 [0x7ff118006c80]: got HTTP connection 26
[13:22:16.595] http_parse_simple:1030 sock: 26, received CONNECTION: close
[13:22:16.595] http_parse_simple:1030 sock: 26, received Host: 192.168.1.10:43375
[13:22:16.595] http_parse_simple:1030 sock: 26, received ACCEPT: */*
[13:22:16.595] http_parse_simple:1030 sock: 26, received USER-AGENT: Linux UPnP/1.0 Sonos/76.2-47270 (ZPS12)
[13:22:16.595] http_parse_simple:1030 sock: 26, received X-Sonos-SWGen: 2
[13:22:16.595] http_parse_simple:1030 sock: 26, received X-Sonos-Firmware: 76.2-47270
[13:22:16.595] http_parse_simple:1030 sock: 26, received X-Sonos-Muse-Api: 1.37.1
[13:22:16.595] http_parse_simple:1030 sock: 26, received X-Sonos-Id-Hash: qx3rchOJjALLQNaTnOkij1abkHulgsT0DmTWJ2OgRVs=
[13:22:16.595] handle_http:1097 [0x7ff118006c80]: received GET HTTP/1.1
CONNECTION: close
Host: 192.168.1.10:43375
ACCEPT: */*
USER-AGENT: Linux UPnP/1.0 Sonos/76.2-47270 (ZPS12)
X-Sonos-SWGen: 2
X-Sonos-Firmware: 76.2-47270
X-Sonos-Muse-Api: 1.37.1
X-Sonos-Id-Hash: qx3rchOJjALLQNaTnOkij1abkHulgsT0DmTWJ2OgRVs=

[13:22:16.595] handle_http:1142 [0x7ff118006c80]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/wav
Content-Length: 2147483647
Connection: close


[13:22:16.595] http_thread_func:979 [0x7ff118006c80]: sending 239 silence frames
[13:22:16.714] _buffer_get_frame:908 [0x7ff118006c80]: drain [level:17 gap:782] [W:6577 R:6560] [R:0 S:0 F:0]
[13:22:18.000] UpdateThread:690 Presence checking
[13:22:18.134] UpdateThread:750 [0x7ff15643e010] UPnP keep alive: Küche+
[13:22:18.206] UpdateThread:750 [0x7ff156441f90] UPnP keep alive: Büro+
[13:22:18.286] UpdateThread:750 [0x7ff15643ffd0] UPnP keep alive: Flur+
[13:22:18.449] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385549669 rtp:2385626844 remote ntp:83adaf231d815986, local time 651321889(now: 651321937)
[13:22:18.452] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=2385538098
[13:22:18.452] http_parse_simple:1030 sock: 19, received Content-Length: 0
[13:22:18.452] http_parse_simple:1030 sock: 19, received Content-Type: image/none
[13:22:18.452] http_parse_simple:1030 sock: 19, received CSeq: 7
[13:22:18.452] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:18.452] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:18.453] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:18.453] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:18.453] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7


[13:22:18.454] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=2385540562
[13:22:18.455] http_parse_simple:1030 sock: 19, received Content-Length: 82
[13:22:18.455] http_parse_simple:1030 sock: 19, received Content-Type: application/x-dmap-tagged
[13:22:18.455] http_parse_simple:1030 sock: 19, received CSeq: 8
[13:22:18.455] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:18.455] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:18.455] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:18.455] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:18.455] handle_rtsp:559 [0x7ff13c025730]: received metadata
	artist:
	album:
	title:
[13:22:18.455] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8


[13:22:18.493] http_parse_simple:1030 sock: 19, received CSeq: 9
[13:22:18.493] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:18.493] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:18.493] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:18.742] ActionHandler:514 [0x7ff15643ffd0]: uPNP playing
[13:22:20.555] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385638297 rtp:2385715472 remote ntp:83adaf251ffe8219, local time 651323899(now: 651324043)
[13:22:20.560] http_parse_simple:1030 sock: 19, received CSeq: 10
[13:22:20.560] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:20.560] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:20.561] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:22.396] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385725664 rtp:2385802839 remote ntp:83adaf271b275b9b, local time 651325880(now: 651325884)
[13:22:22.534] http_parse_simple:1030 sock: 19, received CSeq: 11
[13:22:22.534] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:22.534] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:22.534] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:23.413] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385770546 rtp:2385847721 remote ntp:83adaf281fb225ce, local time 651326898(now: 651326901)
[13:22:23.413] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651326901 (port: 65450)
[13:22:23.415] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651326901, remote: 83adaf2820347597 (delta : 0, sum : -1, adjust : 0, gaps :  0)
[13:22:24.550] http_parse_simple:1030 sock: 19, received CSeq: 12
[13:22:24.550] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:24.550] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:24.550] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:24.991] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:25.024] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:25.034] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:25.396] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385857974 rtp:2385935149 remote ntp:83adaf2a1b36c24d, local time 651328881(now: 651328884)
[13:22:26.414] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385902814 rtp:2385979989 remote ntp:83adaf2b1f82a807, local time 651329898(now: 651329902)
[13:22:26.564] http_parse_simple:1030 sock: 19, received CSeq: 13
[13:22:26.564] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:26.564] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:26.564] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:27.945] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:27.961] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:27.976] UpdateThread:750 [0x7ff156443f50] UPnP keep alive: Kello_D4567C+
[13:22:28.398] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:2385990310 rtp:2386067485 remote ntp:83adaf2d1b6bdc29, local time 651331882(now: 651331886)
[13:22:28.596] http_parse_simple:1030 sock: 19, received CSeq: 14
[13:22:28.596] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:28.596] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:28.596] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:28.809] http_parse_simple:1030 sock: 19, received CSeq: 15
[13:22:28.809] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:28.809] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:28.809] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:28.809] handle_rtsp:374 [0x7ff13c025730]: received TEARDOWN
[13:22:28.809] HandleRAOP:290 [0x7ff15643ffd0]: Stop
[13:22:28.809] AVTStop:180 [0x7ff15643ffd0]: uPNP stop (cookie 0x11)
[13:22:28.823] http_thread_func:1081 [0x7ff118006c80]: terminating
[13:22:28.837] rtp_thread_func:757 [0x7ff118006c80]: terminating
[13:22:28.837] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 15


[13:22:28.840] http_read_line:1101 disconnected on the other end 19
[13:22:28.840] rtsp_thread:348 RTSP close 19
[13:22:28.859] ActionHandler:480 [0x7ff15643ffd0]: Waited action StopResponse
[13:22:28.997] ActionHandler:510 [0x7ff15643ffd0]: uPNP stopped
[13:22:30.847] rtsp_thread:333 got RTSP connection 19
[13:22:30.848] http_parse_simple:1030 sock: 19, received CSeq: 0
[13:22:30.848] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.848] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.848] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.852] http_parse_simple:1030 sock: 19, received CSeq: 1
[13:22:30.852] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.852] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.852] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.854] http_parse_simple:1030 sock: 19, received Apple-Challenge: xYF/BqApRTj/HgmEUbGHbA==
[13:22:30.854] http_parse_simple:1030 sock: 19, received CSeq: 2
[13:22:30.854] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.854] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.854] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.854] handle_rtsp:380 [0x7ff13c025730]: challenge xYF/BqApRTj/HgmEUbGHbA==
[13:22:30.864] http_parse_simple:1030 sock: 19, received Content-Length: 642
[13:22:30.865] http_parse_simple:1030 sock: 19, received Content-Type: application/sdp
[13:22:30.865] http_parse_simple:1030 sock: 19, received CSeq: 3
[13:22:30.865] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.865] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.865] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.865] handle_rtsp:374 [0x7ff13c025730]: received ANNOUNCE
[13:22:30.875] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 3


[13:22:30.882] http_parse_simple:1030 sock: 19, received Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=61360;control_port=55213
[13:22:30.882] http_parse_simple:1030 sock: 19, received CSeq: 4
[13:22:30.882] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.883] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.883] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.883] handle_rtsp:374 [0x7ff13c025730]: received SETUP
[13:22:30.884] bind_socket:701 socket binding 22 on port 37949
[13:22:30.884] raopst_init:260 [0x7ff118006c80]: UDP port-0 37949
[13:22:30.885] bind_socket:701 socket binding 23 on port 57892
[13:22:30.885] raopst_init:260 [0x7ff118006c80]: UDP port-1 57892
[13:22:30.885] bind_socket:701 socket binding 24 on port 41639
[13:22:30.885] raopst_init:260 [0x7ff118006c80]: UDP port-2 41639
[13:22:30.885] bind_socket:701 socket binding 25 on port 58865
[13:22:30.885] raopst_init:278 [0x7ff118006c80]: HTTP listening port 58865
[13:22:30.885] handle_rtsp:470 [0x7ff13c025730]: http=(58865) audio=(0:37949), timing=(61360:41639), control=(55213:57892)
[13:22:30.885] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651334373 (port: 61360)
[13:22:30.885] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=57892;timing_port=41639;server_port=37949
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 4


[13:22:30.885] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651334373 (port: 61360)
[13:22:30.885] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651334373 (port: 61360)
[13:22:30.887] rtp_thread_func:746 [0x7ff118006c80]: 1st NTP packet received
[13:22:30.887] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651334373, remote: 83adaf2f98fbefb6 (delta : 0, sum : 0, adjust : 0, gaps :  0)
[13:22:30.887] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651334373, remote: 83adaf2f98fe538b (delta : -1, sum : -1, adjust : 0, gaps :  0)
[13:22:30.888] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651334373, remote: 83adaf2f98fead04 (delta : -1, sum : -2, adjust : 0, gaps :  0)
[13:22:30.888] http_parse_simple:1030 sock: 19, received CSeq: 5
[13:22:30.888] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.888] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.888] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.888] handle_rtsp:374 [0x7ff13c025730]: received RECORD
[13:22:30.888] raopst_record:371 [0x7ff118006c80]: record 0 - 0
[13:22:30.888] HandleRAOP:285 [0x7ff15643ffd0]: Stream
[13:22:30.888] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Latency: 44100
Audio-Jack-Status: connected; type=analog
CSeq: 5


[13:22:30.892] rtp_thread_func:652 [0x7ff118006c80]: 1st RTP packet received
[13:22:30.892] rtp_thread_func:658 [0x7ff118006c80]: 1st sync packet received
[13:22:30.892] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:4129792293 rtp:4129869468 remote ntp:83adaf2f9a28ae97, local time 651334377(now: 651334380)
[13:22:30.892] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651334380 (port: 61360)
[13:22:30.894] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651334380, remote: 83adaf2f9ad8ab45 (delta : -1, sum : -3, adjust : 0, gaps :  0)
[13:22:30.932] buffer_put_packet:449 [0x7ff118006c80]: 1st accepted packet:54145, waiting for FLUSH
[13:22:30.932] buffer_put_packet:531 [0x7ff118006c80]: fill [level:1] [W:54145 R:54145]
[13:22:30.949] http_parse_simple:1030 sock: 19, received RTP-Info: seq=54145;rtptime=4129870614
[13:22:30.949] http_parse_simple:1030 sock: 19, received CSeq: 6
[13:22:30.950] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:30.950] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:30.950] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:30.950] handle_rtsp:374 [0x7ff13c025730]: received FLUSH
[13:22:30.950] raopst_flush:356 [0x7ff118006c80]: FLUSH packets below 54145 - 4129870614
[13:22:30.950] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6


[13:22:30.959] buffer_put_packet:461 [0x7ff118006c80]: done waiting for FLUSH with packet:54149, now playing starting:54147
[13:22:30.959] HandleRAOP:320 [0x7ff15643ffd0]: uPNP setURI http://192.168.1.10:58865/stream-1.wav (cookie 0x13)
[13:22:30.959] AVTSetURI:69 [0x7ff15643ffd0]: uPNP setURI http://192.168.1.10:58865/stream-1.wav (cookie 0x13)
[13:22:30.959] AVTSetURI:70 [0x7ff15643ffd0]: DIDL header: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/">
<item id="1" parentID="0" restricted="1">
<dc:title>Streaming from AirConnect</dc:title>
<dc:creator></dc:creator>
<upnp:genre></upnp:genre>
<upnp:artist></upnp:artist>
<upnp:album></upnp:album>
<upnp:class>object.item.audioItem.musicTrack</upnp:class>
<res duration="0:00:00.001" protocolInfo="http-get:*:audio/wav:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=0d500000000000000000000000000000">http://192.168.1.10:58865/stream-1.wav</res>
</item>
</DIDL-Lite>

[13:22:30.960] AVTPlay:123 [0x7ff15643ffd0]: uPNP play (cookie 0x14)
[13:22:30.981] ActionHandler:480 [0x7ff15643ffd0]: Waited action SetAVTransportURIResponse
[13:22:31.002] ActionHandler:480 [0x7ff15643ffd0]: Waited action PlayResponse
[13:22:31.004] http_thread_func:956 [0x7ff118006c80]: got HTTP connection 26
[13:22:31.004] http_parse_simple:1030 sock: 26, received CONNECTION: close
[13:22:31.004] http_parse_simple:1030 sock: 26, received Host: 192.168.1.10:58865
[13:22:31.004] http_parse_simple:1030 sock: 26, received ACCEPT: */*
[13:22:31.005] http_parse_simple:1030 sock: 26, received USER-AGENT: Linux UPnP/1.0 Sonos/76.2-47270 (ZPS12)
[13:22:31.005] http_parse_simple:1030 sock: 26, received X-Sonos-SWGen: 2
[13:22:31.005] http_parse_simple:1030 sock: 26, received X-Sonos-Firmware: 76.2-47270
[13:22:31.005] http_parse_simple:1030 sock: 26, received X-Sonos-Muse-Api: 1.37.1
[13:22:31.005] http_parse_simple:1030 sock: 26, received X-Sonos-Id-Hash: qx3rchOJjALLQNaTnOkij1abkHulgsT0DmTWJ2OgRVs=
[13:22:31.005] handle_http:1097 [0x7ff118006c80]: received GET HTTP/1.1
CONNECTION: close
Host: 192.168.1.10:58865
ACCEPT: */*
USER-AGENT: Linux UPnP/1.0 Sonos/76.2-47270 (ZPS12)
X-Sonos-SWGen: 2
X-Sonos-Firmware: 76.2-47270
X-Sonos-Muse-Api: 1.37.1
X-Sonos-Id-Hash: qx3rchOJjALLQNaTnOkij1abkHulgsT0DmTWJ2OgRVs=

[13:22:31.005] handle_http:1142 [0x7ff118006c80]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/wav
Content-Length: 2147483647
Connection: close


[13:22:31.005] http_thread_func:979 [0x7ff118006c80]: sending 241 silence frames
[13:22:31.119] _buffer_get_frame:908 [0x7ff118006c80]: drain [level:23 gap:811] [W:54170 R:54147] [R:0 S:0 F:0]
[13:22:32.846] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:4129878441 rtp:4129955616 remote ntp:83adaf318e3efc83, local time 651336330(now: 651336334)
[13:22:32.847] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=4129866894
[13:22:32.847] http_parse_simple:1030 sock: 19, received Content-Length: 0
[13:22:32.847] http_parse_simple:1030 sock: 19, received Content-Type: image/none
[13:22:32.847] http_parse_simple:1030 sock: 19, received CSeq: 7
[13:22:32.847] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:32.847] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:32.847] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:32.847] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:32.847] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7


[13:22:32.849] http_parse_simple:1030 sock: 19, received RTP-Info: rtptime=4129866894
[13:22:32.849] http_parse_simple:1030 sock: 19, received Content-Length: 82
[13:22:32.850] http_parse_simple:1030 sock: 19, received Content-Type: application/x-dmap-tagged
[13:22:32.850] http_parse_simple:1030 sock: 19, received CSeq: 8
[13:22:32.850] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:32.850] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:32.850] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:32.850] handle_rtsp:374 [0x7ff13c025730]: received SET_PARAMETER
[13:22:32.850] handle_rtsp:559 [0x7ff13c025730]: received metadata
	artist:
	album:
	title:
[13:22:32.850] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8


[13:22:32.911] http_parse_simple:1030 sock: 19, received CSeq: 9
[13:22:32.911] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:32.911] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:32.911] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:34.246] ActionHandler:514 [0x7ff15643ffd0]: uPNP playing
[13:22:34.860] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:4129967244 rtp:4130044419 remote ntp:83adaf3391be9750, local time 651338344(now: 651338348)
[13:22:34.932] http_parse_simple:1030 sock: 19, received CSeq: 10
[13:22:34.932] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:34.932] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:34.932] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:36.841] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:4130054569 rtp:4130131744 remote ntp:83adaf358ca9e34f, local time 651340324(now: 651340329)
[13:22:36.944] http_parse_simple:1030 sock: 19, received CSeq: 11
[13:22:36.944] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:36.944] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:36.944] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:37.850] rtp_thread_func:664 [0x7ff118006c80]: sync packet rtp_latency:4130099137 rtp:4130176312 remote ntp:83adaf368f621d09, local time 651341335(now: 651341338)
[13:22:37.850] rtp_request_timing:769 [0x7ff118006c80]: timing request now:651341338 (port: 61360)
[13:22:37.854] rtp_thread_func:750 [0x7ff118006c80]: Timing references local:651341338, remote: 83adaf36902fe99a (delta : -1, sum : -4, adjust : 0, gaps :  0)
[13:22:38.630] http_parse_simple:1030 sock: 19, received CSeq: 12
[13:22:38.630] http_parse_simple:1030 sock: 19, received DACP-ID: 511B6249FD1E5F1C
[13:22:38.630] http_parse_simple:1030 sock: 19, received Active-Remote: 1841493647
[13:22:38.630] http_parse_simple:1030 sock: 19, received User-Agent: AirPlay/750.14.1
[13:22:38.630] handle_rtsp:374 [0x7ff13c025730]: received TEARDOWN
[13:22:38.630] HandleRAOP:290 [0x7ff15643ffd0]: Stop
[13:22:38.630] AVTStop:180 [0x7ff15643ffd0]: uPNP stop (cookie 0x16)
[13:22:38.639] http_thread_func:1081 [0x7ff118006c80]: terminating
[13:22:38.662] rtp_thread_func:757 [0x7ff118006c80]: terminating
[13:22:38.687] ActionHandler:480 [0x7ff15643ffd0]: Waited action StopResponse
[13:22:38.692] handle_rtsp:587 [0x7ff13c025730]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 12


[13:22:38.698] http_read_line:1101 disconnected on the other end 19
[13:22:38.698] rtsp_thread:348 RTSP close 19
[13:22:39.245] ActionHandler:510 [0x7ff15643ffd0]: uPNP stopped
^C[13:22:40.325] Stop:1164 terminate update thread ...
[13:22:40.326] Stop:1169 flush renderers ...
[13:22:40.400] MRThread:268 [0x7ff15643e010] player thread exited
[13:22:40.401] MRThread:268 [0x7ff15643ffd0] player thread exited
[13:22:40.481] MRThread:268 [0x7ff156441f90] player thread exited
[13:22:40.545] MRThread:268 [0x7ff156443f50] player thread exited
[13:22:40.545] Stop:1172 terminate libupnp
^C[13:22:40.861] Stop:1164 terminate update thread ...

Edit: I have uploaded a zip file containing some versions (no static packages, file size limit of GitHub) of the Synology package with added changes from above as hard coded values. could someone @Gandulf78 @huleiEthan f.e. please test it and give feedback how it works on your devices? Thanks
AirConnect-Synology-1.8.1.zip

@Gandulf78
Copy link

Gandulf78 commented Jan 20, 2024

I just tested it on my DS220+ with my iPhone XR. It is much better on start-up : 1-2 s to start!

@philippe44
Copy link

philippe44 commented Jan 20, 2024

is "-g 0" or is "-c wav" what is making the difference?

@eizedev
Copy link
Owner

eizedev commented Jan 20, 2024

will test it tomorrow

@huleiEthan
Copy link

yes! It's work in my case, starting takes about 2s.

@eizedev
Copy link
Owner

eizedev commented Jan 24, 2024

will test it tomorrow

Had Not much the last two days. Will test it in the next days

@philippe44
Copy link

BTW, I don't recommend much using wav as they have a hard limit in term of playback duration which is not really compatible with AirPlay. It's 4GB (that I might have limited to 2GB, I'll have to verify that), so about 3 hours (or 6) of playback.

@eizedev
Copy link
Owner

eizedev commented Jan 27, 2024

@philippe44 i've tested it today with all different parameters and settings. -c wav is not needed. -g 0 in general is doing the most to reduce initial time for playback. The best results I get with following parameters and settings:

./airupnp-linux-x86_64 -b 192.168.1.10:49159 -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -d all=debug -g 0 -l 50:100

So -g 0 and -l 50:100 or 50:100:0 did the trick for me. Playback in my local network is now nearly instant (max 1 sec) to old Sonos Play:1 speakers and I did not notice any side effects in my environment with lowering latency settings after 2h of playback.
Codec selection is not necessary, mp3 is ok. Flac will not work and there is no significant difference between wav and mp3. I did not test bitrate for mp3 or pcm.

i will build a new package for testing tomorrow.

@philippe44
Copy link

philippe44 commented Jan 27, 2024

What do you mean by flac did not work? Did it work before? And this is the default codec if you don't specify any option

@eizedev
Copy link
Owner

eizedev commented Jan 27, 2024

What do you mean by flax did not work? Did it work before? And this is the default codec if you don't specify any option

Hmmm, than i missed something. I only added -c flac. But without adding any codec and using default settings it works as described above
(Your documentation says "flc" for codec, ./airupnp -h help says "flac")

@philippe44
Copy link

I will check but flac is the default for sure c, now I might have not allowed flc or flac on the command line

@philippe44
Copy link

I corrected my README regarding flc vs flac as it was incorrect ("flac" should be used, not "flc"). But it does not change much in a sense that flac is the default codec and if the -c is not recognized, the default value is used. The only difference is that the name of the file sent to the player still still be ".flc" if you set "-c flc".

So none of this seems to make sense (not what you are saying, of course I trust you see what you see, it's just I cannot make sense of it)

@eizedev
Copy link
Owner

eizedev commented Jan 27, 2024

During the test, I briefly appended -c mp3 and -c flac to determine the differences. With -c mp3 I could not detect any difference compared to not specifying the parameter at all. With -c flac, it didn't play any sound for the next 30 seconds, but i also did not checked the log, and then didn't follow it any further.

I'll have another look tomorrow. Maybe I mistyped -c flac towards the end when testing and that's why it didn't work.

Finally, I omitted the parameter again as usual and only added -g 0, which makes a significant difference. With -l 50:100 it got even better (in my environment)

Basically, the behavior now with the command line call from above is great and I'll build another package tomorrow for the others here to test.

@philippe44
Copy link

Would you mind trying again with just -c flac to be sure? The 2nd latency parameter reduce lag for sure but at the expense of potential buffering issue in case of network hiccup

@eizedev
Copy link
Owner

eizedev commented Jan 28, 2024

Would you mind trying again with just -c flac to be sure? The 2nd latency parameter reduce lag for sure but at the expense of potential buffering issue in case of network hiccup

ok -c flac is working as it should, I think I had mistyped anything yesterday during tests.

./airupnp-linux-x86_64 -b 192.168.1.10:49159 -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -d all=debug -g 0 -l 50:500 -c flac

i have increased the http latency to 500 and playback now takes about 1 second, maximum 2 seconds to start. I think this is okay. @philippe44 Do you think 50:500 could be a good default setting for delivering inside the Synology package for airupnp? So the middle between fast start + stability? Instead of 1000:2000? Users of a Synology device could also change the latency through the gui in a separate config file that I added. (should be easy to use for most users without the need for using ssh to their NAS)

@eizedev
Copy link
Owner

eizedev commented Jan 28, 2024

@5trobl In new testing version (below) the log file should be deleted if it exceeds a size of 50MB (a one shot backup until the next start will created airconnect.1.log if someone needs the old log for debugging).
I have also changed the way the config file will be generated/updated. During upgrade, if any parameter for airupnp/aircast is missing in the airconnect.conf it will be added. So the upgrade process should now be consistent if I add new parameters to the config file.
For Installation (Uninstall + New Install) the default config file with default settings will be used and must be changed later on, if needed.
so in general, your config file settings should be used in any way (I hope 👍🏼 ).

All others:
I have tuned the default parameters in this version to -l 50:500 and -g 0, that should reduce the playback time to 1-3 seconds. Please give me feedback :-).

if you get any errors during upgrade process (not uninstall and reinstall) please let me know. That is related to my change in the upgrade process. It works on my devices, at least ;-).
Errors during installation/upgrade will be logged in less /var/log/packages/AirConnect.log

Readme and code will be updated, if anything is working.

AirConnect-Synology-1.8.1.zip

@philippe44
Copy link

philippe44 commented Jan 28, 2024

Would you mind trying again with just -c flac to be sure? The 2nd latency parameter reduce lag for sure but at the expense of potential buffering issue in case of network hiccup

ok -c flac is working as it should, I think I had mistyped anything yesterday during tests.

./airupnp-linux-x86_64 -b 192.168.1.10:49159 -o "<NULL>,S1,S3,S5,S9,S12,ZP80,ZP90,S15,ZP100,ZP120,1.0,LibreWireless,Fitzwilliam,2.2.6,AllShare1.0" -d all=debug -g 0 -l 50:500 -c flac

i have increased the http latency to 500 and playback now takes about 1 second, maximum 2 seconds to start. I think this is okay. @philippe44 Do you think 50:500 could be a good default setting for delivering inside the Synology package for airupnp? So the middle between fast start + stability? Instead of 1000:2000? Users of a Synology device could also change the latency through the gui in a separate config file that I added. (should be easy to use for most users without the need for using ssh to their NAS)

There is no perfect solutio, it's just one to deal with network issues from the AirPlay to the bridge and the other is from the bridge to the UPnP device. So UPnP device do their own buffering and wait a lot to play, in which case :HTTP can be zero, some like Sonos don't so you have to add some because otherwise they'll miss data very frequently.

Now the need for -g 0 baffles me.

@Gandulf78
Copy link

Gandulf78 commented Jan 28, 2024

Hi.
I just tested it on my DS220+, Sonos Play:1 and my iPhone XR. It takes around 6s to start, 2s to stop.

@NeoKentai
Copy link

Hi
I also just tested the new version on my DS220+ with a Sonos Play:1 and a Sonos Playbar.
For me it takes 5s to start playing and pausing is instant.

@eizedev
Copy link
Owner

eizedev commented Mar 27, 2024

I have uploaded a new release for 1.8.3. https://github.com/eizedev/AirConnect-Synology/releases/tag/1.8.3-20240327

For me if i change the config in /volume1/airconnect/airconnect.conf

"AIRUPNP_CONTENTLENGTH_MODE=0"
"AIRUPNP_LATENCY=50:500"

(results in -l 50:500 -g 0)

it is nearly instant, max. 2 seconds delay on playback. No playback problems if i play from apple music, spotify or directly from macOS/ipad/iOS in the last weeks (for hours)

@Xavantes81
Copy link

Xavantes81 commented Mar 28, 2024

Unfortunately the new package won’t start on my DS224+. Installation works flawless, but after running airconnect it immediately stops…

1.8.1 did work without any issues.

Thanks for your help!

@eizedev
Copy link
Owner

eizedev commented Mar 28, 2024

Unfortunately the new package won’t start on my DS224+. Installation works flawless, but after running airconnect it immediately stops…

1.8.1 did work without any issues.

Thanks for your help!

Thanks for the reply. i already got the info from @Gandulf78 in another issue. I have changed 1.8.3 to pre-release and will investigate the problem. Looks like a problem in my build and start/stop process.

@eizedev
Copy link
Owner

eizedev commented Apr 3, 2024

Should now be fixed in the latest release: https://github.com/eizedev/AirConnect-Synology/releases/tag/1.8.3-20240403.
New version 1.8.3 with all the enhancements are working on my devices.

thanks to @seiryIsNotABlock @seiry for your help to find the problem and creating the pull request!!

@eizedev eizedev closed this as completed Apr 3, 2024
@hadsnz
Copy link

hadsnz commented May 21, 2024

Hi - So happy reading this. I'm using Sonos speakers and was having the 10-15 second delay when starting and resuming.
It's now working well for me using. Airconnect 1.8.3. Iphone and apple pusic

airupnp.exe -l :50:500 -g 0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
airconnect-bug Bug in the Airconnect binaries aircast and/or airupnp bug Something isn't working dsm7 DSM7 related issues work-in-progress Issue will not be stale
Projects
None yet
Development

No branches or pull requests

9 participants