search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.2k stars 571 forks source link

[Problem]: 100% cpu utilization and crash after network connection is interrupted and device comes back online #1870

Closed tobiashuttinger closed 3 weeks ago

tobiashuttinger commented 3 months ago

What happened?

When streaming from an iOS device to shairport sync in airplay mode 1 and toggling airplane mode mid-stream (or interrupting the connection otherwise, so that iOS switches back to local playback), after reconnecting the client device to the network, shairport-sync ramps up to 100% cpu utilization on one core and crashes shortly afterwards.

This also happens when setting allow_session_interruption to yes and for different values for session_timeout (e.g. 0), with the difference, that shairport-sync doesn't crash but hast 100% cpu indefinitely and no log output. Streaming still works in those cases.

Relevant log output

0.000175840 "shairport.c:2281" Startup in classic Airplay (aka "AirPlay 1") mode.
         0.000014757 "shairport.c:2317" Version String: "4.3.3-libdaemon-OpenSSL-dns_sd-ao-pa-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc/shairport-sync"
         0.000003914 "shairport.c:2336" Command Line: "/usr/local/opt/shairport-sync/bin/shairport-sync --use-stderr --verbose".
         0.000031835 "shairport.c:2372" Log Verbosity is 1.
         0.002263854 "shairport.c:2440" disable_resend_requests is off.
         0.000007639 "shairport.c:2444" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000003584 "shairport.c:2445" statistics_requester status is 0.
         0.000002479 "shairport.c:2447" daemon status is 0.
         0.000002549 "shairport.c:1567" PID file: "/usr/local/var/run/shairport-sync.pid".
         0.000002381 "shairport.c:2448" daemon pid file path is "/usr/local/var/run/shairport-sync.pid".
         0.000002468 "shairport.c:2450" rtsp listening port is 5000.
         0.000002299 "shairport.c:2451" udp base port is 6001.
         0.000002242 "shairport.c:2452" udp port range is 10.
         0.000002230 "shairport.c:2453" player name is "shairport".
         0.000002339 "shairport.c:2454" backend is "ao".
         0.000002214 "shairport.c:2455" run_this_before_play_begins action is "(null)".
         0.000002289 "shairport.c:2456" run_this_after_play_ends action is "(null)".
         0.000015171 "shairport.c:2457" wait-cmd status is 0.
         0.000006808 "shairport.c:2458" run_this_before_play_begins may return output is 0.
         0.000003029 "shairport.c:2460" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000002900 "shairport.c:2462" run_this_before_entering_active_state action is  "(null)".
         0.000002734 "shairport.c:2464" run_this_after_exiting_active_state action is  "(null)".
         0.000002506 "shairport.c:2465" active_state_timeout is  10.000000 seconds.
         0.000002532 "shairport.c:2466" mdns backend "(null)".
         0.000002414 "shairport.c:2471" interpolation setting is "auto".
         0.000002300 "shairport.c:2472" interpolation soxr_delay_threshold is 30000000.
         0.000002473 "shairport.c:2473" resync time is 0.050000 seconds.
         0.000002461 "shairport.c:2474" resync recovery time is 0.100000 seconds.
         0.000002393 "shairport.c:2475" allow a session to be interrupted: 0.
         0.000002374 "shairport.c:2476" busy timeout time is 10.
         0.000002269 "shairport.c:2477" drift tolerance is 0.002000 seconds.
         0.000002405 "shairport.c:2478" password is not set.
         0.000002306 "shairport.c:2479" default airplay volume is: -24.000000.
         0.000002527 "shairport.c:2480" high threshold airplay volume is: -16.000000.
         0.000002556 "shairport.c:2482" check for higher-than-threshold volume for new play session is disabled.
         0.000002388 "shairport.c:2488" ignore_volume_control is 0.
         0.000002283 "shairport.c:2492" volume_max_db is not set
         0.000002241 "shairport.c:2494" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000002511 "shairport.c:2498" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000002573 "shairport.c:2500" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000002452 "shairport.c:2501" disable_synchronization is 0.
         0.000002278 "shairport.c:2502" use_mmap_if_available is 1.
         0.000002263 "shairport.c:2504" output_format automatic selection is enabled.
         0.000002294 "shairport.c:2508" output_rate automatic selection is enabled.
         0.000002349 "shairport.c:2512" audio backend desired buffer length is 1.000000 seconds.
         0.000002465 "shairport.c:2514" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000002573 "shairport.c:2515" audio backend latency offset is 0.000000 seconds.
         0.000002374 "shairport.c:2517" audio backend silence lead-in time is "auto".
         0.000002194 "shairport.c:2521" zeroconf regtype is "_raop._tcp".
         0.000002315 "shairport.c:2522" decoders_supported field is 1.
         0.000002230 "shairport.c:2523" use_apple_decoder is 0.
         0.000002360 "shairport.c:2524" alsa_use_hardware_mute is 0.
         0.000007107 "shairport.c:2528" no special mdns service interface was requested.
         0.000029539 "shairport.c:2532" configuration file name "/usr/local/etc/shairport-sync/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync/shairport-sync.conf".
         0.000005617 "shairport.c:2538" metadata enabled is 1.
         0.000002553 "shairport.c:2539" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000002375 "shairport.c:2541" metadata socket address is "(null)" port 0.
         0.000002305 "shairport.c:2542" metadata socket packet size is "500".
         0.000002272 "shairport.c:2543" get-coverart is 1.
         0.000002174 "shairport.c:2561" loudness is 0.
         0.000002185 "shairport.c:2562" loudness reference level is -20.000000
         0.001120353 "rtsp.c:4235" metadata pipe name is "/tmp/shairport-sync-metadata".
         0.000061262 "rtsp.c:433" Error locking for pc_queue_add_item
         0.000007157 "rtsp.c:419" Error unlocking for pc_queue_add_item or pc_queue_get_item.
         0.000002929 "rtsp.c:433" Error locking for pc_queue_add_item
         0.000002374 "rtsp.c:419" Error unlocking for pc_queue_add_item or pc_queue_get_item.
         0.000024556 "rtsp.c:433" Error locking for pc_queue_add_item
         0.000004114 "rtsp.c:433" Error locking for pc_queue_add_item
         0.000002494 "rtsp.c:419" Error unlocking for pc_queue_add_item or pc_queue_get_item.
         0.000003348 "rtsp.c:433" Error locking for pc_queue_add_item
         1.499022448 "shairport.c:259" "soxr" interpolation has been chosen.
       101.699410674 "rtsp.c:645" Connection 3: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         4.003217569 "rtsp.c:654" *fatal error: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
         0.000036141 "rtsp.c:530" Connection 3: cancelled.
         0.000295442 "shairport.c:1728" emergency exit

