[core] Service thread startup/stop race with timer-driven playback can cause 100% CPU and prevent session teardown

[sinalvee]

Describe the bug

With timer_name=soft, a short playback can finish before its audio service thread has completed startup. A controlled scheduling-delay test on FreeSWITCH 1.11.2 reproduced a service thread consuming approximately one CPU core indefinitely, with a channel remaining in show channels after hangup while uuid_exists returns false.

The suspected race is between switch_core_service_thread() setting CF_SERVICE and switch_core_thread_session_end() clearing the service flags. The worker can set CF_SERVICE after the stop request has cleared CF_SERVICE_AUDIO and CF_SERVICE_VIDEO, leaving the worker in a loop with neither audio/video work nor a wait/exit path.

Reproduction boundary: ordinary local playback tests did not reproduce this naturally. The positive reproduction below deliberately delays the worker at a specific startup point. It demonstrates the problematic interleaving in the real binary, but does not establish its frequency under normal scheduling.

Source analysis and workaround limitations

Suspected interleaving

The relevant code is in switch_core.c. Timer-driven playback starts and stops this worker in switch_ivr_play_say.c.

1. switch_core_service_session_av() sets CF_SERVICE_AUDIO and launches the worker asynchronously.
2. The worker acquires the session read lock and frame_read_mutex, then is delayed before setting CF_SERVICE.
3. The short timer-driven playback finishes. switch_core_thread_session_end() clears CF_SERVICE, CF_SERVICE_AUDIO, and CF_SERVICE_VIDEO, and sends SWITCH_SIG_BREAK.
4. The delayed worker resumes and sets CF_SERVICE again.
5. Its loop sees CF_SERVICE set, but both audio/video work flags cleared. Neither conditional branch runs; there is no wait or exit check for this state.
6. The worker keeps spinning while holding the locks acquired during startup, preventing normal session teardown.

This sequence is inferred from the source and controlled scheduling experiment; I did not capture a live dump of all three flag values.

Why simply unsetting timer_name is not sufficient for our use case

In a separate local RTP test, I sent PCMU packets containing 60 ms of audio every 60 ms while SDP advertised ptime:20. Playing a 1-second WAV and then hanging up took approximately:

• 1.919–1.920 seconds with timer_name unset;
• 1.019–1.020 seconds with timer_name=soft.

Each case was repeated three times. With matching 20 ms RTP and SDP, both variants took approximately one second. These measurements are from SIP answer to receipt of BYE, including small signaling overhead; they are not an end-to-end bridged audio-latency measurement.

Therefore, removing independent playback timing is not a complete workaround in this packetization-mismatch scenario.

Maintainer guidance requested

Could you confirm whether the service-thread startup/stop synchronization is intended to prevent this interleaving, or whether a fix already exists elsewhere?

A fix appears to need coordination between startup and stop so a late worker cannot overwrite a completed stop request. I have not implemented or validated a patch yet. Adding a sleep to the empty loop would reduce CPU consumption but would not by itself resolve the stale worker or session teardown problem.

To Reproduce

Steps to reproduce the behavior in an isolated local instance:

1. Prepare a short audio file and dialplan

Generate a 20 ms, mono, 8 kHz, signed 16-bit PCM WAV and make it available at /tmp/service-race-20ms.wav inside the test container:

import math
import struct
import wave

with wave.open('/tmp/service-race-20ms.wav', 'wb') as wav:
    wav.setparams((1, 2, 8000, 0, 'NONE', 'not compressed'))
    wav.writeframes(b''.join(
        struct.pack('<h', int(8000 * math.sin(2 * math.pi * 440 * i / 8000)))
        for i in range(160)
    ))

Add the following extension to the context used by a local SIP profile:

<extension name="service-race">
  <condition field="destination_number" expression="^service-race$">
    <action application="answer"/>
    <action application="set" data="timer_name=soft"/>
    <action application="playback" data="/tmp/service-race-20ms.wav"/>
    <action application="hangup" data="NORMAL_CLEARING"/>
  </condition>
</extension>

2. Delay the service worker at startup

The injection point is after the worker acquires the session read lock and frame_read_mutex, but before it sets CF_SERVICE:

/* switch_core_service_thread(), abbreviated */
switch_core_session_read_lock(session);
switch_mutex_lock(session->frame_read_mutex);

channel = switch_core_session_get_channel(session); /* inject delay here */

switch_channel_set_flag(channel, CF_SERVICE);

In the tested binary, I used an LD_PRELOAD shim to delay this particular call to switch_core_session_get_channel() by 200 ms. The shim does not alter any channel flags or the function's return value.

Exact fault-injection shim used in the local test

#define _GNU_SOURCE
#include <dlfcn.h>
#include <stdint.h>
#include <stdio.h>
#include <unistd.h>

void *switch_core_session_get_channel(void *session)
{
    void *(*real)(void *) = dlsym(RTLD_NEXT, "switch_core_session_get_channel");
    void *caller = __builtin_return_address(0);
    Dl_info info;

    if (dladdr(caller, &info) &&
        (uintptr_t)caller - (uintptr_t)info.dli_fbase == 0xa2d49) {
        fprintf(stderr,
                "AB_DELAY service thread acquired locks; pause 200ms\n");
        usleep(200000);
    }
    return real(session);
}

