search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.27k stars 573 forks source link

[Problem]: Airplay2 on Mac mini G4 .. #1683

Closed jfdelaune closed 10 months ago

jfdelaune commented 1 year ago

What happened?

Hello,

On Mac Mini G4 PPC, I installed Fienix 6.01. I compiled for AirPlay. It works very well. I compiled for AirPlay 2. It doesn't works. it seems there is a problem of pairing or authentication ? Please find debug output:

root@fienix:/home/fienix/shairport-sync# ./shairport-sync -V
4.1.1-5-g69d3b02a-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc
root@fienix:/home/fienix/shairport-sync# ./shairport-sync -vv --statistics
         0.000917800 "shairport.c:573" looking for configuration file at full path "/etc/shairport-sync.conf"
         0.379540559 "shairport.c:2200" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "00:11:24:e4:d4:a8".
         0.000782610 "shairport.c:2239" Version String: "4.1.1-5-g69d3b02a-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000305981 "shairport.c:2258" Command Line: "./shairport-sync -vv --statistics".
         0.000325356 "shairport.c:2265" libsodium initialised.
         0.000655640 "shairport.c:2290" libgcrypt initialised.
         0.000272521 "shairport.c:2294" Log Verbosity is 2.
         0.000247905 "audio_alsa.c:1014" alsa: init() -- alsa_backend_state => abm_disconnected.
         0.000563021 "audio_alsa.c:1031" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000231607 "audio_alsa.c:1320" alsa: disable_standby_mode is "never".
         0.000188580 "audio_alsa.c:1324" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000123700 "audio_alsa.c:1326" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000126296 "audio_alsa.c:1366" alsa: output device name is "default".
         0.000383601 "shairport.c:2312" The processor is running big-endian.
         0.000194684 "shairport.c:2342" disable_resend_requests is off.
         0.000393841 "shairport.c:2343" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000132522 "shairport.c:2347" statistics_requester status is 1.
         0.000220045 "shairport.c:2352" rtsp listening port is 7000.
         0.000189469 "shairport.c:2353" udp base port is 6001.
         0.000110239 "shairport.c:2354" udp port range is 10.
         0.000174132 "shairport.c:2355" player name is "retro-ppc 4.1.1".
         0.000231848 "shairport.c:2356" backend is "alsa".
         0.000197089 "shairport.c:2357" run_this_before_play_begins action is "(null)".
         0.000179132 "shairport.c:2358" run_this_after_play_ends action is "(null)".
         0.000112522 "shairport.c:2359" wait-cmd status is 0.
         0.000167810 "shairport.c:2360" run_this_before_play_begins may return output is 0.
         0.000166248 "shairport.c:2361" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000111561 "shairport.c:2363" run_this_before_entering_active_state action is  "/bin/sleep 5".
         0.000171801 "shairport.c:2365" run_this_after_exiting_active_state action is  "/bin/sleep 5".
         0.000109589 "shairport.c:2367" active_state_timeout is  10.000000 seconds.
         0.000176056 "shairport.c:2368" mdns backend "(null)".
         0.000107162 "shairport.c:2369" userSuppliedLatency is 0.
         0.000339683 "shairport.c:2370" interpolation setting is "soxr".
         0.000142522 "shairport.c:2374" interpolation soxr_delay_threshold is 30000000.
         0.000201848 "shairport.c:2375" resync time is 0.050000 seconds.
         0.000199949 "shairport.c:2376" allow a session to be interrupted: 1.
         0.000297063 "shairport.c:2377" busy timeout time is 0.
         0.000207041 "shairport.c:2378" drift tolerance is 0.001995 seconds.
         0.000176632 "shairport.c:2379" password is "(null)".
         0.000157257 "shairport.c:2380" ignore_volume_control is 0.
         0.000118869 "shairport.c:2384" volume_max_db is not set
         0.000161007 "shairport.c:2385" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000109181 "shairport.c:2387" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000266151 "shairport.c:2391" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000197834 "shairport.c:2393" disable_synchronization is 1.
         0.000190213 "shairport.c:2394" use_mmap_if_available is 1.
         0.000169926 "shairport.c:2395" output_format automatic selection is enabled.
         0.000110719 "shairport.c:2399" output_rate automatic selection is enabled.
         0.000139782 "shairport.c:2403" audio backend desired buffer length is 0.200000 seconds.
         0.000107619 "shairport.c:2405" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000135984 "shairport.c:2407" audio backend latency offset is 0.000000 seconds.
         0.000136272 "shairport.c:2409" audio backend silence lead-in time is "auto".
         0.000106441 "shairport.c:2413" zeroconf regtype is "_raop._tcp".
         0.000130695 "shairport.c:2414" decoders_supported field is 1.
         0.000212064 "shairport.c:2415" use_apple_decoder is 0.
         0.000125768 "shairport.c:2416" alsa_use_hardware_mute is 0.
         0.000150863 "shairport.c:2420" no special mdns service interface was requested.
         0.000373336 "shairport.c:2423" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000271415 "shairport.c:2453" loudness is 0.
         0.000192930 "shairport.c:2454" loudness reference level is -20.000000
         0.000513575 "shairport.c:2464" size of hw_addr is 8.
         0.000452037 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.001120153 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.000754436 "audio_alsa.c:2073" keep_dac_busy is now "no"
         0.004972072 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 0
         0.000559343 "ptp-utilities.c:147" ptp_shm_interface_open -- success!
         0.000284563 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 2814459904
         0.000208098 "ptp-utilities.c:151" ptp_shm_interface_open -- already open!
         0.000328626 "shairport.c:2547" NQPTP is online.
         0.002124538 "activity_monitor.c:163" am_state: am_inactive
         0.013071046 "mdns_avahi.c:220" avahi: service '23311E36F971@retro-ppc 4.1.1' group is not yet committed.
         0.006566112 "mdns_avahi.c:268" avahi: avahi_entry_group_commit 0
         0.000399201 "mdns_avahi.c:463" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.001447889 "mdns_avahi.c:224" avahi: service '23311E36F971@retro-ppc 4.1.1' group is registering.
         0.884789875 "mdns_avahi.c:191" avahi: service '23311E36F971@retro-ppc 4.1.1' successfully added.
         0.587820706 "shairport.c:247" soxr_delay: 9946300 nanoseconds, soxr_delay_threshold: 30 milliseconds.
        46.812741998 "rtsp.c:5564" Connection 1: New connection from 2a01:cb00:e92:9700:39d1:4333:3409:9ba9:49399 to self at 2a01:cb00:e92:9700:c0c2:2f3:af77:4bf5:7000.
         0.003231230 "rtsp.c:2037" Connection 1: GET /info :: Content-Length 70
         0.000370620 "rtsp.c:2039" GET request
         0.000275164 "rtsp.c:2039"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000211368 "rtsp.c:2039"   Type: "Content-Length", content: "70"
         0.000188338 "rtsp.c:2039"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000190767 "rtsp.c:2039"   Type: "CSeq", content: "0"
         0.000224973 "rtsp.c:2039"   Type: "DACP-ID", content: "E6CF2D25FBCC872D"
         0.000117041 "rtsp.c:2039"   Type: "Active-Remote", content: "1919042277"
         0.000175960 "rtsp.c:2039"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.087221543 "rtsp.c:2039"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.001723197 "rtsp.c:1683" GET /info:
         0.000129109 "rtsp.c:1683"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000227761 "rtsp.c:1683"   Type: "Content-Length", content: "70"
         0.000118028 "rtsp.c:1683"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000106753 "rtsp.c:1683"   Type: "CSeq", content: "0"
         0.000103051 "rtsp.c:1683"   Type: "DACP-ID", content: "E6CF2D25FBCC872D"
         0.000103100 "rtsp.c:1683"   Type: "Active-Remote", content: "1919042277"
         0.000070720 "rtsp.c:1683"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000064639 "rtsp.c:1683"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.000392422 "rtsp.c:1692" Connection 1: GET_INFO: Source AirPlay Version is: 690.7.1.
         0.000101489 "rtsp.c:1715" GET /info Stage 1: qualifier: txtAirPlay
         0.001759712 "rtsp.c:1797" GET /info Stage 1 Response:
         0.000232208 "rtsp.c:1797"   Response Code: 501.
         0.000215886 "rtsp.c:1797"   Type: "CSeq", content: "0"
         0.000220286 "rtsp.c:1797"   Type: "Server", content: "AirTunes/366.0"
         0.000236655 "rtsp.c:1797"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000446845 "rtsp.c:1797"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>audioLatencies</key>
    <array>
        <dict>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>102</integer>
        </dict>
    </array>
    <key>keepAliveLowPower</key>
    <true/>
    <key>keepAliveSendStatsAsBody</key>
    <true/>
    <key>manufacturer</key>
    <string>Shairport Sync</string>
    <key>nameIsFactoryDefault</key>
    <false/>
    <key>protocolVersion</key>
    <string>1.1</string>
    <key>sdk</key>
    <string>AirPlay;2.0.2</string>
    <key>sourceVersion</key>
    <string>366.0</string>
    <key>statusFlags</key>
    <integer>4</integer>
    <key>txtAirPlay</key>
    <data>
    BWFjbD0wGmRldmljZWlkPTAwOjExOjI0OmU0OmQ0OmE4G2ZlYXR1cmVzPTB4NDA1QzRB
    MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
    YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
    Ni4wJ3BpPWFlNDQxNjM4LTI5YzEtNGIzOC04YzM2LWI1MjIzODYwZjE3ZihnaWQ9YWU0
    NDE2MzgtMjljMS00YjM4LThjMzYtYjUyMjM4NjBmMTdmBmdjZ2w9MENwaz0yNzQ3YjE1
    NmUwZDA4ZmEyYmY0YzY0OTM5NTg2NWQ4MjMzYjgyNmQwYmM0OWYxZDVkN2EyOTRkYjI4
    NWNlYjZl
    </data>
    <key>features</key>
    <integer>496155701824000</integer>
    <key>deviceID</key>
    <string>00:11:24:e4:d4:a8</string>
    <key>pi</key>
    <string>ae441638-29c1-4b38-8c36-b5223860f17f</string>
    <key>name</key>
    <string>retro-ppc 4.1.1</string>
    <key>model</key>
    <string>Shairport Sync</string>