System Information.

Client: iPhone with iOS 17 Server: Mac OS 14.5 Sonoma with shairport-sync 4.3.3 via Homebrew

Configuration Information.

general =
{
        output_backend = "ao";
}

sessioncontrol =
{
        allow_session_interruption = "no";
        session_timeout = 10;
        active_state_timeout = 10;
}

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

Homebrew for Mac

Check previous issues

mikebrady commented 3 months ago

Thanks. I'll take a look. As a matter of interest, is the Mac an Apple Silicon Mac or an Intel Mac?

tobiashuttinger commented 3 months ago

It's an intel mac. If you can't reproduce it but want to fix it anyway, please let me know if i can help (testing code, running memory dump, debugger).

mikebrady commented 3 months ago

Hmm, I'm afraid I'm not getting this to happen. Here is my config:

$ shairport-sync -v --statistics
         0.000733119 "shairport.c:2278" Startup in classic Airplay (aka "AirPlay 1") mode.
         0.000035860 "shairport.c:2314" Version String: "4.3.4-dev-15-g0412a840-OpenSSL-dns_sd-ao-stdout-sysconfdir:/usr/local/etc"
         0.000005897 "shairport.c:2333" Command Line: "./shairport-sync -v --statistics".
         0.000003076 "shairport.c:2369" Log Verbosity is 1.
         0.004824154 "shairport.c:2437" disable_resend_requests is off.
         0.000026893 "shairport.c:2441" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000006168 "shairport.c:2442" statistics_requester status is 1.
         0.000002931 "shairport.c:2447" rtsp listening port is 5000.
         0.000002678 "shairport.c:2448" udp base port is 6001.
         0.000002683 "shairport.c:2449" udp port range is 10.
         0.000002668 "shairport.c:2450" player name is "Testmac".
         0.000002758 "shairport.c:2451" backend is "ao".
         0.000002728 "shairport.c:2452" run_this_before_play_begins action is "(null)".
         0.000002751 "shairport.c:2453" run_this_after_play_ends action is "(null)".
         0.000002596 "shairport.c:2454" wait-cmd status is 0.
         0.000002548 "shairport.c:2455" run_this_before_play_begins may return output is 0.
         0.000002671 "shairport.c:2457" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000106843 "shairport.c:2459" run_this_before_entering_active_state action is  "(null)".
         0.000015910 "shairport.c:2461" run_this_after_exiting_active_state action is  "(null)".
         0.000004415 "shairport.c:2462" active_state_timeout is  10.000000 seconds.
         0.000004010 "shairport.c:2463" mdns backend "(null)".
         0.000003910 "shairport.c:2468" interpolation setting is "basic".
         0.000071832 "shairport.c:2469" interpolation soxr_delay_threshold is 30000000.
         0.000012090 "shairport.c:2470" resync time is 0.050000 seconds.
         0.000006073 "shairport.c:2471" resync recovery time is 0.100000 seconds.
         0.000004954 "shairport.c:2472" allow a session to be interrupted: 0.
         0.000003865 "shairport.c:2473" busy timeout time is 120.
         0.000003707 "shairport.c:2474" drift tolerance is 0.002000 seconds.
         0.000003809 "shairport.c:2475" password is not set.
         0.000003824 "shairport.c:2476" default airplay volume is: -24.000000.
         0.000004251 "shairport.c:2477" high threshold airplay volume is: -16.000000.
         0.000005588 "shairport.c:2479" check for higher-than-threshold volume for new play session is disabled.
         0.000005951 "shairport.c:2485" ignore_volume_control is 0.
         0.000004110 "shairport.c:2489" volume_max_db is not set
         0.000003757 "shairport.c:2491" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000003608 "shairport.c:2495" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000003558 "shairport.c:2497" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000003518 "shairport.c:2498" disable_synchronization is 0.
         0.000003216 "shairport.c:2499" use_mmap_if_available is 1.
         0.000036337 "shairport.c:2501" output_format automatic selection is enabled.
         0.000011259 "shairport.c:2505" output_rate automatic selection is enabled.
         0.000006013 "shairport.c:2509" audio backend desired buffer length is 1.000000 seconds.
         0.000006357 "shairport.c:2511" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000006823 "shairport.c:2512" audio backend latency offset is 0.000000 seconds.
         0.000004610 "shairport.c:2514" audio backend silence lead-in time is "auto".
         0.000004435 "shairport.c:2518" zeroconf regtype is "_raop._tcp".
         0.000004815 "shairport.c:2519" decoders_supported field is 1.
         0.000005247 "shairport.c:2520" use_apple_decoder is 0.
         0.000006105 "shairport.c:2521" alsa_use_hardware_mute is 0.
         0.000012341 "shairport.c:2525" no special mdns service interface was requested.
         0.000088090 "shairport.c:2532" configuration file name "/usr/local/etc/shairport-sync.conf" can not be resolved.
         0.000010000 "shairport.c:2558" loudness is 0.
         0.000004440 "shairport.c:2559" loudness reference level is -20.000000