Compile with:

gcc -shared -fPIC -O2 -o service-race-delay.so service-race-delay.c -ldl

Start the isolated FreeSWITCH process with LD_PRELOAD pointing to that library.

The return-address offset 0xa2d49 was verified by disassembly for this particular binary. It is not portable, even to a different build of the same source revision. Verify the call site in your own binary before using this shim; otherwise it may not inject any delay or may target the wrong call. A source-level delay at the equivalent location is another way to exercise the interleaving, but that variant was not used in my test.

3. Place one local call

Using a test SIP profile listening on 127.0.0.1:5080 and routing to the extension above, run this from fs_cli inside the isolated container. Replace TEST_PROFILE with that profile's name:

originate {originate_timeout=3,absolute_codec_string=PCMA}sofia/TEST_PROFILE/service-race@127.0.0.1:5080 &park()

The tested profile permits this local call without authentication. No external SIP endpoint is needed.

Confirm the AB_DELAY marker was emitted, then inspect CPU usage and channels after the short playback has ended:

show channels as json
uuid_exists RESIDUAL_UUID

For the control run, use a fresh isolated instance with the same injection and replace the dialplan's set timer_name=soft action with:

<action application="unset" data="timer_name"/>

Expected behavior

Once the playback cleanup requests that the service thread stop, a delayed worker must not reactivate itself. It should release its locks and exit, allowing normal session teardown.

Package version or git hash

• FreeSWITCH 1.11.2 -release-31326320293-3f13ad1b1d.
• Linux x86-64, Debian-based Docker image.
• Isolated test containers: --network none, no published ports, 1 CPU, 384 MB RAM.
• SIP/RTP traffic stays on 127.0.0.1 inside each container.
• SIP codec for the race test: PCMA, 8 kHz.
• SIP profile retains rtp-timer-name=soft in both A/B variants. The variable being changed is the channel variable timer_name.

I also compared src/switch_core.c at 3f13ad1b1d and tag v1.11.3; the files were byte-identical. I have not run this reproduction on v1.11.3 or current master.

Trace logs

The available capture contains INFO/NOTICE and application execution output; a full DEBUG trace with per-line UUID logging was not collected in this run. The excerpts below are from the isolated reproduction, not a production call. Profile and audio-file names have been normalized to match the reproduction instructions; the UUID is from the local test.

2026-09-15 14:04:46.242455 93.17% [NOTICE] switch_channel.c:1143 New Channel sofia/TEST_PROFILE/0000000000@127.0.0.1 [3ffff3c0-785a-4ef7-ab5a-0304c067e2e0]
EXECUTE [depth=0] sofia/TEST_PROFILE/0000000000@127.0.0.1 set(timer_name=soft)
EXECUTE [depth=0] sofia/TEST_PROFILE/0000000000@127.0.0.1 playback(/tmp/service-race-20ms.wav)
EXECUTE [depth=0] sofia/TEST_PROFILE/0000000000@127.0.0.1 hangup(NORMAL_CLEARING)
2026-09-15 14:04:46.262447 93.17% [NOTICE] mod_dptools.c:1374 Hangup sofia/TEST_PROFILE/0000000000@127.0.0.1 [CS_EXECUTE] [NORMAL_CLEARING]

The injection marker was also present in captured stderr (shown separately because stdout/stderr ordering is not a synchronized execution trace):

AB_DELAY service thread acquired locks; pause 200ms

Channel state and CPU observations

Test	Result
timer_name=soft, 200 ms startup delay	First short call left one residual channel; CPU remained approximately 96–99% of one core across repeated samples
timer_name unset, same injection library	Three short calls completed and reclaimed all channels; idle CPU approximately 0.2–0.4%
No injected delay, either timer setting	28 playback/digit-collection tests and 12 playback interruption/hangup tests all reclaimed their channels

The residual channel had the following fields (excerpt):

{
  "state": "CS_EXECUTE",
  "application": "hangup",
  "application_data": "NORMAL_CLEARING"
}

uuid_exists returned false for that same UUID. The log contained the injection marker and a NORMAL_CLEARING hangup, but the channel remained listed. The affected test container continued consuming approximately one core until it was removed.

For the channel UUID 3ffff3c0-785a-4ef7-ab5a-0304c067e2e0 above:

uuid_exists 3ffff3c0-785a-4ef7-ab5a-0304c067e2e0
false

The final Docker CPU sample for the affected container was 99.03%, with show channels as json still reporting one row. The same sample for the control instance with timer_name unset was 0.21%, with zero channel rows.

backtrace from core file

No core-file backtrace is available. This reproduction caused sustained CPU spinning and incomplete session teardown, not a process crash. No core dump or full GDB thread backtrace was collected in this run. The source-level interleaving above is an analysis supported by the controlled delay, not a captured backtrace.