</dict>
</plist>
--
         0.005757469 "rtsp.c:1545" Responding with content of length 915
         0.006684644 "rtsp.c:2197" Connection 1: pair-verify Content-Length 37
         0.034787647 "rtsp.c:2233" pair-verify response
         0.000756529 "rtsp.c:2233"   Response Code: 200.
         0.000293337 "rtsp.c:2233"   Type: "CSeq", content: "1"
         0.000232569 "rtsp.c:2233"   Type: "Server", content: "AirTunes/366.0"
         0.000200646 "rtsp.c:2233"   Type: "Content-Type", content: "application/octet-stream"
         0.000119133 "rtsp.c:2233"   No Content Plist. Content length: 140.
         0.000188579 "rtsp.c:1545" Responding with content of length 140
         0.214940896 "rtsp.c:2241" Connection 1: handle_pair-setup Content-Length 9
         0.089203487 "rtsp.c:2279" pair-setup response
         0.000449249 "rtsp.c:2279"   Response Code: 200.
         0.000362471 "rtsp.c:2279"   Type: "CSeq", content: "2"
         0.000270669 "rtsp.c:2279"   Type: "Server", content: "AirTunes/366.0"
         0.000119806 "rtsp.c:2279"   Type: "Content-Type", content: "application/octet-stream"
         0.000267785 "rtsp.c:2279"   No Content Plist. Content length: 409.
         0.000139013 "rtsp.c:1545" Responding with content of length 409
         0.034939159 "rtsp.c:2241" Connection 1: handle_pair-setup Content-Length 457
         0.107018123 "rtsp.c:2279" pair-setup response
         0.000381100 "rtsp.c:2279"   Response Code: 200.
         0.000357255 "rtsp.c:2279"   Type: "CSeq", content: "3"
         0.000168315 "rtsp.c:2279"   Type: "Server", content: "AirTunes/366.0"
         0.000178579 "rtsp.c:2279"   Type: "Content-Type", content: "application/octet-stream"
         0.000208050 "rtsp.c:2279"   No Content Plist. Content length: 69.
         0.000215719 "rtsp.c:1545" Responding with content of length 69
        60.439346644 "rtsp.c:1353" Connection 1: Connection closed by client.
         0.000447326 "rtsp.c:4985" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
         0.000060071 "rtsp.c:2657" Connection 1: TEARDOWN unspecified stream connection.
         0.000033341 "rtsp.c:5020" Connection 1: terminating -- closing RTSP connection socket 8: from 2a01:cb00:e92:9700:39d1:4333:3409:9ba9:49399 to self at 2a01:cb00:e92:9700:c0c2:2f3:af77:4bf5:7000.
         0.001156571 "rtsp.c:5083" Connection 1: Closed.

Jean-Francois

Relevant log output