Running macOS Ventura 13.6.7 (the latest it can use) on a 27" 2017 iMac.

The config of Shairport Sync is a bit different; in particular, metadata is not enabled. Would you be kind enough to try building without metadata and see if the problem persists?

(I'll keep digging myself.)

tobiashuttinger commented 3 months ago

Thank you for digging into this!

I tried to build with the same options as you did and with the sample config file, but the error still occurs. Also I noticed the Unix System Calls and Process Switches counts in activity monitor go completely crazy once the cpu time is 100%.

./shairport-sync -v --statistics
         0.000699258 "shairport.c:2281" Startup in classic Airplay (aka "AirPlay 1") mode.
         0.000016477 "shairport.c:2317" Version String: "4.3.4-dev-OpenSSL-dns_sd-ao-stdout-sysconfdir:/usr/local/etc/shairport-sync"
         0.000003870 "shairport.c:2336" Command Line: "./shairport-sync -v --statistics".
         0.000002559 "shairport.c:2372" Log Verbosity is 1.
         0.004336634 "shairport.c:2440" disable_resend_requests is off.
         0.000007116 "shairport.c:2444" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000003344 "shairport.c:2445" statistics_requester status is 1.
         0.000002505 "shairport.c:2450" rtsp listening port is 5000.
         0.000002351 "shairport.c:2451" udp base port is 6001.
         0.000002334 "shairport.c:2452" udp port range is 10.
         0.000002275 "shairport.c:2453" player name is "Tobimac".
         0.000002433 "shairport.c:2454" backend is "ao".
         0.000002330 "shairport.c:2455" run_this_before_play_begins action is "(null)".
         0.000002417 "shairport.c:2456" run_this_after_play_ends action is "(null)".
         0.000002335 "shairport.c:2457" wait-cmd status is 0.
         0.000002237 "shairport.c:2458" run_this_before_play_begins may return output is 0.
         0.000002609 "shairport.c:2460" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000002624 "shairport.c:2462" run_this_before_entering_active_state action is  "(null)".
         0.000002264 "shairport.c:2464" run_this_after_exiting_active_state action is  "(null)".
         0.000002383 "shairport.c:2465" active_state_timeout is  10.000000 seconds.
         0.000002472 "shairport.c:2466" mdns backend "(null)".
         0.000002337 "shairport.c:2471" interpolation setting is "basic".
         0.000002356 "shairport.c:2472" interpolation soxr_delay_threshold is 30000000.
         0.000002306 "shairport.c:2473" resync time is 0.050000 seconds.
         0.000002500 "shairport.c:2474" resync recovery time is 0.100000 seconds.
         0.000002396 "shairport.c:2475" allow a session to be interrupted: 0.
         0.000002474 "shairport.c:2476" busy timeout time is 120.
         0.000002239 "shairport.c:2477" drift tolerance is 0.002000 seconds.
         0.000002493 "shairport.c:2478" password is not set.
         0.000002407 "shairport.c:2479" default airplay volume is: -24.000000.
         0.000002484 "shairport.c:2480" high threshold airplay volume is: -16.000000.
         0.000002597 "shairport.c:2482" check for higher-than-threshold volume for new play session is disabled.
         0.000002396 "shairport.c:2488" ignore_volume_control is 0.
         0.000002350 "shairport.c:2492" volume_max_db is not set
         0.000002368 "shairport.c:2494" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000002475 "shairport.c:2498" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000002624 "shairport.c:2500" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000002531 "shairport.c:2501" disable_synchronization is 0.
         0.000002189 "shairport.c:2502" use_mmap_if_available is 1.
         0.000002289 "shairport.c:2504" output_format automatic selection is enabled.
         0.000002261 "shairport.c:2508" output_rate automatic selection is enabled.
         0.000002496 "shairport.c:2512" audio backend desired buffer length is 1.000000 seconds.
         0.000002459 "shairport.c:2514" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000002766 "shairport.c:2515" audio backend latency offset is 0.000000 seconds.
         0.000002393 "shairport.c:2517" audio backend silence lead-in time is "auto".
         0.000002197 "shairport.c:2521" zeroconf regtype is "_raop._tcp".
         0.000002441 "shairport.c:2522" decoders_supported field is 1.
         0.000002298 "shairport.c:2523" use_apple_decoder is 0.
         0.000002178 "shairport.c:2524" alsa_use_hardware_mute is 0.
         0.000002366 "shairport.c:2528" no special mdns service interface was requested.
         0.000017756 "shairport.c:2532" configuration file name "/usr/local/etc/shairport-sync/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync/shairport-sync.conf".
         0.000003896 "shairport.c:2561" loudness is 0.
         0.000002279 "shairport.c:2562" loudness reference level is -20.000000
       140.222129153 "rtsp.c:645" Connection 1: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         4.004061899 "rtsp.c:654" *fatal error: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
         0.000033788 "rtsp.c:530" Connection 1: cancelled.
         0.000288527 "shairport.c:1728" emergency exit

My next steps would be to try on a fresh install of Mac OS Ventura as well as Sonoma and see if it works then. I'll try this over the next days.

mikebrady commented 3 months ago

Well, I have found something. Let me look at it...

mikebrady commented 3 months ago

So, I found a bug and pushed a fix [I hope!] in the development branch. If you got a chance to test it and report back, it would be appreciated!

tobiashuttinger commented 3 months ago

Amazing, that fixed the error and it works perfectly now!

mikebrady commented 3 months ago

Thanks for the feedback, and indeed thanks for the bug report. BTW, I've just made the session timeout two minutes by default -- one minute seems to be a bit short.

github-actions[bot] commented 1 month 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.