Volume on Airplay connect changes

[gwww]

Thanks for this amazing project!!

With a Sonos Play 1, I set the volume to 0 (using the Sonos app). You can see where I did as the first line of the log.

In Apple Music I then connect to the Sonos and the volume changes to 34.

This feels like a bug. I tried looking at the code and wasn't clear enough on the logic. The set volume is coming from here: https://github.com/philippe44/AirConnect/blob/263806c92bf39cecb0f347d5bc1ca0806759bae3/airupnp/src/airupnp.c#L366

Here is the log. I trimmed what I could but didn't want to take too much out as you might find it useful.

[13:38:55.996] ProcessEvent:447 [0x7fbba8ef6f50]: UPnP Volume local change 0:0 (master)
[13:39:12.001] UpdateThread:690 Presence checking
[13:39:12.325] UpdateThread:845 Updating configuration /config/airsonos.xml
[13:39:26.432] rtsp_thread:333 got RTSP connection 15
[13:39:26.433] http_parse_simple:1030 sock: 15, received CSeq: 0
[13:39:26.433] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.434] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.434] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.486] http_parse_simple:1030 sock: 15, received CSeq: 1
[13:39:26.486] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.486] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.486] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.491] http_parse_simple:1030 sock: 15, received CSeq: 2
[13:39:26.492] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.492] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.492] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.498] http_parse_simple:1030 sock: 15, received Apple-Challenge: asIh1gIMAfISfiUwZdRvZA==
[13:39:26.498] http_parse_simple:1030 sock: 15, received CSeq: 3
[13:39:26.498] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.498] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.498] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.498] handle_rtsp:380 [0x7fbb94010c90]: challenge asIh1gIMAfISfiUwZdRvZA==
[13:39:26.510] http_parse_simple:1030 sock: 15, received Content-Length: 652
[13:39:26.511] http_parse_simple:1030 sock: 15, received Content-Type: application/sdp
[13:39:26.511] http_parse_simple:1030 sock: 15, received CSeq: 4
[13:39:26.511] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.511] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.511] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.511] handle_rtsp:374 [0x7fbb94010c90]: received ANNOUNCE
[13:39:26.521] handle_rtsp:587 [0x7fbb94010c90]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4
[13:39:26.526] http_parse_simple:1030 sock: 15, received Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=60620;control_port=49945
[13:39:26.526] http_parse_simple:1030 sock: 15, received CSeq: 5
[13:39:26.526] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.527] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.527] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.527] handle_rtsp:374 [0x7fbb94010c90]: received SETUP
[13:39:26.528] bind_socket:701 socket binding 17 on port 50633
[13:39:26.528] raopst_init:260 [0x7fbb8801c9d0]: UDP port-0 50633
[13:39:26.528] bind_socket:701 socket binding 18 on port 46639
[13:39:26.528] raopst_init:260 [0x7fbb8801c9d0]: UDP port-1 46639
[13:39:26.528] bind_socket:701 socket binding 19 on port 49399
[13:39:26.528] raopst_init:260 [0x7fbb8801c9d0]: UDP port-2 49399
[13:39:26.528] bind_socket:701 socket binding 20 on port 40789
[13:39:26.528] raopst_init:278 [0x7fbb8801c9d0]: HTTP listening port 40789
[13:39:26.528] rtp_request_timing:769 [0x7fbb8801c9d0]: timing request now:1479011648 (port: 60620)
[13:39:26.528] handle_rtsp:470 [0x7fbb94010c90]: http=(40789) audio=(0:50633), timing=(60620:49399), control=(49945:46639)
[13:39:26.528] rtp_request_timing:769 [0x7fbb8801c9d0]: timing request now:1479011648 (port: 60620)
[13:39:26.528] rtp_request_timing:769 [0x7fbb8801c9d0]: timing request now:1479011648 (port: 60620)
[13:39:26.528] handle_rtsp:587 [0x7fbb94010c90]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=46639;timing_port=49399;server_port=50633
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 5
[13:39:26.532] http_parse_simple:1030 sock: 15, received CSeq: 6
[13:39:26.532] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.532] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.532] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.532] handle_rtsp:374 [0x7fbb94010c90]: received RECORD
[13:39:26.532] raopst_record:371 [0x7fbb8801c9d0]: record 0 - 0
[13:39:26.532] HandleRAOP:285 [0x7fbba8ef6f50]: Stream
[13:39:26.532] handle_rtsp:587 [0x7fbb94010c90]: responding:
RTSP/1.0 200 OK
Audio-Latency: 44100
Audio-Jack-Status: connected; type=analog
CSeq: 6
[13:39:26.534] rtp_thread_func:746 [0x7fbb8801c9d0]: 1st NTP packet received
[13:39:26.534] rtp_thread_func:750 [0x7fbb8801c9d0]: Timing references local:1479011648, remote: 83aeb47c89768eae (delta : 0, sum : 0, adjust : 0, gaps :  0)
[13:39:26.534] rtp_thread_func:750 [0x7fbb8801c9d0]: Timing references local:1479011648, remote: 83aeb47c897ca0ac (delta : -1, sum : -1, adjust : 0, gaps :  0)
[13:39:26.534] rtp_thread_func:750 [0x7fbb8801c9d0]: Timing references local:1479011648, remote: 83aeb47c897e0530 (delta : -1, sum : -2, adjust : 0, gaps :  0)
[13:39:26.537] http_parse_simple:1030 sock: 15, received Content-Length: 20
[13:39:26.537] http_parse_simple:1030 sock: 15, received Content-Type: text/parameters
[13:39:26.537] http_parse_simple:1030 sock: 15, received CSeq: 7
[13:39:26.537] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.537] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.537] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.537] handle_rtsp:374 [0x7fbb94010c90]: received SET_PARAMETER
[13:39:26.537] handle_rtsp:541 [0x7fbb94010c90]: SET PARAMETER volume -20.000000
[13:39:26.537] CtrlSetVolume:205 [0x7fbba8ef6f50]: uPNP volume 33 (cookie 0x2)
[13:39:26.537] HandleRAOP:367 [0x7fbba8ef6f50]: Volume[0..100] 33:0
[13:39:26.537] handle_rtsp:587 [0x7fbb94010c90]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7
[13:39:26.542] rtp_thread_func:652 [0x7fbb8801c9d0]: 1st RTP packet received
[13:39:26.542] rtp_thread_func:658 [0x7fbb8801c9d0]: 1st sync packet received
[13:39:26.542] rtp_thread_func:664 [0x7fbb8801c9d0]: sync packet rtp_latency:1605089920 rtp:1605167095 remote ntp:83aeb47c8bdc5bfd, local time 1479011657(now: 1479011662)
[13:39:26.542] rtp_request_timing:769 [0x7fbb8801c9d0]: timing request now:1479011662 (port: 60620)
[13:39:26.543] http_parse_simple:1030 sock: 15, received Content-Length: 20
[13:39:26.543] http_parse_simple:1030 sock: 15, received Content-Type: text/parameters
[13:39:26.543] http_parse_simple:1030 sock: 15, received CSeq: 8
[13:39:26.543] http_parse_simple:1030 sock: 15, received DACP-ID: 8A4ADA29A2D87783
[13:39:26.543] http_parse_simple:1030 sock: 15, received Active-Remote: 2073912104
[13:39:26.543] http_parse_simple:1030 sock: 15, received User-Agent: AirPlay/845.6.1
[13:39:26.543] handle_rtsp:374 [0x7fbb94010c90]: received SET_PARAMETER
[13:39:26.543] handle_rtsp:541 [0x7fbb94010c90]: SET PARAMETER volume -20.000000
[13:39:26.543] CtrlSetVolume:205 [0x7fbba8ef6f50]: uPNP volume 34 (cookie 0x3)
[13:39:26.543] HandleRAOP:367 [0x7fbba8ef6f50]: Volume[0..100] 33:33
[13:39:26.543] handle_rtsp:587 [0x7fbb94010c90]: responding:

Edit: I could not find the handle_rtsp function, but it does a set volume to -20.00000.