root@fienix:/home/fienix/shairport-sync# ./shairport-sync -V
4.1.1-5-g69d3b02a-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc
root@fienix:/home/fienix/shairport-sync# ./shairport-sync -vv --statistics
         0.000917800 "shairport.c:573" looking for configuration file at full path "/etc/shairport-sync.conf"
         0.379540559 "shairport.c:2200" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "00:11:24:e4:d4:a8".
         0.000782610 "shairport.c:2239" Version String: "4.1.1-5-g69d3b02a-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000305981 "shairport.c:2258" Command Line: "./shairport-sync -vv --statistics".
         0.000325356 "shairport.c:2265" libsodium initialised.
         0.000655640 "shairport.c:2290" libgcrypt initialised.
         0.000272521 "shairport.c:2294" Log Verbosity is 2.
         0.000247905 "audio_alsa.c:1014" alsa: init() -- alsa_backend_state => abm_disconnected.
         0.000563021 "audio_alsa.c:1031" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000231607 "audio_alsa.c:1320" alsa: disable_standby_mode is "never".
         0.000188580 "audio_alsa.c:1324" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000123700 "audio_alsa.c:1326" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000126296 "audio_alsa.c:1366" alsa: output device name is "default".
         0.000383601 "shairport.c:2312" The processor is running big-endian.
         0.000194684 "shairport.c:2342" disable_resend_requests is off.
         0.000393841 "shairport.c:2343" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000132522 "shairport.c:2347" statistics_requester status is 1.
         0.000220045 "shairport.c:2352" rtsp listening port is 7000.
         0.000189469 "shairport.c:2353" udp base port is 6001.
         0.000110239 "shairport.c:2354" udp port range is 10.
         0.000174132 "shairport.c:2355" player name is "retro-ppc 4.1.1".
         0.000231848 "shairport.c:2356" backend is "alsa".
         0.000197089 "shairport.c:2357" run_this_before_play_begins action is "(null)".
         0.000179132 "shairport.c:2358" run_this_after_play_ends action is "(null)".
         0.000112522 "shairport.c:2359" wait-cmd status is 0.
         0.000167810 "shairport.c:2360" run_this_before_play_begins may return output is 0.
         0.000166248 "shairport.c:2361" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000111561 "shairport.c:2363" run_this_before_entering_active_state action is  "/bin/sleep 5".
         0.000171801 "shairport.c:2365" run_this_after_exiting_active_state action is  "/bin/sleep 5".
         0.000109589 "shairport.c:2367" active_state_timeout is  10.000000 seconds.
         0.000176056 "shairport.c:2368" mdns backend "(null)".
         0.000107162 "shairport.c:2369" userSuppliedLatency is 0.
         0.000339683 "shairport.c:2370" interpolation setting is "soxr".
         0.000142522 "shairport.c:2374" interpolation soxr_delay_threshold is 30000000.
         0.000201848 "shairport.c:2375" resync time is 0.050000 seconds.
         0.000199949 "shairport.c:2376" allow a session to be interrupted: 1.
         0.000297063 "shairport.c:2377" busy timeout time is 0.
         0.000207041 "shairport.c:2378" drift tolerance is 0.001995 seconds.
         0.000176632 "shairport.c:2379" password is "(null)".
         0.000157257 "shairport.c:2380" ignore_volume_control is 0.
         0.000118869 "shairport.c:2384" volume_max_db is not set
         0.000161007 "shairport.c:2385" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000109181 "shairport.c:2387" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000266151 "shairport.c:2391" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000197834 "shairport.c:2393" disable_synchronization is 1.
         0.000190213 "shairport.c:2394" use_mmap_if_available is 1.
         0.000169926 "shairport.c:2395" output_format automatic selection is enabled.
         0.000110719 "shairport.c:2399" output_rate automatic selection is enabled.
         0.000139782 "shairport.c:2403" audio backend desired buffer length is 0.200000 seconds.
         0.000107619 "shairport.c:2405" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000135984 "shairport.c:2407" audio backend latency offset is 0.000000 seconds.
         0.000136272 "shairport.c:2409" audio backend silence lead-in time is "auto".
         0.000106441 "shairport.c:2413" zeroconf regtype is "_raop._tcp".
         0.000130695 "shairport.c:2414" decoders_supported field is 1.
         0.000212064 "shairport.c:2415" use_apple_decoder is 0.
         0.000125768 "shairport.c:2416" alsa_use_hardware_mute is 0.
         0.000150863 "shairport.c:2420" no special mdns service interface was requested.
         0.000373336 "shairport.c:2423" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000271415 "shairport.c:2453" loudness is 0.
         0.000192930 "shairport.c:2454" loudness reference level is -20.000000
         0.000513575 "shairport.c:2464" size of hw_addr is 8.
         0.000452037 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.001120153 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.000754436 "audio_alsa.c:2073" keep_dac_busy is now "no"
         0.004972072 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 0
         0.000559343 "ptp-utilities.c:147" ptp_shm_interface_open -- success!
         0.000284563 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 2814459904
         0.000208098 "ptp-utilities.c:151" ptp_shm_interface_open -- already open!
         0.000328626 "shairport.c:2547" NQPTP is online.
         0.002124538 "activity_monitor.c:163" am_state: am_inactive
         0.013071046 "mdns_avahi.c:220" avahi: service '23311E36F971@retro-ppc 4.1.1' group is not yet committed.
         0.006566112 "mdns_avahi.c:268" avahi: avahi_entry_group_commit 0
         0.000399201 "mdns_avahi.c:463" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.001447889 "mdns_avahi.c:224" avahi: service '23311E36F971@retro-ppc 4.1.1' group is registering.
         0.884789875 "mdns_avahi.c:191" avahi: service '23311E36F971@retro-ppc 4.1.1' successfully added.
         0.587820706 "shairport.c:247" soxr_delay: 9946300 nanoseconds, soxr_delay_threshold: 30 milliseconds.
        46.812741998 "rtsp.c:5564" Connection 1: New connection from 2a01:cb00:e92:9700:39d1:4333:3409:9ba9:49399 to self at 2a01:cb00:e92:9700:c0c2:2f3:af77:4bf5:7000.
         0.003231230 "rtsp.c:2037" Connection 1: GET /info :: Content-Length 70
         0.000370620 "rtsp.c:2039" GET request
         0.000275164 "rtsp.c:2039"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000211368 "rtsp.c:2039"   Type: "Content-Length", content: "70"
         0.000188338 "rtsp.c:2039"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000190767 "rtsp.c:2039"   Type: "CSeq", content: "0"
         0.000224973 "rtsp.c:2039"   Type: "DACP-ID", content: "E6CF2D25FBCC872D"
         0.000117041 "rtsp.c:2039"   Type: "Active-Remote", content: "1919042277"
         0.000175960 "rtsp.c:2039"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.087221543 "rtsp.c:2039"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.001723197 "rtsp.c:1683" GET /info:
         0.000129109 "rtsp.c:1683"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000227761 "rtsp.c:1683"   Type: "Content-Length", content: "70"
         0.000118028 "rtsp.c:1683"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000106753 "rtsp.c:1683"   Type: "CSeq", content: "0"
         0.000103051 "rtsp.c:1683"   Type: "DACP-ID", content: "E6CF2D25FBCC872D"
         0.000103100 "rtsp.c:1683"   Type: "Active-Remote", content: "1919042277"
         0.000070720 "rtsp.c:1683"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000064639 "rtsp.c:1683"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.000392422 "rtsp.c:1692" Connection 1: GET_INFO: Source AirPlay Version is: 690.7.1.
         0.000101489 "rtsp.c:1715" GET /info Stage 1: qualifier: txtAirPlay
         0.001759712 "rtsp.c:1797" GET /info Stage 1 Response:
         0.000232208 "rtsp.c:1797"   Response Code: 501.
         0.000215886 "rtsp.c:1797"   Type: "CSeq", content: "0"
         0.000220286 "rtsp.c:1797"   Type: "Server", content: "AirTunes/366.0"
         0.000236655 "rtsp.c:1797"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000446845 "rtsp.c:1797"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>audioLatencies</key>
    <array>
        <dict>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>102</integer>
        </dict>
    </array>
    <key>keepAliveLowPower</key>
    <true/>
    <key>keepAliveSendStatsAsBody</key>
    <true/>
    <key>manufacturer</key>
    <string>Shairport Sync</string>
    <key>nameIsFactoryDefault</key>
    <false/>
    <key>protocolVersion</key>
    <string>1.1</string>
    <key>sdk</key>
    <string>AirPlay;2.0.2</string>
    <key>sourceVersion</key>
    <string>366.0</string>
    <key>statusFlags</key>
    <integer>4</integer>
    <key>txtAirPlay</key>
    <data>
    BWFjbD0wGmRldmljZWlkPTAwOjExOjI0OmU0OmQ0OmE4G2ZlYXR1cmVzPTB4NDA1QzRB
    MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
    YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
    Ni4wJ3BpPWFlNDQxNjM4LTI5YzEtNGIzOC04YzM2LWI1MjIzODYwZjE3ZihnaWQ9YWU0
    NDE2MzgtMjljMS00YjM4LThjMzYtYjUyMjM4NjBmMTdmBmdjZ2w9MENwaz0yNzQ3YjE1
    NmUwZDA4ZmEyYmY0YzY0OTM5NTg2NWQ4MjMzYjgyNmQwYmM0OWYxZDVkN2EyOTRkYjI4
    NWNlYjZl
    </data>
    <key>features</key>
    <integer>496155701824000</integer>
    <key>deviceID</key>
    <string>00:11:24:e4:d4:a8</string>
    <key>pi</key>
    <string>ae441638-29c1-4b38-8c36-b5223860f17f</string>
    <key>name</key>
    <string>retro-ppc 4.1.1</string>
    <key>model</key>
    <string>Shairport Sync</string>
