[BUG] CRITICAL:dialog:_unref_dlg: bogus ref -2 with cnt 1 for dlg

[wphowell]

OpenSIPS version you are running

version: opensips 3.6.3 (aarch64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, HP_MALLOC, F_PARALLEL_MALLOC, DBG_MALLOC, USE_POSIX_SEM
MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: d5222226a
main.c compiled on 10:40:33 Dec 24 2025 with cc 12

Describe the bug

To Reproduce

Expected behavior

Relevant System Logs

OS/environment information

• Operating System:
• OpenSIPS installation:
• other relevant information: Linux a003.hcs-hosted.com 6.1.0-41-cloud-arm64 Dummy ticket #1 SMP Debian 6.1.158-1 (2025-11-09) aarch64 GNU/Linux

Additional context

[NormB]

We were able to reproduce this crash on an ARM64 test VM (QEMU aarch64, Debian 12) using unmodified OpenSIPS master source — SIGSEGV within minutes under load. The crash signature matches yours: bogus ref -1 on the same dialog from two workers simultaneously, followed by use-after-free in dlg_release_cloned_leg.

We've submitted a proposed fix in #3836. Summary of our findings below.

Root Cause

We believe this is a race between BYE processing and dlg_ontimeout() when bye_on_timeout is enabled (create_dialog("B")). Two independent race paths:

1. Timer removal outside lock: next_state_dlg() transitions the dialog to DELETED and releases the hash entry lock before the caller performs remove_dlg_timer(). A concurrent worker can observe state=DELETED and begin cleanup, racing with the caller's timer removal — resulting in a double-free of the timer ref.

2. Stale state read in timer handler: dlg_ontimeout() reads dlg->state at three locations without the hash entry lock. On ARM64's relaxed memory ordering, these reads can return a stale CONFIRMED value after a BYE worker has already set DELETED under the lock. The timer handler then enters the bye_on_timeout path on a dialog that is already being torn down.

Both races are architecture-sensitive — ARM64's relaxed memory ordering makes them significantly more likely than on x86_64, which is consistent with your experience on Graviton.

Note: the DLG_FLAG_RACE_CONDITION_OCCURRED mechanism (the "E" flag you tried) addresses a different race at the SIP signaling level (CANCEL/200-OK overlap). It wouldn't help with this refcount race.

Race window diagram

Worker A (BYE handler):                     Worker B (timer handler):
----------------------------                ----------------------------------
                                            dlg_ontimeout() fires
                                            reads dlg->state WITHOUT hash lock
                                            sees state=CONFIRMED (stale on ARM64)

next_state_dlg(REQBYE)
  lock(hash_entry)
  state: CONFIRMED -> DELETED
  unref = 1
  unlock(hash_entry)
                                            still using stale CONFIRMED state
  +--- race window ---+                     enters bye_on_timeout path
  |  caller-side       |                    dlg_end_dlg() sends BYEs
  |  timer removal     |                    unref_dlg(dlg, 1)
  |  and unref not     |                      ^-- timer ref consumed
  |  yet performed     |
  +--------------------+

remove_dlg_timer()    <-- returns 0 (success) or races
unref_dlg(dlg, unref) <-- double-free of timer ref -> "bogus ref -1"

Proposed Fix

A two-part fix (PR #3836). In our testing, neither part alone was sufficient — both are needed to cover all race windows.

1. Timer removal inside lock (dlg_hash.c): Move remove_dlg_timer() inside next_state_dlg()'s lock scope so the timer is removed atomically with the DELETED state transition. Removes duplicate timer-removal blocks from all four callers.

2. Locked state read in dlg_ontimeout() (dlg_handlers.c): Read dlg->state under the hash entry lock into a local variable. The lock acquire/release provides the memory barriers needed for ARM64 cache coherency.

Net change: +45/−91 lines across 4 files. No behavioral changes to existing call flows, no configuration changes needed.

ARM64 reproduction results

Tested on QEMU aarch64 VM (Debian 12, 2 vCPUs, 2GB RAM) with unmodified master source (commit aad6b85). High worker count (32) on 2 vCPUs, 2s dialog timeout, SIPp BYE timed ~100ms before timeout, stress-ng for CPU/memory/IO pressure, taskset pinning timer + workers to same CPU core.

Run	Patch	Workers	CPS	Duration	Result
1	None	16	100	~3 min	SIGSEGV at ~20k calls
2	None	32	200	1m55s	SIGSEGV at ~15k calls
3	Part 1 only	32	200	~2 min	SIGABRT (same root cause)
4	Part 1 + Part 2	32	200	15 min	No crash (~180k calls)
5	Part 1 + Part 2	32	200	76 min	No crash (~920k calls)

Crash backtrace from unpatched runs:

#0  qm_frag_size (p=0x6e6f3d32723b) at mem/q_malloc.h:192
#1  _shm_free (ptr=..., file="dlg_handlers.c",
       function="dlg_release_cloned_leg", line=506)
#2  dlg_release_cloned_leg (dlg=0xffff96e2e230) at dlg_handlers.c:506
#3  push_reply_in_dialog (...) at dlg_handlers.c:570
#4  dlg_onreply (t=..., type=8) at dlg_handlers.c:665
#5  run_trans_callbacks (...) at t_hooks.c:233
#6  relay_reply (..., msg_status=200) at t_reply.c:1322

GDB inspection confirmed use-after-free: dialog at the crash address had state=EARLY(1), ref=2 — a completely different dialog occupying reused shared memory.

Caveat: these results are from a QEMU-emulated ARM64 environment, not production hardware. The crashes are consistent with the reported issue, but testing on production ARM64 under real traffic patterns would provide additional confidence.

We'd welcome feedback from the maintainers on the approach. Happy to provide additional details or adjust the fix.

[NormB]

Supporting Evidence and Reproduction Details

Below are the additional appendices from our analysis — simulation, nanosleep instrumentation, reproduction steps, test configurations, and limitations.

---

Refcount walkthrough (normal BYE, pre-fix crash, post-fix safe)

Normal BYE (with proposed fix):

Initial:  ref=3 (base + hash + timer)

next_state_dlg(REQBYE):
  lock(hash_entry)
  state: CONFIRMED -> DELETED
  remove_dlg_timer() succeeds -> unref++ (now unref=2: hash + timer)
  unlock(hash_entry)

dlg_onroute():
  unref_dlg(dlg, 2)  -> ref goes 3 -> 1 (base ref remains for TM callback)

TM callback:
  next_state_dlg(TDEL):
    state: DELETED -> DELETED
    unref = 1 (TM ref)
  unref_dlg(dlg, 1)  -> ref goes 1 -> 0 -> destroy

BYE + Timer race (current code, the crash):

Initial:  ref=3 (base + hash + timer)

Worker A - next_state_dlg(REQBYE):
  lock(hash_entry)
  state: CONFIRMED -> DELETED
  unref = 1 (hash only -- timer not removed yet!)
  unlock(hash_entry)
                                    Worker B - dlg_ontimeout():
  [race window]                     reads state=CONFIRMED (stale/pre-lock)
                                    enters bye_on_timeout path
                                    dlg_end_dlg() sends BYEs
                                    unref_dlg(dlg, 1) -> ref 3 -> 2
                                    (consumed timer ref)

Worker A - dlg_onroute():
  remove_dlg_timer() -> returns 0 (timer already dequeued by timer wheel)
  unref++ -> unref=2 (hash + timer... but timer ref already consumed!)
  unref_dlg(dlg, 2)  -> ref 2 -> 0 -> premature destroy

Worker B - bye_reply_cb:
  accesses freed dialog -> SIGSEGV
  or: unref_dlg -> "bogus ref -1"

BYE + Timer race (with proposed fix, safe):

Initial:  ref=3 (base + hash + timer)

Worker A - next_state_dlg(REQBYE):
  lock(hash_entry)
  state: CONFIRMED -> DELETED
  remove_dlg_timer() succeeds -> unref=2 (hash + timer, both under lock)
  unlock(hash_entry)
                                    Worker B - dlg_ontimeout():
                                    lock(hash_entry)
                                    reads state=DELETED (correct)
                                    unlock(hash_entry)
                                    does NOT enter bye_on_timeout path

Worker A - dlg_onroute():
  (no timer removal -- already done under lock)
  unref_dlg(dlg, 2)  -> ref 3 -> 1 (base ref remains for TM callback)

TM callback:
  next_state_dlg(TDEL): unref = 1
  unref_dlg(dlg, 1)  -> ref 1 -> 0 -> clean destroy

Correlation with reporter's environment

The reporter (GH-3835) runs OpenSIPS 3.6.x on AWS Graviton (aarch64) and sees:

• _unref_dlg: bogus ref -1 / bogus ref -2 from two workers on the same dialog
• SIGSEGV crashes 1-2 times per week under production load

Our test environment crashes match this signature:

• Same crash path: push_reply_in_dialog → dlg_release_cloned_leg → shm_free on freed memory
• Same architecture sensitivity: crashes on ARM64 (aarch64), difficult to reproduce on x86_64
• Same precondition: create_dialog("B") enabling BYEONTIMEOUT

Key differences: our testing uses QEMU-emulated ARM64 (not bare-metal Graviton), synthetic SIPp load (not production traffic), and an artificially tight BYE-vs-timeout window. The reporter's production environment will have different timing characteristics. We believe the root cause is the same, but the maintainers and the reporter are best positioned to evaluate whether the proposed fix matches their production observations.

Appendix A: Direct race simulation (x86_64)

Approach: Inject code into next_state_dlg() that directly simulates a concurrent worker stealing the timer ref and hash ref after the lock is released but before the caller performs its cleanup.

Instrumentation added after dlg_unlock() in next_state_dlg(), REQBYE case:

/* Race simulation: after unlock, a concurrent "worker" steals
 * the timer ref + hash ref before caller can clean up */
if (*old_state != DLG_STATE_DELETED && *new_state == DLG_STATE_DELETED) {
    /* Simulate concurrent worker removing timer */
    int sim_ret = remove_dlg_timer(&dlg->tl);
    if (sim_ret == 0) {
        /* Timer successfully removed by "other worker" -- steal the ref */
        _unref_dlg(dlg, 1);  /* concurrent timer ref theft */
    }
    /* Simulate concurrent worker removing from hash */
    _unref_dlg(dlg, 1);  /* concurrent hash ref theft */
}

Test: 20 SIP calls (INVITE → BYE) against OpenSIPS 4.0.0-dev on x86_64.

Result (without fix):

CRITICAL:dialog:_unref_dlg: bogus ref -1 with cnt 1 for dlg 0x7f796002a418
CRITICAL:core:sig_usr: segfault in process pid: 530691, id: 3

OpenSIPS crashed. 0 processes remaining.

Result (with Part 1 applied):

All 20 calls completed. The simulated racer's remove_dlg_timer() returned >0 (timer already removed under lock). Zero "bogus ref" messages. OpenSIPS stable with 8/8 processes running.

This simulation validates that Part 1 closes Race Path 1. It does not exercise Race Path 2, which requires actual concurrent timer firing on ARM64.

Appendix B: nanosleep reproduction (x86_64)

Approach: Use nanosleep() instrumentation to widen the race window to observable timescales, then use SIPp to generate call flows where the BYE and dialog timer fire within the widened window.

Location	Delay	Purpose
dlg_hash.c:1290 in next_state_dlg(), REQBYE case, before dlg->state = DLG_STATE_DELETED	nanosleep(3s)	Hold hash lock with state=CONFIRMED for 3 seconds during BYE→DELETED transition
dlg_handlers.c:2166 in dlg_onroute(), after remove_dialog_from_db()	nanosleep(10s)	Delay BYE handler's final unref so timer handler completes first

Timeline (from syslog):

02:45:46  INVITE -> dialog 0x7ff40cdddff0 created, link_dlg ref=3
02:45:52  ACK -> state 4->4 (CONFIRMED, re-INVITE guard)
02:45:55  BYE -> Worker 546082 enters next_state_dlg, acquires hash lock
          nanosleep(3s) begins -- lock held, state still CONFIRMED
02:45:57  TIMER FIRES -> Worker 546085 enters dlg_ontimeout
          "byeontimeout ? flags = 24607, state = 4"  <-- STALE READ
          Worker blocked on hash lock (or reads stale CONFIRMED)
02:45:58  BYE handler wakes, state 4->5 (CONFIRMED->DELETED), unlocks
02:45:59  Timer handler proceeds, calls dlg_end_dlg -> sends BYEs to both legs
02:46:00  BYE handler completes, relays BYE to UAS
          bye_reply_cb x2 (200 OK responses for bye_on_timeout BYEs)
          UAC receives unexpected second BYE from bye_on_timeout (CSeq:3)
02:46:06  Dialog destroyed via final TM timer unref

Key observation: dlg_ontimeout: byeontimeout ? flags = 24607, state = 4 — state = 4 = DLG_STATE_CONFIRMED, read WITHOUT hash lock while the BYE handler holds it. This demonstrates that dlg_ontimeout() can proceed with a stale state value.

Why no crash in this test: The deterministic nanosleep() gaps ensure the timer fully completes its path before the BYE handler wakes. The actual crash requires microsecond-level interleaving where remove_dlg_timer() races with the timer dequeue itself.

Limitations and open questions

We want to be transparent about the boundaries of our testing:

1. QEMU vs. bare-metal ARM64: Our reproduction uses QEMU aarch64 with Apple HVF. QEMU's memory ordering behavior may differ from bare-metal Graviton in subtle ways. While the crashes are consistent with the reported issue, testing on production ARM64 hardware would provide stronger confirmation.

2. Cluster replication paths: We tested only the local BYE and timer paths. The dlg_replicated_delete() and drop_dlg() callers had their timer removal blocks removed (same pattern), but we did not test with dialog replication enabled. Maintainers with cluster test environments may want to verify these paths.

3. Lock contention under high load: Part 2 adds a lock/unlock pair at the top of dlg_ontimeout(). Under very high dialog timeout rates, this could add contention on the hash entry lock. In our testing (~200 cps with 2s timeouts), we observed no measurable impact, but production environments with thousands of concurrent dialogs may behave differently.

4. Other dlg->state readers: We addressed the unprotected reads in dlg_ontimeout(). We did not audit every other location in the codebase where dlg->state is read without the hash lock. There may be other code paths with similar ARM64 visibility issues.

5. Single test environment: While the soak test (76 min, ~920k calls) provides reasonable confidence, all testing was done in one QEMU VM configuration. Testing across different ARM64 hardware, kernel versions, or OpenSIPS configurations would strengthen confidence further.

6. DLG_FLAG_RACE_CONDITION_OCCURRED interaction: The existing SIP-level race handling (CANCEL/200-OK via create_dialog("E")) uses dlg_ontimeout() with shortened timeouts. Our fix protects this path too, but we did not specifically test the E-flag scenario.

How to reproduce

Quick-start for reproducing the crash on an ARM64 system (bare-metal or QEMU). Full SIPp scenarios and OpenSIPS config are in the next section.

# 1. Build OpenSIPS from master (commit aad6b85 or later, UNPATCHED)
make -j$(nproc) && make install

# 2. Set up core dumps
ulimit -c unlimited
echo "/tmp/core.%e.%p.%t" > /proc/sys/kernel/core_pattern  # or sysctl

# 3. Start OpenSIPS (config must use create_dialog("B"), dialog timeout 2s)
opensips -f /usr/local/etc/opensips/opensips.cfg

# 4. Start SIPp UAS (callee side, port 5080)
sipp -sf uas.xml -p 5080 -i 127.0.0.1 &

# 5. Start SIPp UAC (caller side, targets OpenSIPS on 5060)
sipp -sf uac_race.xml 127.0.0.1:5060 -p 5070 -i 127.0.0.1 \
     -r 200 -l 800 -d 1900 -trace_err

# 6. Add CPU pressure (optional but increases race probability)
stress-ng --cpu 2 --vm 2 --io 2 &

# 7. Pin timer + workers to same CPU (key for triggering the race)
#    Find opensips PIDs, then:
#    taskset -p 0x1 <timer_pid>
#    taskset -p 0x1 <worker_pid_1> <worker_pid_2> ...

# 8. Monitor for crash
watch -n5 'pgrep -c opensips; ls /tmp/core.opensips.* 2>/dev/null'

# 9. On crash, analyze core dump
gdb /usr/local/sbin/opensips /tmp/core.opensips.<pid>.<timestamp>
# (gdb) bt
# Look for: push_reply_in_dialog -> dlg_release_cloned_leg -> shm_free

In our testing, crashes occurred within 2-3 minutes at 200 cps with 32 workers on 2 vCPUs. Lower call rates or fewer workers may require longer runs.

Appendix C: Test configurations (SIPp scenarios + OpenSIPS config)

UAC scenario (uac_race.xml):

<?xml version="1.0" encoding="ISO-8859-1" ?>
<!DOCTYPE scenario SYSTEM "sipp.dtd">
<scenario name="UAC race trigger for GH-3835">
  <send retrans="500">
    <![CDATA[
      INVITE sip:race@[remote_ip]:[remote_port] SIP/2.0
      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
      From: "Race UAC" <sip:uac@[local_ip]:[local_port]>;tag=[pid]SIPpTag[call_number]
      To: <sip:race@[remote_ip]:[remote_port]>
      Call-ID: [call_id]
      CSeq: 1 INVITE
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Max-Forwards: 70
      Content-Type: application/sdp
      Content-Length: [len]

      v=0
      o=sipp 1 1 IN IP[local_ip_type] [local_ip]
      s=SIPp UAC
      c=IN IP[local_ip_type] [local_ip]
      t=0 0
      m=audio [media_port] RTP/AVP 0
      a=rtpmap:0 PCMU/8000
    ]]>
  </send>
  <recv response="100" optional="true"/>
  <recv response="180" optional="true"/>
  <recv response="200" rtd="true" crlf="true" rrs="true"/>
  <send>
    <![CDATA[
      ACK [next_url] SIP/2.0
      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
      From: "Race UAC" <sip:uac@[local_ip]:[local_port]>;tag=[pid]SIPpTag[call_number]
      [last_To:]
      Call-ID: [call_id]
      CSeq: 1 ACK
      [routes]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Max-Forwards: 70
      Content-Length: 0
    ]]>
  </send>
  <!-- Pause controlled by -d flag (1900ms for 2s timeout) -->
  <pause/>
  <send retrans="500">
    <![CDATA[
      BYE [next_url] SIP/2.0
      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
      From: "Race UAC" <sip:uac@[local_ip]:[local_port]>;tag=[pid]SIPpTag[call_number]
      [last_To:]
      Call-ID: [call_id]
      CSeq: 2 BYE
      [routes]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Max-Forwards: 70
      Content-Length: 0
    ]]>
  </send>
  <recv response="200" optional="false" timeout="5000"/>
</scenario>

UAS scenario (uas.xml):

<?xml version="1.0" encoding="ISO-8859-1" ?>
<!DOCTYPE scenario SYSTEM "sipp.dtd">
<scenario name="UAS for GH-3835 race test">
  <recv request="INVITE" crlf="true"/>
  <send>
    <![CDATA[
      SIP/2.0 180 Ringing
      [last_Via:]
      [last_Record-Route:]
      [last_From:]
      [last_To:];tag=[pid]SIPpTag[call_number]
      [last_Call-ID:]
      [last_CSeq:]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Content-Length: 0
    ]]>
  </send>
  <pause milliseconds="100"/>
  <send retrans="500">
    <![CDATA[
      SIP/2.0 200 OK
      [last_Via:]
      [last_Record-Route:]
      [last_From:]
      [last_To:];tag=[pid]SIPpTag[call_number]
      [last_Call-ID:]
      [last_CSeq:]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Content-Type: application/sdp
      Content-Length: [len]

      v=0
      o=sipp 1 1 IN IP[local_ip_type] [local_ip]
      s=SIPp UAS
      c=IN IP[local_ip_type] [local_ip]
      t=0 0
      m=audio [media_port] RTP/AVP 0
      a=rtpmap:0 PCMU/8000
    ]]>
  </send>
  <recv request="ACK" optional="false" crlf="true"/>
  <recv request="BYE" crlf="true"/>
  <send>
    <![CDATA[
      SIP/2.0 200 OK
      [last_Via:]
      [last_From:]
      [last_To:]
      [last_Call-ID:]
      [last_CSeq:]
      Content-Length: 0
    ]]>
  </send>
</scenario>

OpenSIPS config (opensips.cfg):

udp_workers=32
log_level=3
stderror_enabled=no
syslog_enabled=yes
syslog_facility=LOG_LOCAL0
socket=udp:127.0.0.1:5060
disable_dns_blacklist=yes
mpath="/usr/local/lib64/opensips/modules/"

loadmodule "proto_udp.so"
loadmodule "signaling.so"
loadmodule "sl.so"
loadmodule "tm.so"
loadmodule "rr.so"
loadmodule "sipmsgops.so"
loadmodule "dialog.so"

modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("dialog", "default_timeout", 2)
modparam("dialog", "db_mode", 0)
modparam("rr", "enable_double_rr", 1)

route {
    if (!has_totag()) {
        if (is_method("INVITE")) {
            create_dialog("B");
            record_route();
        }
        $du = "sip:127.0.0.1:5080";
        t_relay();
        exit;
    }
    if (loose_route()) {
        t_relay();
        exit;
    }
    sl_send_reply(404, "Not Found");
}

[wphowell]

We had tried this emergency patch to get our production environment stable, but this did not resolve the issue.

2521,2523d2520
<
< struct dlg_entry *d_entry = &(d_table->entries[dlg->h_entry]);
< int local_state;
2525,2528d2521
< dlg_lock(d_table, d_entry);
< local_state = dlg->state;
< dlg_unlock(d_table, d_entry);
<
2530c2523
< (local_state==DLG_STATE_CONFIRMED_NA || local_state==DLG_STATE_CONFIRMED)) {

(dlg->state==DLG_STATE_CONFIRMED_NA || dlg->state==DLG_STATE_CONFIRMED)) {

[NormB]

I reproduced this on ARM64 and validated PR #3836 against the 3.6 branch. The affected code (dlg_ontimeout and next_state_dlg) is identical between 3.6.3 and 3.6.4, so the patch applies cleanly to either. The fix eliminates the crash completely under sustained load.

One thing I noticed — the diff in your comment above only shows the dlg_handlers.c portion of PR #3836 (Fix B). The full fix also includes a change to dlg_hash.c (Fix A) which moves remove_dlg_timer() inside next_state_dlg's lock scope. Both parts are needed to fully close the race. The backport patch below includes both.

Test Environment

• Platform: Debian 12 aarch64 (QEMU with HVF acceleration)
• OpenSIPS: 3.6 branch, udp_workers=32, default_timeout=1
• Config: create_dialog("B") to enable DLG_FLAG_BYEONTIMEOUT
• SIPp UAC: 200 CPS, 200k calls, BYE sent at 900ms (racing the 1s dialog timeout)
• SIPp UAS: 200 OK with retrans="500" (retransmits every 500ms until ACK — maximizes timing pressure)

Results

Build	Calls	Crashes	Workers alive
Unpatched	~24k	2 core dumps in ~2 min	5/36
PR #3836 (Fix A + Fix B)	200k	0	36/36

The unpatched baseline crashes consistently within 1-2 minutes. With the full PR #3836 backport applied, the 200k-call soak test completes cleanly with zero crashes and all 36 worker processes intact.

Crash analysis (unpatched baseline)

Every crash follows the same pattern — dlg_ontimeout reads dlg->state without the entry lock, sees a stale CONFIRMED value on ARM64's weakly-ordered memory, then enters the bye_on_timeout path for a dialog that another worker has already transitioned to DELETED and freed:

#0  fm_remove_free (pf = 0x656361723a706973)   <- "sip:race" -- freed memory reused for SIP data
#1  fm_free
#2  _shm_free (file="dlg_hash.c", line=183)
#3  free_dlg_dlg (dlg=0x...)                    <- dialog struct contains data from a NEW dialog
#4  destroy_dlg
#5  _unref_dlg (cnt=1)
#6  dlg_onreply (type=TMCB_TRANS_DELETED)       <- TM cleanup fires on stale pointer
#7  unreference_dialog_create
#8  empty_tmcb_list                              <- INVITE transaction being freed
#9  free_cell
#10 wait_handler                                 <- TM wait timer

The freed dialog memory at the crash address consistently shows state=1 (EARLY), ref=2 — a completely different dialog that reused the shared memory allocation.

3.6 backport patch

Here's the backport of both fixes from PR #3836, applicable to 3.6.3 and 3.6.4:

diff --git a/modules/dialog/dlg_handlers.c b/modules/dialog/dlg_handlers.c
index 481df72..055de00 100644
--- a/modules/dialog/dlg_handlers.c
+++ b/modules/dialog/dlg_handlers.c
@@ -2454,11 +2454,23 @@ void dlg_ontimeout(struct dlg_tl *tl)
 	int new_state;
 	int old_state;
 	int unref;
+	int dlg_state;
 	int do_expire_actions = 1;
+	struct dlg_entry *d_entry;

 	dlg = get_dlg_tl_payload(tl);

-	LM_DBG("byeontimeout ? flags = %d , state = %d\n",dlg->flags,dlg->state);
+	/* Read state under the dialog entry lock to ensure memory
+	 * visibility of concurrent state changes (GH-3835).  On architectures
+	 * with weak memory ordering (e.g. ARM64), an unlocked read may return
+	 * a stale value, causing the timeout handler to act on an
+	 * already-transitioned dialog. */
+	d_entry = &(d_table->entries[dlg->h_entry]);
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
+
+	LM_DBG("byeontimeout ? flags = %d , state = %d\n",dlg->flags,dlg_state);

 	if (dialog_repl_cluster) {
 		/* if dialog replication is used, send BYEs only if the current node
@@ -2470,7 +2482,7 @@ void dlg_ontimeout(struct dlg_tl *tl)
 		 * the dialog. We this self prolonging only once! */
 		if (!do_expire_actions
 		&& ref_script_route_check_and_update(dlg->rt_on_timeout)
-		&& dlg->state<DLG_STATE_DELETED
+		&& dlg_state<DLG_STATE_DELETED
 		&& !(dlg->flags&DLG_FLAG_SELF_EXTENDED_TIMEOUT)) {
 			LM_DBG("self prolonging with 10 mins to see what the active"
 				"decides after the on-timeout route\n");
@@ -2493,7 +2505,7 @@ void dlg_ontimeout(struct dlg_tl *tl)

 	if (do_expire_actions
 	&& ref_script_route_check_and_update(dlg->rt_on_timeout)
-	&& dlg->state<DLG_STATE_DELETED) {
+	&& dlg_state<DLG_STATE_DELETED) {
 		struct dlg_tl bk_tl = *tl;
 		/* allow the dialog to be re-inserted in the timer list */
 		tl->next = tl->prev = NULL;
@@ -2520,7 +2532,7 @@ void dlg_ontimeout(struct dlg_tl *tl)
 	}

 	if ((dlg->flags&DLG_FLAG_BYEONTIMEOUT) &&
-	(dlg->state==DLG_STATE_CONFIRMED_NA || dlg->state==DLG_STATE_CONFIRMED)) {
+	(dlg_state==DLG_STATE_CONFIRMED_NA || dlg_state==DLG_STATE_CONFIRMED)) {

 		if (do_expire_actions) {
 			if (dlg->flags & DLG_FLAG_RACE_CONDITION_OCCURRED)
diff --git a/modules/dialog/dlg_hash.c b/modules/dialog/dlg_hash.c
index 79609cb..39f6ae2 100644
--- a/modules/dialog/dlg_hash.c
+++ b/modules/dialog/dlg_hash.c
@@ -1335,6 +1335,23 @@ void next_state_dlg(struct dlg_cell *dlg, int event, int dir, int *old_state,
 	}
 	*new_state = dlg->state;

+	/* Remove dialog timer under lock to prevent race with concurrent
+	 * unref (GH-3835): if we transitioned to DELETED, remove the timer
+	 * atomically with the state change so no other worker can see
+	 * state=DELETED and race to unref before timer cleanup */
+	if (*old_state != DLG_STATE_DELETED && *new_state == DLG_STATE_DELETED) {
+		int ret = remove_dlg_timer(&dlg->tl);
+		if (ret == 0)
+			(*unref)++;
+		else if (ret < 0)
+			LM_CRIT("unable to unlink the timer on dlg %p [%u:%u] "
+				"with clid '%.*s' and tags '%.*s' '%.*s'\n",
+				dlg, dlg->h_entry, dlg->h_id,
+				dlg->callid.len, dlg->callid.s,
+				dlg_leg_print_info(dlg, DLG_CALLER_LEG, tag),
+				dlg_leg_print_info(dlg, callee_idx(dlg), tag));
+	}
+
 	dlg_unlock( d_table, d_entry);

 	if (*old_state != *new_state)

To apply: save as gh3835.patch in the opensips source root and run git apply gh3835.patch.

Race condition mechanics

The race requires create_dialog("B") (which sets DLG_FLAG_BYEONTIMEOUT) and a BYE arriving close to the dialog timeout:

1. Worker A processes the BYE -> next_state_dlg(REQBYE) transitions state to DELETED under the entry lock, sets unref=1 (hash)
2. Timer handler fires dlg_ontimeout -> reads dlg->state without the entry lock
3. On ARM64 (weakly-ordered memory), the timer handler can see the stale CONFIRMED value
4. Timer handler enters the bye_on_timeout path -> calls dlg_end_dlg -> unref_dlg
5. Both workers race to unref -> dialog freed while still referenced -> SIGSEGV

Fix A (dlg_hash.c): Moves remove_dlg_timer() inside next_state_dlg's lock scope, so the timer is removed atomically with the state transition. This prevents the timer from firing after state reaches DELETED.

Fix B (dlg_handlers.c): Reads dlg->state under the entry lock in dlg_ontimeout and caches it in a local variable. This ensures the timer handler sees the current state on weakly-ordered architectures, so it correctly skips processing when a BYE worker has already transitioned the dialog.

Both fixes are needed — Fix A handles the case where the timer fires before the BYE is processed, Fix B handles the case where the timer handler is already running when the BYE transitions the state.

The 3.6 backport patch above applies cleanly to both 3.6.3 and 3.6.4. Happy to help test further if needed.

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[NormB]

Waiting on feedback @wphowell

[wphowell]

We did add the full patch as described in 196b51f.

Unfortunately, we did see a crash occur yesterday. Here are those logs:

2026-03-26T15:57:04.253952+00:00 a003 /usr/local/sbin/opensips[2444050 ERROR:core:parse_uri: bad char '@' in state 0 parsed: sip: (4) / sip:@sbc.hcs-hosted.com (23)
2026-03-26T15:57:04.253969+00:00 a003 /usr/local/sbin/opensips[2444050 ERROR:core:parse_sip_msg_uri: bad uri sip:@sbc.hcs-hosted.com
2026-03-26T15:57:04.253984+00:00 a003 /usr/local/sbin/opensips[2444050 ERROR:presence:handle_publish: parsing Request URI
2026-03-26T15:57:04.254242+00:00 a003 /usr/local/sbin/opensips[2444051 NOTICE:incoming reply
2026-03-26T15:57:04.254317+00:00 a003 /usr/local/sbin/opensips[2444050 NOTICE:FROM kamailio: received PUBLISH request.
2026-03-26T15:57:04.818261+00:00 a003 /usr/local/sbin/opensips[2444049 CRITICAL:dialog:_unref_dlg: bogus ref -1 with cnt 1 for dlg 0xffff7c77f848 [1450:874264682] with clid 'a91c3b95-dc3e-4f59-a2d4-7c2ab0a23993' and tags '0851d6a7-3807-4feb-9dd7-f0410bbd33a7' 'of0fjl676q'
2026-03-26T15:57:04.824460+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:handle_sigs: child process 2444049 exited by a signal 6
2026-03-26T15:57:04.824505+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:handle_sigs: core was not generated
2026-03-26T15:57:04.824523+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:handle_sigs: terminating due to SIGCHLD
2026-03-26T15:57:04.824609+00:00 a003 /usr/local/sbin/opensips[2444043 INFO:core:sig_usr: signal 15 received
2026-03-26T15:57:04.824699+00:00 a003 /usr/local/sbin/opensips[2444044 INFO:core:sig_usr: signal 15 received
2026-03-26T15:57:04.837924+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 14(2444055) [SIP receiver udp:10.0.8.248:5061] terminated, still waiting for 14 more
2026-03-26T15:57:04.838776+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 2(2444043) [time_keeper] terminated, still waiting for 13 more
2026-03-26T15:57:04.839832+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 11(2444052) [SIP receiver udp:10.0.8.248:5060] terminated, still waiting for 12 more
2026-03-26T15:57:04.840170+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 12(2444053) [SIP receiver udp:10.0.8.248:5061] terminated, still waiting for 11 more
2026-03-26T15:57:04.840462+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 13(2444054) [SIP receiver udp:10.0.8.248:5061] terminated, still waiting for 10 more
2026-03-26T15:57:04.844324+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 1(2444042) [MI FIFO] terminated, still waiting for 9 more
2026-03-26T15:57:04.844774+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 4(2444045) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 8 more
2026-03-26T15:57:04.844800+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 5(2444046) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 7 more
2026-03-26T15:57:04.845076+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 7(2444048) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 6 more
2026-03-26T15:57:04.845560+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 9(2444050) [SIP receiver udp:10.0.8.248:5060] terminated, still waiting for 5 more
2026-03-26T15:57:04.846472+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 16(2444057) [Timer handler] terminated, still waiting for 4 more
2026-03-26T15:57:04.847057+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 3(2444044) [timer] terminated, still waiting for 3 more
2026-03-26T15:57:04.847381+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 6(2444047) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 2 more
2026-03-26T15:57:04.848006+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 15(2444056) [SIP receiver udp:10.0.8.248:5061] terminated, still waiting for 1 more
2026-03-26T15:57:04.848386+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:shutdown_opensips: process 10(2444051) [SIP receiver udp:10.0.8.248:5060] terminated, still waiting for 0 more
2026-03-26T15:57:04.848414+00:00 a003 /usr/local/sbin/opensips[2444041 INFO:core:cleanup: cleanup
2026-03-26T15:57:04.849552+00:00 a003 /usr/local/sbin/opensips[2444041 NOTICE:presence:destroy: destroy module ...
2026-03-26T15:57:04.927138+00:00 a003 opensips[2444041]: Thank you for running opensips
2026-03-26T15:57:04.933731+00:00 a003 systemd[1]: opensips.service: Main process exited, code=exited, status=6/NOTCONFIGURED
2026-03-26T15:57:04.933779+00:00 a003 systemd[1]: opensips.service: Failed with result 'exit-code'.
2026-03-26T15:57:04.933898+00:00 a003 systemd[1]: opensips.service: Consumed 16min 39.511s CPU time.
2026-03-26T15:57:05.080636+00:00 a003 systemd[1]: opensips.service: Scheduled restart job, restart counter is at 1.
2026-03-26T15:57:05.080745+00:00 a003 systemd[1]: Stopped opensips.service - OpenSIPS is a very fast and flexible SIP (RFC3261) server.
2026-03-26T15:57:05.080769+00:00 a003 systemd[1]: opensips.service: Consumed 16min 39.511s CPU time.

[NormB]

Third race path in dlg_ontimeout (post-fix crash)

The cached dlg_state variable goes stale between the initial locked read (Fix B) and the critical decision points further down the function. Between the initial read and the DLG_FLAG_BYEONTIMEOUT check, a BYE can arrive on another worker and transition the dialog to DLG_STATE_DELETED.

Race timeline:

Timer thread                          BYE worker
============                          ==========
dlg_ontimeout() fires
  lock → read state=CONFIRMED → unlock
  [cluster check, etc.]
                                      BYE arrives
                                      next_state_dlg(REQBYE):
                                        lock
                                        state = DELETED
                                        remove_dlg_timer → ret>0 (dequeued)
                                        unlock
                                      unref_dlg(1) [hash ref]
                                      (dialog ref now = 1, only timer ref left)

  cached dlg_state still == CONFIRMED
  enters bye_on_timeout path:
    dlg_end_dlg() → sends BYEs via TM
    unref_dlg(1) [timer ref] → ref drops to 0 → destroy

  TM callbacks from dlg_end_dlg fire
  → access freed dialog memory → "bogus ref -1"

Why Fix A + Fix B are insufficient:

Fix A correctly prevents the BYE worker from consuming the timer ref. But it does not prevent the timer from using its stale cached state to enter a code path it should not.

Fix B prevents stale reads due to ARM64 relaxed memory ordering at the TOP of the function. But the value is cached once and used much later — any state change between the read and the action is invisible.

Fix: Re-read dlg->state under the hash lock immediately before each critical decision:

--- a/modules/dialog/dlg_handlers.c
+++ b/modules/dialog/dlg_handlers.c
@@ -2487,6 +2487,15 @@ void dlg_ontimeout(struct dlg_tl *tl)
 		}
 	}
 
+	/* Re-read state under lock before running on_timeout route.
+	 * The cached dlg_state from the top of this function may be stale
+	 * if a BYE arrived between our initial read and now - a concurrent
+	 * worker may have transitioned the dialog to DELETED.
+	 * (GH-3835, third race path) */
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
+
 	if (do_expire_actions
 	&& ref_script_route_check_and_update(dlg->rt_on_timeout)
 	&& dlg_state<DLG_STATE_DELETED) {
@@ -2515,6 +2524,17 @@ void dlg_ontimeout(struct dlg_tl *tl)
 		 * here, as the following code will do this for us later */
 	}
 
+	/* Re-check state under lock immediately before acting on it.
+	 * The cached dlg_state may be stale if a BYE worker transitioned
+	 * the dialog to DELETED between our initial read and now.  Without
+	 * this re-read, the timer handler enters the bye_on_timeout path,
+	 * calls dlg_end_dlg() + unref, while the BYE worker also completes
+	 * its unref chain - resulting in "bogus ref -1 with cnt 1".
+	 * (GH-3835, third race path) */
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
+
 	if ((dlg->flags&DLG_FLAG_BYEONTIMEOUT) &&
 	(dlg_state==DLG_STATE_CONFIRMED_NA || dlg_state==DLG_STATE_CONFIRMED)) {

This patch applies on top of commit 196b51fa.

Reproduction: Instrumented build with 500ms delay between initial state read and action — 4 out of 100 calls hit the race window (state changed from CONFIRMED to DELETED during the delay). With the re-read fix, all 4 races were caught and the stale-state paths were skipped. 1000-call stress test at 50 CPS with the clean fix: zero bogus refs, zero crashes.

Full combined patch (Fix A + Fix B + third race fix)

To apply: save as gh3835-combined.patch in the opensips source root and run git apply gh3835-combined.patch. This applies to 3.6.x and master.

diff --git a/modules/dialog/dlg_handlers.c b/modules/dialog/dlg_handlers.c
index abc123..def456 100644
--- a/modules/dialog/dlg_handlers.c
+++ b/modules/dialog/dlg_handlers.c
@@ dlg_onroute - remove caller-side timer removal (now done under lock in next_state_dlg)
 
-		/* remove from timer */
-		ret = remove_dlg_timer(&dlg->tl);
-		if (ret < 0) {
-			LM_CRIT("unable to unlink the timer on dlg %p [%u:%u] "
-			...
-		} else if (ret > 0) {
-			LM_DBG("dlg expired (not in timer list) on dlg %p [%u:%u] "
-			...
-		} else {
-			/* dialog successfully removed from timer -> unref */
-			unref++;
-		}
-
@@ dlg_ontimeout - locked state read + re-reads before critical decisions

 void dlg_ontimeout(struct dlg_tl *tl)
 {
+	struct dlg_entry *d_entry;
 	int new_state, old_state, unref;
 	int do_expire_actions = 1;
+	int dlg_state;
 
 	dlg = get_dlg_tl_payload(tl);
+	d_entry = &(d_table->entries[dlg->h_entry]);
+
+	/* Initial state read under lock (Fix B - ARM64 visibility) */
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
 
 	/* ... cluster checks using dlg_state ... */
 
+	/* Re-read before rt_on_timeout (third race fix) */
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
+
 	if (do_expire_actions
 	&& ref_script_route_check_and_update(dlg->rt_on_timeout)
-	&& dlg->state<DLG_STATE_DELETED) {
+	&& dlg_state<DLG_STATE_DELETED) {
 
 	/* ... on_timeout route handling ... */
 
+	/* Re-read before bye_on_timeout (third race fix) */
+	dlg_lock(d_table, d_entry);
+	dlg_state = dlg->state;
+	dlg_unlock(d_table, d_entry);
+
 	if ((dlg->flags&DLG_FLAG_BYEONTIMEOUT) &&
-	(dlg->state==DLG_STATE_CONFIRMED_NA || dlg->state==DLG_STATE_CONFIRMED)) {
+	(dlg_state==DLG_STATE_CONFIRMED_NA || dlg_state==DLG_STATE_CONFIRMED)) {

See commit 196b51fa for the complete Fix A (dlg_hash.c) and Fix B changes, plus the removal of redundant caller-side timer removal from dlg_replication.c and dlg_req_within.c.

[NormB]

@wphowell Interesting that I am seeing both opensips and kamailio in the logs:

NOTICE:FROM kamailio: received PUBLISH request.

patch updated.

It is important to note that the fix reduces the window of the problem because the state can be changed between the unlock and the if statement on the very next line. While not impossible to happen, the likelihood of the failure is greatly reduced. A redesign of bye_on_timeout will be needed to completely eliminate the chance of a race. Perhaps this will happen with the new 4.0 codebase that is under heavy development.