</dict>
</plist>
--
         0.005757469 "rtsp.c:1545" Responding with content of length 915
         0.006684644 "rtsp.c:2197" Connection 1: pair-verify Content-Length 37
         0.034787647 "rtsp.c:2233" pair-verify response
         0.000756529 "rtsp.c:2233"   Response Code: 200.
         0.000293337 "rtsp.c:2233"   Type: "CSeq", content: "1"
         0.000232569 "rtsp.c:2233"   Type: "Server", content: "AirTunes/366.0"
         0.000200646 "rtsp.c:2233"   Type: "Content-Type", content: "application/octet-stream"
         0.000119133 "rtsp.c:2233"   No Content Plist. Content length: 140.
         0.000188579 "rtsp.c:1545" Responding with content of length 140
         0.214940896 "rtsp.c:2241" Connection 1: handle_pair-setup Content-Length 9
         0.089203487 "rtsp.c:2279" pair-setup response
         0.000449249 "rtsp.c:2279"   Response Code: 200.
         0.000362471 "rtsp.c:2279"   Type: "CSeq", content: "2"
         0.000270669 "rtsp.c:2279"   Type: "Server", content: "AirTunes/366.0"
         0.000119806 "rtsp.c:2279"   Type: "Content-Type", content: "application/octet-stream"
         0.000267785 "rtsp.c:2279"   No Content Plist. Content length: 409.
         0.000139013 "rtsp.c:1545" Responding with content of length 409
         0.034939159 "rtsp.c:2241" Connection 1: handle_pair-setup Content-Length 457
         0.107018123 "rtsp.c:2279" pair-setup response
         0.000381100 "rtsp.c:2279"   Response Code: 200.
         0.000357255 "rtsp.c:2279"   Type: "CSeq", content: "3"
         0.000168315 "rtsp.c:2279"   Type: "Server", content: "AirTunes/366.0"
         0.000178579 "rtsp.c:2279"   Type: "Content-Type", content: "application/octet-stream"
         0.000208050 "rtsp.c:2279"   No Content Plist. Content length: 69.
         0.000215719 "rtsp.c:1545" Responding with content of length 69
        60.439346644 "rtsp.c:1353" Connection 1: Connection closed by client.
         0.000447326 "rtsp.c:4985" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
         0.000060071 "rtsp.c:2657" Connection 1: TEARDOWN unspecified stream connection.
         0.000033341 "rtsp.c:5020" Connection 1: terminating -- closing RTSP connection socket 8: from 2a01:cb00:e92:9700:39d1:4333:3409:9ba9:49399 to self at 2a01:cb00:e92:9700:c0c2:2f3:af77:4bf5:7000.
         0.001156571 "rtsp.c:5083" Connection 1: Closed.

Configuration Information.

root@fienix:/home/fienix/shairport-sync# ./shairport-sync --displayConfig 
         0.003697930 "shairport.c:2061" >> Display Config Start.
         0.006168305 "shairport.c:2061" 
         0.000504440 "shairport.c:2061" From "uname -a":
         0.000122114 "shairport.c:2061"  Linux fienix 5.19.0-2-powerpc #1 Debian 5.19.11-1 (2022-09-24) ppc GNU/Linux
         0.107254057 "shairport.c:2061" 
         0.000493094 "shairport.c:2061" From /etc/os-release:
         0.000055143 "shairport.c:2061"  Debian GNU/Linux bookworm/sid
         0.007708741 "shairport.c:2061" 
         0.000465354 "shairport.c:2061" From /sys/firmware/devicetree/base/model:
         0.000054807 "shairport.c:2061"  PowerMac10,2
         0.000410715 "shairport.c:2061" 
         0.000070504 "shairport.c:2061" Shairport Sync Version String:
         0.000068220 "shairport.c:2061"  4.1.1-5-g69d3b02a-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc
         0.000039736 "shairport.c:2061" 
         0.000027788 "shairport.c:2061" Command Line:
         0.000177882 "shairport.c:2061"  ./shairport-sync --displayConfig
         0.000117811 "shairport.c:2061" 
         0.000139060 "shairport.c:2061" Configuration File:
         0.000036394 "shairport.c:2061"  /etc/shairport-sync.conf
         0.000028317 "shairport.c:2061" 
         0.000656265 "shairport.c:2061" Configuration File Settings:
         0.000254179 "shairport.c:2061"  general : 
         0.000463551 "shairport.c:2061"  {
         0.000108533 "shairport.c:2061"    name = "retro-ppc %v";
         0.000033076 "shairport.c:2061"    interpolation = "soxr";
         0.000116224 "shairport.c:2061"    output_backend = "alsa";
         0.000031995 "shairport.c:2061"  };
         0.000090792 "shairport.c:2061"  sessioncontrol : 
         0.000030000 "shairport.c:2061"  {
         0.000134060 "shairport.c:2061"    run_this_before_entering_active_state = "/bin/sleep 5";
         0.000133989 "shairport.c:2061"    run_this_after_exiting_active_state = "/bin/sleep 5";
         0.000099927 "shairport.c:2061"    allow_session_interruption = "yes";
         0.000032547 "shairport.c:2061"  };
         0.000191127 "shairport.c:2061"  alsa : 
         0.000150695 "shairport.c:2061"  {
         0.000034327 "shairport.c:2061"    output_device = "default";
         0.000081177 "shairport.c:2061"    output_rate = "auto";
         0.000087234 "shairport.c:2061"    output_format = "auto";
         0.000031081 "shairport.c:2061"    disable_synchronization = "yes";
         0.000101081 "shairport.c:2061"  };
         0.000091777 "shairport.c:2061"  diagnostics : 
         0.000030096 "shairport.c:2061"  {
         0.000027644 "shairport.c:2061"    log_verbosity = 1;
         0.000103676 "shairport.c:2061"  };
         0.000031346 "shairport.c:2061" 
         0.000081081 "shairport.c:2061" >> Display Config End.
         0.000032163 "shairport.c:2063" >> Goodbye!
         0.000179468 "shairport.c:1674" normal exit

How did you install Shairport Sync?

Built from source

Check previous issues

mikebrady commented 1 year ago

Thanks for the interesting post. Two things:

  1. You should update to the latest version -- there have been some fixes including a fix to a race condition that just might be the culprit.
  2. The PPC is running big-endian, and we have little experience of that, so that could be a possible source of the problem.

But the first thing is to update, preferably to the latest development branch. Note that you'll also have to update nqptp.

jfdelaune commented 1 year ago

I updated to the latest version.

root@fienix:/home/fienix/shairport-sync# ./shairport-sync -V
4.2.1d0-4-gbeb195eb-AirPlay2-smi9-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

I have the same behaviour :

root@fienix:/home/fienix/shairport-sync# ./shairport-sync -vv --statistics
         0.000737082 "shairport.c:578" looking for configuration file at full path "/etc/shairport-sync.conf"
         0.121973109 "shairport.c:2248" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "00:11:24:e4:d4:a8".
         0.000837561 "shairport.c:2287" Version String: "4.2.1d0-4-gbeb195eb-AirPlay2-smi9-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000328072 "shairport.c:2306" Command Line: "./shairport-sync -vv --statistics".
         0.000330645 "shairport.c:2313" libsodium initialised.
         0.000706937 "shairport.c:2338" libgcrypt initialised.
         0.000312328 "shairport.c:2342" Log Verbosity is 2.
         0.000173843 "audio_alsa.c:1003" alsa: init() -- alsa_backend_state => abm_disconnected.
         0.000375788 "audio_alsa.c:1020" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000167522 "audio_alsa.c:1309" alsa: disable_standby_mode is "never".
         0.000120792 "audio_alsa.c:1313" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000107330 "audio_alsa.c:1315" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000121465 "audio_alsa.c:1355" alsa: output device name is "default".
         0.000675591 "shairport.c:2360" The processor is running big-endian.
         0.000376654 "shairport.c:2390" disable_resend_requests is off.
         0.000186440 "shairport.c:2391" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000118772 "shairport.c:2395" statistics_requester status is 1.
         0.000105119 "shairport.c:2400" rtsp listening port is 7000.
         0.000104421 "shairport.c:2401" udp base port is 6001.
         0.000237257 "shairport.c:2402" udp port range is 10.
         0.000148676 "shairport.c:2403" player name is "retro-ppc 4.2".
         0.000176656 "shairport.c:2404" backend is "alsa".
         0.000128291 "shairport.c:2405" run_this_before_play_begins action is "(null)".
         0.000205430 "shairport.c:2406" run_this_after_play_ends action is "(null)".
         0.000175695 "shairport.c:2407" wait-cmd status is 0.
         0.000119373 "shairport.c:2408" run_this_before_play_begins may return output is 0.
         0.000214420 "shairport.c:2409" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000119566 "shairport.c:2411" run_this_before_entering_active_state action is  "(null)".
         0.000179877 "shairport.c:2413" run_this_after_exiting_active_state action is  "(null)".
         0.000144253 "shairport.c:2415" active_state_timeout is  10.000000 seconds.
         0.000139926 "shairport.c:2416" mdns backend "(null)".
         0.000107379 "shairport.c:2417" userSuppliedLatency is 0.
         0.000127089 "shairport.c:2418" interpolation setting is "auto".
         0.000106249 "shairport.c:2422" interpolation soxr_delay_threshold is 30000000.
         0.000104205 "shairport.c:2423" resync time is 0.050000 seconds.
         0.000103749 "shairport.c:2424" resync recovery time is 0.100000 seconds.
         0.000104493 "shairport.c:2425" allow a session to be interrupted: 1.
         0.000104278 "shairport.c:2426" busy timeout time is 0.
         0.000356461 "shairport.c:2427" drift tolerance is 0.002000 seconds.
         0.000146873 "shairport.c:2428" password is "(null)".
         0.000191945 "shairport.c:2429" default airplay volume is: -24.000000.
         0.000243386 "shairport.c:2430" high threshold airplay volume is: -16.000000.
         0.000119589 "shairport.c:2432" check for higher-than-threshold volume for new play session is disabled.
         0.000250670 "shairport.c:2438" ignore_volume_control is 0.
         0.000204661 "shairport.c:2442" volume_max_db is not set
         0.000166392 "shairport.c:2443" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000124974 "shairport.c:2445" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000143460 "shairport.c:2449" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000109397 "shairport.c:2451" disable_synchronization is 0.
         0.000130599 "shairport.c:2452" use_mmap_if_available is 1.
         0.000211584 "shairport.c:2453" output_format automatic selection is enabled.
         0.000115311 "shairport.c:2457" output_rate automatic selection is enabled.
         0.000172546 "shairport.c:2461" audio backend desired buffer length is 0.200000 seconds.
         0.000118748 "shairport.c:2463" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000145575 "shairport.c:2465" audio backend latency offset is 0.000000 seconds.
         0.000204444 "shairport.c:2467" audio backend silence lead-in time is "auto".
         0.000168291 "shairport.c:2471" zeroconf regtype is "_raop._tcp".
         0.000124181 "shairport.c:2472" decoders_supported field is 1.
         0.000106729 "shairport.c:2473" use_apple_decoder is 0.
         0.000104110 "shairport.c:2474" alsa_use_hardware_mute is 0.
         0.000104589 "shairport.c:2478" no special mdns service interface was requested.
         0.000173796 "shairport.c:2481" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000126897 "shairport.c:2511" loudness is 0.
         0.000105432 "shairport.c:2512" loudness reference level is -20.000000
         0.000394225 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.000837609 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.000513598 "audio_alsa.c:2038" keep_dac_busy is now "no"
         0.004965653 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 0
         0.000553719 "ptp-utilities.c:147" ptp_shm_interface_open -- success!
         0.000282688 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 2817376256
         0.000385452 "ptp-utilities.c:151" ptp_shm_interface_open -- already open!
         0.000301919 "shairport.c:2610" NQPTP is online.
         0.002403909 "activity_monitor.c:163" am_state: am_inactive
         0.013030446 "mdns_avahi.c:220" avahi: service '001124E4D4A8@retro-ppc 4.2' group is not yet committed.
         0.006649404 "mdns_avahi.c:268" avahi: avahi_entry_group_commit 0
         0.000356966 "mdns_avahi.c:463" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000230550 "mdns_avahi.c:224" avahi: service '001124E4D4A8@retro-ppc 4.2' group is registering.
         0.875758725 "mdns_avahi.c:191" avahi: service '001124E4D4A8@retro-ppc 4.2' successfully added.
         0.596766232 "shairport.c:247" soxr_delay: 9874984 nanoseconds, soxr_delay_threshold: 30 milliseconds.
         0.000638260 "shairport.c:254" "soxr" interpolation has been chosen.
        34.258696501 "rtsp.c:774" No active connections.
         0.000617251 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
         0.000255045 "rtsp.c:5610" Connection 1: New connection from 192.168.1.20:49518 to self at 192.168.1.147:7000.
         0.000941213 "rtsp.c:2068" Connection 1: GET /info :: Content-Length 70
         0.000300164 "rtsp.c:2070" GET request
         0.000123532 "rtsp.c:2070"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000151512 "rtsp.c:2070"   Type: "Content-Length", content: "70"
         0.000109422 "rtsp.c:2070"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000139806 "rtsp.c:2070"   Type: "CSeq", content: "0"
         0.000108075 "rtsp.c:2070"   Type: "DACP-ID", content: "7C76B9DE8ADB3ED2"
         0.000103172 "rtsp.c:2070"   Type: "Active-Remote", content: "1453203653"
         0.000345091 "rtsp.c:2070"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.084972800 "rtsp.c:2070"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.001589858 "rtsp.c:1712" GET /info:
         0.000098196 "rtsp.c:1712"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000073797 "rtsp.c:1712"   Type: "Content-Length", content: "70"
         0.000160118 "rtsp.c:1712"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000039471 "rtsp.c:1712"   Type: "CSeq", content: "0"
         0.000028701 "rtsp.c:1712"   Type: "DACP-ID", content: "7C76B9DE8ADB3ED2"
         0.000028894 "rtsp.c:1712"   Type: "Active-Remote", content: "1453203653"
         0.000028245 "rtsp.c:1712"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000154445 "rtsp.c:1712"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>
--
         0.000326750 "rtsp.c:1721" Connection 1: GET_INFO: Source AirPlay Version is: 690.7.1.
         0.000104374 "rtsp.c:1744" GET /info Stage 1: qualifier: txtAirPlay
         0.001253204 "rtsp.c:1826" GET /info Stage 1 Response:
         0.000170190 "rtsp.c:1826"   Response Code: 501.
         0.000110936 "rtsp.c:1826"   Type: "CSeq", content: "0"
         0.000103195 "rtsp.c:1826"   Type: "Server", content: "AirTunes/366.0"
         0.000106730 "rtsp.c:1826"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000278674 "rtsp.c:1826"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>audioLatencies</key>
    <array>
        <dict>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>100</integer>
        </dict>
        <dict>
            <key>audioType</key>
            <string>media</string>
            <key>inputLatencyMicros</key>
            <integer>0</integer>
            <key>outputLatencyMicros</key>
            <integer>400000</integer>
            <key>type</key>
            <integer>102</integer>
        </dict>
    </array>
    <key>keepAliveLowPower</key>
    <true/>
    <key>keepAliveSendStatsAsBody</key>
    <true/>
    <key>manufacturer</key>
    <string>Shairport Sync</string>
    <key>nameIsFactoryDefault</key>
    <false/>
    <key>protocolVersion</key>
    <string>1.1</string>
    <key>sdk</key>
    <string>AirPlay;2.0.2</string>
    <key>sourceVersion</key>
    <string>366.0</string>
    <key>statusFlags</key>
    <integer>4</integer>
    <key>txtAirPlay</key>
    <data>
    BWFjbD0wGmRldmljZWlkPTAwOjExOjI0OmU0OmQ0OmE4G2ZlYXR1cmVzPTB4NDA1QzRB
    MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
    YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
    Ni4wJ3BpPTBjN2I4MDljLThmNzQtNDk1Yi1hOTE3LTRlNmJjNDczYzY5ZShnaWQ9MGM3
    YjgwOWMtOGY3NC00OTViLWE5MTctNGU2YmM0NzNjNjllBmdjZ2w9MENwaz0yNzQ3YjE1
    NmUwZDA4ZmEyYmY0YzY0OTM5NTg2NWQ4MjMzYjgyNmQwYmM0OWYxZDVkN2EyOTRkYjI4
    NWNlYjZl
    </data>
    <key>features</key>
    <integer>496155701824000</integer>
    <key>deviceID</key>
    <string>00:11:24:e4:d4:a8</string>
    <key>pi</key>
    <string>0c7b809c-8f74-495b-a917-4e6bc473c69e</string>
    <key>name</key>
    <string>retro-ppc 4.2</string>
    <key>model</key>
    <string>Shairport Sync</string>
</dict>
</plist>
--
         0.004820198 "rtsp.c:1574" Responding with content of length 911
         0.051776020 "rtsp.c:2228" Connection 1: pair-verify Content-Length 37
         0.047585837 "rtsp.c:2264" pair-verify response
         0.000527012 "rtsp.c:2264"   Response Code: 200.
         0.000241319 "rtsp.c:2264"   Type: "CSeq", content: "1"
         0.000122715 "rtsp.c:2264"   Type: "Server", content: "AirTunes/366.0"
         0.000106873 "rtsp.c:2264"   Type: "Content-Type", content: "application/octet-stream"
         0.000104927 "rtsp.c:2264"   No Content Plist. Content length: 140.
         0.000113796 "rtsp.c:1574" Responding with content of length 140
         0.133658358 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 9
         0.088605707 "rtsp.c:2310" pair-setup response
         0.000494536 "rtsp.c:2310"   Response Code: 200.
         0.000235718 "rtsp.c:2310"   Type: "CSeq", content: "2"
         0.000120071 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
         0.000107522 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
         0.000273506 "rtsp.c:2310"   No Content Plist. Content length: 409.
         0.000141272 "rtsp.c:1574" Responding with content of length 409
         0.060084416 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 457
         0.107492202 "rtsp.c:2310" pair-setup response
         0.000386341 "rtsp.c:2310"   Response Code: 200.
         0.000193171 "rtsp.c:2310"   Type: "CSeq", content: "3"
         0.000115671 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
         0.000107883 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
         0.000105984 "rtsp.c:2310"   No Content Plist. Content length: 69.
         0.000112282 "rtsp.c:1574" Responding with content of length 69
        59.335198531 "rtsp.c:765" Airplay Volume for connection 1 is -24.000000.
         0.000443047 "rtsp.c:776" One active connection.
         0.000059038 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
         0.553991602 "rtsp.c:1376" Connection 1: Connection closed by client.
         0.000416509 "rtsp.c:5029" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
         0.000060840 "rtsp.c:2688" Connection 1: TEARDOWN unspecified stream connection.
         0.000033798 "rtsp.c:5064" Connection 1: terminating -- closing RTSP connection socket 8: from 192.168.1.20:49518 to self at 192.168.1.147:7000.
         0.001077197 "rtsp.c:5127" Connection 1: Closed.
        59.373714805 "rtsp.c:760" Connection 1: deleted in cleanup.
         0.000448167 "rtsp.c:774" No active connections.
         0.000059879 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
        59.909939656 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
mikebrady commented 1 year ago

Thanks for the update. Having eliminated the race condition as a possibility, my suspicion would fall on the fact that it's a big-endian system. Unfortunately, I don't have a big-endian system to hand, so can't really purse this issue at present.

jfdelaune commented 1 year ago

Do you have an idea where I can put debug trace in source code to looking for issue ?

mikebrady commented 1 year ago

(I edited your posts for format, BTW.) Your playback seems to go wrong after the last:

         0.000112282 "rtsp.c:1574" Responding with content of length 69

On my system just now, here is what I get:

         0.010256792 "rtsp.c:2310" pair-setup response
         0.000023125 "rtsp.c:2310"   Response Code: 200.
         0.000003083 "rtsp.c:2310"   Type: "CSeq", content: "3"
         0.000002417 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
         0.000001875 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
         0.000002208 "rtsp.c:2310"   No Content Plist. Content length: 69.
         0.000003583 "rtsp.c:1574" Responding with content of length 69
         0.001584709 "rtsp.c:1574" Responding with content of length 142
         0.001533041 "rtsp.c:1574" Responding with content of length 32
         0.015680084 "rtsp.c:2881" Connection 1: SETUP (AirPlay 2)
         0.000038000 "rtsp.c:2901" Connection 1 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
         0.000005458 "rtsp.c:2914" Connection 1: AP2 PTP connection from fe80::1032:17d4:3eca:9715:53660 ("MacBook Pro") to self at fe80::20c:29ff:fe82:322b:7000.
         0.000015625 "rtsp.c:562" Connection 1: request play lock.
         0.000008833 "rtsp.c:629" Connection 1: Got player lock.

The lines:

         0.001584709 "rtsp.c:1574" Responding with content of length 142
         0.001533041 "rtsp.c:1574" Responding with content of length 32

are response to further RTSP messages from the client. Let me see how to enable debug messages to see what they are...

mikebrady commented 1 year ago

An update to the development branch has just been pushed to increase the level of debug output. Now that sequence above looks like this (verbosity level 2, i.e. -vv):

         0.000004041 "rtsp.c:2228" Connection 1: pair-verify Content-Length 37
         0.000458375 "rtsp.c:2264" pair-verify response
         0.000012542 "rtsp.c:2264"   Response Code: 200.
         0.000003042 "rtsp.c:2264"   Type: "CSeq", content: "1"
         0.000002375 "rtsp.c:2264"   Type: "Server", content: "AirTunes/366.0"
         0.000002291 "rtsp.c:2264"   Type: "Content-Type", content: "application/octet-stream"
         0.000002625 "rtsp.c:2264"   No Content Plist. Content length: 140.
         0.000002459 "rtsp.c:5254" Connection 1: RTSP Response:
         0.000002291 "rtsp.c:5255"   Response Code: 200.
         0.000002375 "rtsp.c:5255"   Type: "CSeq", content: "1"
         0.000015500 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
         0.000002875 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
         0.000002459 "rtsp.c:5255"   No Content Plist. Content length: 140.
         0.000007000 "rtsp.c:1574" Responding with content of length 140
         0.038523333 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
         0.000042250 "rtsp.c:5195"   Type: "X-Apple-HKP", content: "4"
         0.000004958 "rtsp.c:5195"   Type: "X-Apple-Client-Name", content: "MacBook Pro"
         0.000003334 "rtsp.c:5195"   Type: "Content-Length", content: "9"
         0.000003041 "rtsp.c:5195"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000003000 "rtsp.c:5195"   Type: "CSeq", content: "2"
         0.000002584 "rtsp.c:5195"   Type: "DACP-ID", content: "6657E4749458C0D5"
         0.000002708 "rtsp.c:5195"   Type: "Active-Remote", content: "2581877574"
         0.000002625 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000003208 "rtsp.c:5195"   No Content Plist. Content length: 9.
         0.000004542 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 9
         0.011058875 "rtsp.c:2310" pair-setup response
         0.000043750 "rtsp.c:2310"   Response Code: 200.
         0.000005292 "rtsp.c:2310"   Type: "CSeq", content: "2"
         0.000003833 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
         0.000004000 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
         0.000004208 "rtsp.c:2310"   No Content Plist. Content length: 409.
         0.000022667 "rtsp.c:5254" Connection 1: RTSP Response:
         0.000011750 "rtsp.c:5255"   Response Code: 200.
         0.000010292 "rtsp.c:5255"   Type: "CSeq", content: "2"
         0.000010208 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
         0.000011042 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
         0.000010375 "rtsp.c:5255"   No Content Plist. Content length: 409.
         0.000012625 "rtsp.c:1574" Responding with content of length 409
         0.031430333 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
         0.000029167 "rtsp.c:5195"   Type: "X-Apple-HKP", content: "4"
         0.000002625 "rtsp.c:5195"   Type: "X-Apple-Client-Name", content: "MacBook Pro"
         0.000002625 "rtsp.c:5195"   Type: "Content-Length", content: "457"
         0.000001750 "rtsp.c:5195"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000001875 "rtsp.c:5195"   Type: "CSeq", content: "3"
         0.000001708 "rtsp.c:5195"   Type: "DACP-ID", content: "6657E4749458C0D5"
         0.000001833 "rtsp.c:5195"   Type: "Active-Remote", content: "2581877574"
         0.000001750 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000002459 "rtsp.c:5195"   No Content Plist. Content length: 457.
         0.000003916 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 457
         0.007911459 "rtsp.c:2310" pair-setup response
         0.000015208 "rtsp.c:2310"   Response Code: 200.
         0.000002000 "rtsp.c:2310"   Type: "CSeq", content: "3"
         0.000001750 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
         0.000001833 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
         0.000002709 "rtsp.c:2310"   No Content Plist. Content length: 69.
         0.000013250 "rtsp.c:5254" Connection 1: RTSP Response:
         0.000005375 "rtsp.c:5255"   Response Code: 200.
         0.000001666 "rtsp.c:5255"   Type: "CSeq", content: "3"
         0.000001709 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
         0.000009458 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
         0.000006250 "rtsp.c:5255"   No Content Plist. Content length: 69.
         0.000007083 "rtsp.c:1574" Responding with content of length 69
         0.009983042 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
         0.000036375 "rtsp.c:5195"   Type: "X-Apple-ET", content: "32"
         0.000007833 "rtsp.c:5195"   Type: "Content-Length", content: "16"
         0.000005750 "rtsp.c:5195"   Type: "Content-Type", content: "application/octet-stream"
         0.000005750 "rtsp.c:5195"   Type: "CSeq", content: "4"
         0.000005542 "rtsp.c:5195"   Type: "DACP-ID", content: "6657E4749458C0D5"
         0.000010167 "rtsp.c:5195"   Type: "Active-Remote", content: "2581877574"
         0.000006000 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000006166 "rtsp.c:5195"   No Content Plist. Content length: 16.
         0.000011709 "rtsp.c:5254" Connection 1: RTSP Response:
         0.000014583 "rtsp.c:5255"   Response Code: 200.
         0.000005292 "rtsp.c:5255"   Type: "CSeq", content: "4"
         0.000001875 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
         0.000001916 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
         0.000009500 "rtsp.c:5255"   No Content Plist. Content length: 142.
         0.000010292 "rtsp.c:1574" Responding with content of length 142
         0.000732875 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
         0.000013583 "rtsp.c:5195"   Type: "X-Apple-ET", content: "32"
         0.000006042 "rtsp.c:5195"   Type: "Content-Length", content: "164"
         0.000009875 "rtsp.c:5195"   Type: "Content-Type", content: "application/octet-stream"
         0.000005875 "rtsp.c:5195"   Type: "CSeq", content: "5"
         0.000012958 "rtsp.c:5195"   Type: "DACP-ID", content: "6657E4749458C0D5"
         0.000005834 "rtsp.c:5195"   Type: "Active-Remote", content: "2581877574"
         0.000001875 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
         0.000001958 "rtsp.c:5195"   No Content Plist. Content length: 164.
         0.000008750 "rtsp.c:5254" Connection 1: RTSP Response:
         0.000009417 "rtsp.c:5255"   Response Code: 200.
         0.000006083 "rtsp.c:5255"   Type: "CSeq", content: "5"
         0.000009458 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
         0.000009125 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
         0.000005667 "rtsp.c:5255"   No Content Plist. Content length: 32.
         0.000009792 "rtsp.c:1574" Responding with content of length 32

This progression, from the line:

         0.000007083 "rtsp.c:1574" Responding with content of length 69

seems to be absent in your setup. It would be interesting to see your logs with the enhanced debug information...

jfdelaune commented 1 year ago

Mike, I compiled with update

root@fienix:/home/fienix/shairport-sync# ./shairport-sync -vv --statistics 0.000731048 "shairport.c:578" looking for configuration file at full path "/etc/shairport-sync.conf" 0.004407656 "shairport.c:2248" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "00:11:24:e4:d4:a8". 0.000750975 "shairport.c:2287" Version String: "4.2.1d0-5-gc3d99f96-AirPlay2-smi9-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"

same behavior. It seems no packet received ?

     0.004618734 "rtsp.c:1574" Responding with content of length 911
     0.005879319 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
     0.000313145 "rtsp.c:5195"   Type: "X-Apple-HKP", content: "6"
     0.000266510 "rtsp.c:5195"   Type: "X-Apple-Client-Name", content: "MacBook Pro de jean-francois"
     0.000234805 "rtsp.c:5195"   Type: "X-Apple-PD", content: "1"
     0.000042812 "rtsp.c:5195"   Type: "Content-Length", content: "37"
     0.000177593 "rtsp.c:5195"   Type: "Content-Type", content: "application/octet-stream"
     0.000105960 "rtsp.c:5195"   Type: "CSeq", content: "1"
     0.000089182 "rtsp.c:5195"   Type: "DACP-ID", content: "DE262C88D74320D7"
     0.000033100 "rtsp.c:5195"   Type: "Active-Remote", content: "3583411168"
     0.000129470 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
     0.000090239 "rtsp.c:5195"   No Content Plist. Content length: 37.
     0.000042139 "rtsp.c:2228" Connection 1: pair-verify Content-Length 37
     0.004240374 "rtsp.c:2264" pair-verify response
     0.000398721 "rtsp.c:2264"   Response Code: 200.
     0.000301486 "rtsp.c:2264"   Type: "CSeq", content: "1"
     0.000199276 "rtsp.c:2264"   Type: "Server", content: "AirTunes/366.0"
     0.000184180 "rtsp.c:2264"   Type: "Content-Type", content: "application/octet-stream"
     0.000177714 "rtsp.c:2264"   No Content Plist. Content length: 140.
     0.000110984 "rtsp.c:5254" Connection 1: RTSP Response:
     0.000170431 "rtsp.c:5255"   Response Code: 200.
     0.000158074 "rtsp.c:5255"   Type: "CSeq", content: "1"
     0.000118004 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
     0.000108075 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
     0.000206728 "rtsp.c:5255"   No Content Plist. Content length: 140.
     0.000187714 "rtsp.c:1574" Responding with content of length 140
     0.029644521 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
     0.000304923 "rtsp.c:5195"   Type: "X-Apple-HKP", content: "4"
     0.000309563 "rtsp.c:5195"   Type: "X-Apple-Client-Name", content: "MacBook Pro de jean-francois"
     0.000185214 "rtsp.c:5195"   Type: "Content-Length", content: "9"
     0.000129950 "rtsp.c:5195"   Type: "Content-Type", content: "application/x-apple-binary-plist"
     0.000171921 "rtsp.c:5195"   Type: "CSeq", content: "2"
     0.000173291 "rtsp.c:5195"   Type: "DACP-ID", content: "DE262C88D74320D7"
     0.000115119 "rtsp.c:5195"   Type: "Active-Remote", content: "3583411168"
     0.000215646 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
     0.000123532 "rtsp.c:5195"   No Content Plist. Content length: 9.
     0.000171848 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 9
     0.087492237 "rtsp.c:2310" pair-setup response
     0.000441051 "rtsp.c:2310"   Response Code: 200.
     0.000387327 "rtsp.c:2310"   Type: "CSeq", content: "2"
     0.000210454 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
     0.000186800 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
     0.000180358 "rtsp.c:2310"   No Content Plist. Content length: 409.
     0.000112330 "rtsp.c:5254" Connection 1: RTSP Response:
     0.000168820 "rtsp.c:5255"   Response Code: 200.
     0.000157498 "rtsp.c:5255"   Type: "CSeq", content: "2"
     0.000114998 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
     0.000164013 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
     0.000109541 "rtsp.c:5255"   No Content Plist. Content length: 409.
     0.000178027 "rtsp.c:1574" Responding with content of length 409
     0.033328965 "rtsp.c:5193" Connection 1: Received an RTSP Packet of type "POST":
     0.000345020 "rtsp.c:5195"   Type: "X-Apple-HKP", content: "4"
     0.000281486 "rtsp.c:5195"   Type: "X-Apple-Client-Name", content: "MacBook Pro de jean-francois"
     0.000215815 "rtsp.c:5195"   Type: "Content-Length", content: "457"
     0.000187617 "rtsp.c:5195"   Type: "Content-Type", content: "application/x-apple-binary-plist"
     0.000161560 "rtsp.c:5195"   Type: "CSeq", content: "3"
     0.000174253 "rtsp.c:5195"   Type: "DACP-ID", content: "DE262C88D74320D7"
     0.000169252 "rtsp.c:5195"   Type: "Active-Remote", content: "3583411168"
     0.000110576 "rtsp.c:5195"   Type: "User-Agent", content: "AirPlay/690.7.1"
     0.000168555 "rtsp.c:5195"   No Content Plist. Content length: 457.
     0.000177353 "rtsp.c:2272" Connection 1: handle_pair-setup Content-Length 457
     0.106432217 "rtsp.c:2310" pair-setup response
     0.000367039 "rtsp.c:2310"   Response Code: 200.
     0.000389249 "rtsp.c:2310"   Type: "CSeq", content: "3"
     0.000331871 "rtsp.c:2310"   Type: "Server", content: "AirTunes/366.0"
     0.000278481 "rtsp.c:2310"   Type: "Content-Type", content: "application/octet-stream"
     0.000203363 "rtsp.c:2310"   No Content Plist. Content length: 69.
     0.000137258 "rtsp.c:5254" Connection 1: RTSP Response:
     0.000178194 "rtsp.c:5255"   Response Code: 200.
     0.000171585 "rtsp.c:5255"   Type: "CSeq", content: "3"
     0.000168122 "rtsp.c:5255"   Type: "Server", content: "AirTunes/366.0"
     0.000167522 "rtsp.c:5255"   Type: "Content-Type", content: "application/octet-stream"
     0.000110984 "rtsp.c:5255"   No Content Plist. Content length: 69.
     0.000177666 "rtsp.c:1574" Responding with content of length 69
    59.610773907 "rtsp.c:765" Airplay Volume for connection 1 is -24.000000.
     0.000461267 "rtsp.c:776" One active connection.
     0.000060240 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
     0.249101941 "rtsp.c:1376" Connection 1: Connection closed by client.
     0.000342592 "rtsp.c:5029" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
     0.000079854 "rtsp.c:2688" Connection 1: TEARDOWN unspecified stream connection.
     0.000257521 "rtsp.c:5064" Connection 1: terminating -- closing RTSP connection socket 8: from 2a01:cb00:e92:9700:d526:1473:7666:28a4:49587 to self at 2a01:cb00:e92:9700:c0c2:2f3:af77:4bf5:7000.
     0.000938737 "rtsp.c:5127" Connection 1: Closed.
    59.666007716 "rtsp.c:760" Connection 1: deleted in cleanup.
     0.000447855 "rtsp.c:774" No active connections.
     0.000060407 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
    59.932438122 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
    59.916429591 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
    59.908429557 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
    59.909637978 "rtsp.c:781" Airplay Volume for new connections is -24.000000.
mikebrady commented 1 year ago

Thanks. Just to be clear, I was not expecting the behaviour of your code to change, I hoped just to see a little more clearly what is going on. It seems that the client (your MacBook Pro) is not sending a POST command when it should. To me, that indicates that something in the preceding exchange didn't work properly. Your MacBook Pro seems up to date, so I wonder if something is off with the previous transaction -- the pair-setup or even the pair verify. If I had to make a guess, I'd be looking for some big-endian/little-endian issue in there somewhere.

jfdelaune commented 1 year ago

Hello Mike,

I put, on cubietruck board, Owntone server, and I checked log file. So, there is a problem in SETUP phase. 

23-06-08 16:47:04] [DEBUG]  airplay: device_start: Sending GET /info to 'retro-ppc 4.2'
[2023-06-08 16:47:04] [DEBUG]  airplay: Local address: 2a01:cb00:e92:9700:de09:e3c8:cd51:8dbc (LL: no) port 52940
[2023-06-08 16:47:04] [DEBUG]  airplay: Status flags from 'retro-ppc 4.2' was 4: cable attached 1, one time pairing 0, password 0, PIN 0
[2023-06-08 16:47:04] [DEBUG]  airplay: device_start: Sending pair setup 1 to 'retro-ppc 4.2'
[2023-06-08 16:47:05] [DEBUG]  airplay: device_start: Sending pair setup 2 to 'retro-ppc 4.2'
[2023-06-08 16:47:05] [DEBUG]  airplay: Ciphering setup of 'retro-ppc 4.2' completed succesfully, now using encrypted mode
[2023-06-08 16:47:05] [DEBUG]  airplay: pair_success: Sending SETUP (session) to 'retro-ppc 4.2'
[2023-06-08 16:47:20] [ WARN]    event: evrtsp_read: read timeout: Success
[2023-06-08 16:47:20] [  LOG]  airplay: No response to SETUP (session) from 'retro-ppc 4.2'

So, I will check in this phase..

mikebrady commented 1 year ago

Thanks. It's interesting that it says that the ciphering setup is completed successfully. AFAIR, what should happen next is that RTSP messages should be encrypted, so it might be that decryption is failing.

ejurgensen commented 1 year ago

@jfdelaune one thing you could try is connecting with the client-example test tool I made. It's in shairport-sync's source code in the pair_ap folder, and you can build it just with 'make'. Build and run on a little-endian machine and try to connect to shairpoint on the PPC. Use 'transient' mode. As mike writes, testing with big-endian is challenging, so I'm also thinking that is likely cause.

ejurgensen commented 1 year ago

Just noticed that it's not possible to build the tool with 'make' from the subdir, but instead you can get it from here and then build with make.

github-actions[bot] commented 1 year ago

This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.

jfdelaune commented 1 year ago

@ejurgensen , I will try with your tool. Thank you.

github-actions[bot] commented 10 months ago

This issue has been inactive for 28 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.