[LBBS-121] mod_asterisk_queues: Memory corruption or use after free in agent list

← All Issues || New Issue →

Sort Normal || Priority

Details

---

Referencing Issues

[LBBS-120] mod_asterisk_ami: NULL dereference possible if ami_session is currently NULL

---

This crash has been observed on two different occasions, though not in close proximity, so this is not a frequent crash, but does seem consistent.

The logs make it clear that something like this happens:

• ami_callback(): An incoming operator call gives us an QueueCallerJoin event
• We call new_call(), which iterates the calls list and calls call_is_dead() for each of them to check if it's dead
• call_is_dead() finds a dead call with the same call ID (typically 0) and calls mark_dead(), setting call->dead to 1
• ami_callback(): We then get an AgentCalled event which calls agent_printf()
• agent_printf() iterates the agents list, and some agent in the loop is invalid memory (confirmed by gdb)

What's strange is that there seems to be some kind old stale call in the calls list, but what causes the crash is an invalid agent in the agents list.

Here is another recent occurence of this issue:

[2026-02-08 01:45:04.665]   DEBUG[3099452]: mod_asterisk_queues.c:571 ami_callback: Processing queue event 'QueueCallerJoin'
[2026-02-08 01:45:04.668]   DEBUG[3099452]: mod_asterisk_queues.c:502 new_call: Added call from '2310112' (Local/0@phreaknet-operators-00009a26;2) to queue 'phreaknet-operator' as call 0
[2026-02-08 01:45:04.670]   DEBUG[3099452]: mod_asterisk_queues.c:571 ami_callback: Processing queue event 'AgentCalled'
Segmentation fault (core dumped)

Thread 1 (Thread 0x7f39ce3896c0 (LWP 3099452)):
#0  0x00007f39cf0f0149 in agent_printf (queue=0x7f39c803afe0, member_name=0x7f39c442be40 "980", fmt=0x7f39cf0f446f "%s\r%s%-15s %-22s %15s\n") at mod_asterisk_queues.c:526
        buf = 0x7f39c40daa40 "\033[0m\r\aACD RING        OPERATOR", ' ' <repeats 23 times>, "2310112\n"
        len = 61
        ap = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f39ce288cb0, reg_save_area = 0x7f39ce288be0}}
        agent = 0xd2
        agent_id = 980
        __func__ = "agent_printf"
#1  0x00007f39cf0f0727 in ami_callback (e=0x7f39c40f9520, eventname=0x7f39c4803f40 "AgentCalled") at mod_asterisk_queues.c:601
        callerid = 0x7f39c48af530 "2310112"
        member_name = 0x7f39c442be40 "980"
        queue_name = 0x7f39c4007e90 "phreaknet-operator"
        queue = 0x7f39c803afe0
        __func__ = "ami_callback"
#2  0x00007f39cf795e3b in ami_callback (ami=0x559519ddc590, event=0x7f39c40f9520) at mod_asterisk_ami.c:218

(gdb) print agent
$1 = (struct agent *) 0xd2
(gdb) print agents
$2 = {first = 0x7f39c0645310, last = 0x7f39c000ad20, lock = {lock = {__data = {__readers = 8, __writers = 0, __wrphase_futex = 0, __writers_futex = 0, __pad3 = 0, __pad4 = 0, __cur_writer = 0,
        __shared = 0, __rwelision = 0 '\000', __pad1 = "\000\000\000\000\000\000", __pad2 = 0, __flags = 0}, __size = "\b", '\000' <repeats 54 times>, __align = 8}, intlock = {__data = {__lock = 0,
        __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, info = {
      initialized = 1, staticinit = 1, destroyed = 0, owners = 1, lastlocked = 1770515104, lwp = 3099452, lineno = 522, filename = "mod_asterisk_queues.c\000\000"}}}
(gdb) print agents.first
$4 = (struct agent *) 0x7f39c0645310
(gdb) print *agents.first
$5 = {id = 884, node = 0x7f39c48aef80, idle = 1, gotwritten = 0, stale = 0, entry = {next = 0x7f39c8122d30}}
(gdb) print (*agents.first).entry
$6 = {next = 0x7f39c8122d30}
(gdb) print (*agents.first).entry.next
$7 = (struct agent *) 0x7f39c8122d30
(gdb) print *((*agents.first).entry.next)
$8 = {id = 231, node = 0x7f39c02e30d0, idle = 1, gotwritten = 0, stale = 0, entry = {next = 0x7f39bc23bb50}}
(gdb) print *((*agents.first).entry.next).entry.next
$9 = {id = 1335238491, node = 0xbc71f11fc8dc52f7, idle = 0, gotwritten = 1, stale = 0, entry = {next = 0xd2}}

Here, id, node, and entry.next are all bogus, so it's not specifically the current agent that is invalid, but the previous agent in the list whose entry.next points to it. How that entry got to be that way (whether it was previously valid and then freed but not removed from the list, etc.) is the mystery now.

More complete logs filed at X:\Development\LBBS-121.txt - from these additional logs it seems a call comes into the agent, who handles the call, but does NOT return to the main menu before the second call comes in, i.e. the call becomes dead while the agent is in a submenu.

(m:ss)
2:33 IAX2/phreaknet-13486 calls 0
2:38 Answers
2:46 press l
2:48 choose call 0
2:58 Choose [S] option and key number, hit ENTER
LBBS/asterisk merged timeline:

3:05 Far end answers
3:08 far end hangs up
3:09 caller gets disconnected

3:16 press ENTER
3:16 IAX2/phreaknet-78 calls 0 using 231 DISA
3:19 press l
3:23 answers
3:27 choose call 0
3:31 choose option 3 ([S])
3:46 enter number and hit ENTER. do not touch terminal from now on
3:58 xfer complete
4:06 caller gets disconnected

4:11 IAX2/phreaknet-16132 calls 0 (crash)

Reproducing 3:16-4:11 sequence does give similar log results:
[2025-09-27 09:02:27.480]   DEBUG[32945]: mod_asterisk_queues.c:571 ami_callback: Processing queue event 'QueueCallerJoin'
[2025-09-27 09:02:27.554]   DEBUG[32945]: mod_asterisk_queues.c:397 call_is_dead: Marking queue call 0 as dead: IAX2/phreaknet-14122
[2025-09-27 09:02:27.554]   DEBUG[32945]: mod_asterisk_queues.c:502 new_call: Added call from 'REDACTED' (IAX2/phreaknet-10052) to queue 'phreaknet-operator' as call 0

[2025-09-26 20:03:17.485]   DEBUG[83287]: mod_asterisk_queues.c:495 new_call: Added call from '8848537' (IAX2/phreaknet-78) to queue 'phreaknet-operator' as call 0
...
[2025-09-26 20:04:11.945]   DEBUG[83287]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'QueueCallerJoin'
[2025-09-26 20:04:11.947]   DEBUG[83287]: mod_asterisk_queues.c:361 __mark_dead: Marking queue call 0 as dead: IAX2/phreaknet-78
[2025-09-26 20:04:11.947]   DEBUG[83287]: mod_asterisk_queues.c:495 new_call: Added call from '8848537' (IAX2/phreaknet-16132) to queue 'phreaknet-operator' as call 0
[2025-09-26 20:04:11.948]   DEBUG[83287]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'AgentCalled'
Segmentation fault (core dumped)

Thread 1 (Thread 0x7f489ee486c0 (LWP 83287)):
#0  0x00007f48a058b0ca in agent_printf (queue=0x5623b503d550, member_name=0x7f4894085760 "791", fmt=0x7f48a058f40f "%s\r%s%-15s %-22s %15s\n") at mod_asterisk_queues.c:519
        buf = 0x7f4890006120 "\033[0m\r\aACD RING        OPERATOR", ' ' <repeats 23 times>, "8848537\n"
        len = 61
        ap = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f489ed47cb0, reg_save_area = 0x7f489ed47be0}}
        agent = 0x51858d6eaed7cf55
        agent_id = 791
        __func__ = "agent_printf"
#1  0x00007f48a058b6ba in ami_callback (e=0x7f4894087040, eventname=0x7f48940049a0 "AgentCalled") at mod_asterisk_queues.c:594
        callerid = 0x7f489400bef0 "8848537"
        member_name = 0x7f4894085760 "791"
        queue_name = 0x7f4894011490 "phreaknet-operator"
        queue = 0x5623b503d550
        __func__ = "ami_callback"
#2  0x00007f48a0c866b3 in ami_callback (ami=0x5623b5039a60, event=0x7f4894087040) at mod_asterisk_ami.c:115
        res = -1
        cb = 0x5623b503deb0
        do_reload = 0
        eventname = 0x7f48940049a0 "AgentCalled"
        __func__ = "ami_callback"
#3  0x00007f48a0877c86 in ami_event_dispatch (varg=0x5623b5039a60) at cami.c:806
        bytes_used = <optimized out>
        start = 0x7f489ed47ea0 "Event: AgentCalled\r\nPrivilege: agent,all\r\nTimestamp: 1758917051.950755\r\nSystemName: ARTNVAAXCG0\r\nChannel: IAX2/phreaknet-16132\r\nChannelState: 4\r\nChannelStateDesc: Ring\r\nCallerIDNum: 8848537\r\nCallerIDN"...
        end = 0x7f489ed4826a ""
        fds = {fd = 16, events = 1, revents = 1}
        event = <optimized out>
        res = 971
        buf = Python Exception <class 'gdb.error'>: value requires 1048576 bytes, which is more than max-value-size
#4  0x00007f48a0f1f1f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139949880149696, 5120490681186163102, -136, 25, 140732927007232, 139949871759360, -5071441385835685474, -5071366787108529762}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#5  0x00007f48a0f9f8dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Normal call (for comparison):
[2025-09-26 20:30:15.509]   DEBUG[15891]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'QueueCallerJoin'
[2025-09-26 20:30:15.596]   DEBUG[15891]: mod_asterisk_queues.c:495 new_call: Added call from '2703330' (IAX2/phreaknet-1029) to queue 'phreaknet-operator' as call 0
[2025-09-26 20:30:15.596]   DEBUG[15891]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'AgentCalled'
...
[2025-09-26 20:30:15.596]   DEBUG[15891]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'AgentCalled'
[2025-09-26 20:30:20.329]   DEBUG[15891]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'QueueCallerAbandon'
[2025-09-26 20:30:20.330]   DEBUG[15891]: mod_asterisk_queues.c:361 __mark_dead: Marking queue call 0 as dead: IAX2/phreaknet-1029
[2025-09-26 20:30:20.330]   DEBUG[15891]: mod_asterisk_queues.c:564 ami_callback: Processing queue event 'QueueCallerLeave'

This non-crashing deadlock(?) is possibly related?

[2025-10-06 19:40:50.815] WARNING[369356]: mod_asterisk_queues.c:206 del_agent: Spent 91 seconds so far waiting to wrlock &agents, possible deadlock? (rwlock acquired at mod_asterisk_queues.c:515 30 s ago by LWP 369313)
[2025-10-06 19:40:50.816]   ERROR[369356]: backtrace.c:255 bbs_log_backtrace: Got 13 backtrace records
[2025-10-06 19:40:51.261]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  0: lbbs bbs_log_backtrace()
[2025-10-06 19:40:51.261]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  1: lbbs __bbs_rwlock_wrlock()
[2025-10-06 19:40:51.261]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  2: [0x7fe42b152c71] mod_asterisk_queues.so       mod_asterisk_queues.c:206   del_agent()
[2025-10-06 19:40:51.261]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  3: [0x7fe42b15669e] mod_asterisk_queues.so       mod_asterisk_queues.c:1191  agent_exec()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  4: lbbs bbs_door_exec()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  5: lbbs menu_handler_exec()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  6: lbbs <unknown>()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  7: lbbs bbs_node_menuexec()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  8: lbbs <unknown>()
[2025-10-06 19:40:51.262]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace:  9: lbbs bbs_node_handler()
[2025-10-06 19:40:51.263]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace: 10: lbbs <unknown>()
[2025-10-06 19:40:51.263]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace: 11: [0x7fe42baa71f5] libc.so.6                         pthread_create.c:442   start_thread()
[2025-10-06 19:40:51.263]   ERROR[369356]: backtrace.c:279 bbs_log_backtrace: 12: [0x7fe42bb278dc] libc.so.6                                 clone3.S:83    clone3()

Here is a more recent example where the address of agent is 0x45, clearly invalid:

[2025-12-19 16:48:31.805]   DEBUG[1945271]: mod_asterisk_queues.c:571 ami_callback: Processing queue event 'QueueCallerJoin'
[2025-12-19 16:48:31.806]   DEBUG[1945271]: mod_asterisk_queues.c:502 new_call: Added call from '12632056' (IAX2/phreaknet-11380) to queue 'phreaknet-operator' as call 0
[2025-12-19 16:48:31.806]   DEBUG[1945271]: mod_asterisk_queues.c:571 ami_callback: Processing queue event 'AgentCalled'
[2025-12-19 16:48:31.818]    AUTH[1945273]: net_msp.c:379 msp_udp_listener: Received new Message Send Protocol message from 10.116.0.5
[2025-12-19 16:48:31.818]   -- Handling Message Send Protocol version 2 message
[2025-12-19 16:48:31.819]   DEBUG[1945273]: socket.c:2857 bbs_auto_any_fd_writef: Discarding write output (no node and no fd)
[2025-12-19 16:48:31.819]   DEBUG[1945273]: net_irc.c:845 __channel_broadcast: (1/0) <= :MSP/ARTNVAAXCG0!MSP@10.116.0.5 PRIVMSG #phreaknet-operators :OPSRV phreaknet-operator - "REDACTED" <12632056>
[2025-12-19 16:48:31.819]   DEBUG[1945273]: net_msp.c:216 msp_response: MSP response <= +
Segmentation fault (core dumped)

Thread 1 (Thread 0x7fb757fff6c0 (LWP 1945271)):
#0  0x00007fb75de4b172 in agent_printf (queue=0x561f5ae39ba0, member_name=0x7fb748201d40 "234051", fmt=0x7fb75de4f46f "%s\r%s%-15s %-22s %15s\n") at mod_asterisk_queues.c:526
        buf = 0x7fb74812a270 "\033[0m\r\aACD RING        OPERATOR", ' ' <repeats 22 times>, "12632056\n"
        len = 61
        ap = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7fb757efecb0, reg_save_area = 0x7fb757efebe0}}
        agent = 0x45
        agent_id = 234051
        __func__ = "agent_printf"
#1  0x00007fb75de4b762 in ami_callback (e=0x7fb748201870, eventname=0x7fb748005d50 "AgentCalled") at mod_asterisk_queues.c:601

(gdb) thread 1
[Switching to thread 1 (Thread 0x7fb757fff6c0 (LWP 1945271))]
#0  0x00007fb75de4b172 in agent_printf (queue=0x561f5ae39ba0, member_name=0x7fb748201d40 "234051", fmt=0x7fb75de4f46f "%s\r%s%-15s %-22s %15s\n") at mod_asterisk_queues.c:526
526                     if (!agent->idle) {
(gdb) print *agent
Cannot access memory at address 0x45

Related (notice the thread deadlocked itself?):

[2025-10-27 21:19:02.772] WARNING[753110]: mod_asterisk_queues.c:188 del_agent: Spent 31 seconds so far waiting to wrlock &queues, possible deadlock? (rwlock acquired at mod_asterisk_queues.c:733 30 s ago by LWP 753110)

Here is another instance where we seem to have some kind of recursive deadlock (at least it was appear, since the logs say thread 1943176 is deadlocked by... itself?)

[2025-12-18 21:39:03.040] WARNING[1943176]: mod_asterisk_queues.c:188 del_agent: Spent 40 seconds so far waiting to wrlock &queues, possible deadlock? (rwlock acquired at mod_asterisk_queues.c:734 30 s ago by LWP 1943176)
[2025-12-18 21:39:03.153]   ERROR[1943176]: backtrace.c:255 bbs_log_backtrace: Got 14 backtrace records
[2025-12-18 21:39:03.833]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  0: lbbs bbs_log_backtrace()
[2025-12-18 21:39:03.835]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  1: lbbs __bbs_rwlock_wrlock()
[2025-12-18 21:39:03.836]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  2: [0x7f8491027aa3] mod_asterisk_queues.so       mod_asterisk_queues.c:189   del_agent()
[2025-12-18 21:39:03.838]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  3: [0x7f849102b7cc] mod_asterisk_queues.so       mod_asterisk_queues.c:1204  agent_exec()
[2025-12-18 21:39:03.840]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  4: lbbs bbs_door_exec()
[2025-12-18 21:39:03.841]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  5: [0x7f846a7d6421] mod_menu_handlers.so           mod_menu_handlers.c:81    door_handler()
[2025-12-18 21:39:03.843]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  6: lbbs menu_handler_exec()
[2025-12-18 21:39:03.845]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  7: lbbs <unknown>()
[2025-12-18 21:39:03.846]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  8: lbbs bbs_node_menuexec()
[2025-12-18 21:39:03.848]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace:  9: lbbs <unknown>()
[2025-12-18 21:39:03.849]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace: 10: lbbs bbs_node_handler()
[2025-12-18 21:39:03.851]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace: 11: lbbs <unknown>()
[2025-12-18 21:39:03.852]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace: 12: [0x7f84919351f5] libc.so.6                         pthread_create.c:442   start_thread()
[2025-12-18 21:39:03.854]   ERROR[1943176]: backtrace.c:279 bbs_log_backtrace: 13: [0x7f84919b58dc] libc.so.6                                 clone3.S:83    clone3()

Thread 51 (Thread 0x7f8437f8a6c0 (LWP 1943372) "lbbs"):
#0  0x00007f849197b545 in __GI___clock_nanosleep (clock_id=clock_id@entry=0, flags=flags@entry=0, req=req@entry=0x7f8437f896e0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:48
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        r = <optimized out>
#1  0x00007f849197fe53 in __GI___nanosleep (req=req@entry=0x7f8437f896e0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/nanosleep.c:25
        ret = <optimized out>
#2  0x00007f84919ab285 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:31
        ts = {tv_sec = 0, tv_nsec = 1000000}
#3  0x0000561b05b501d3 in __bbs_rwlock_wrlock (t=0x7f84910303b0 <queues+16>, filename=0x7f849102d00a "mod_asterisk_queues.c", lineno=188, func=0x7f849102dc58 <__func__.20> "del_agent", name=0x7f849102d08>
        diff = 2735
        res = 16
        c = 2541095
        now = 1766099004
        elapsed = 2735
        start = 1766096269
        __func__ = "__bbs_rwlock_wrlock"
#4  0x00007f8491027aa3 in del_agent (agent=0x7f847c1ebc50) at mod_asterisk_queues.c:188
        queue = 0x7f849102b657 <agent_exec+823>
        member = 0x7f8437f89880
        __func__ = "del_agent"
#5  0x00007f849102b7cc in agent_exec (node=0x7f84818c49b0, args=0x0) at mod_asterisk_queues.c:1203

Thread 41 (Thread 0x7f8430f7c6c0 (LWP 1943176) "lbbs"):
#0  0x00007f849197b545 in __GI___clock_nanosleep (clock_id=clock_id@entry=0, flags=flags@entry=0, req=req@entry=0x7f8430f7b6e0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:48
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        r = <optimized out>
#1  0x00007f849197fe53 in __GI___nanosleep (req=req@entry=0x7f8430f7b6e0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/nanosleep.c:25
        ret = <optimized out>
#2  0x00007f84919ab285 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:31
        ts = {tv_sec = 0, tv_nsec = 1000000}
#3  0x0000561b05b501d3 in __bbs_rwlock_wrlock (t=0x7f84910303b0 <queues+16>, filename=0x7f849102d00a "mod_asterisk_queues.c", lineno=188, func=0x7f849102dc58 <__func__.20> "del_agent", name=0x7f849102d08>
        diff = 2735
        res = 16
        c = 4606273
        now = 1766099004
        elapsed = 2735
        start = 1766096269
        __func__ = "__bbs_rwlock_wrlock"
#4  0x00007f8491027aa3 in del_agent (agent=0x561b280d4d60) at mod_asterisk_queues.c:188
        queue = 0x7f8430f7c6c0
        member = 0x1ffffffff
        __func__ = "del_agent"
#5  0x00007f849102b7cc in agent_exec (node=0x7f848c1b8f90, args=0x0) at mod_asterisk_queues.c:1203
        agentid = 378
        agent = 0x561b280d4d60
        tmp = 0x561b28171350 "378"
        __func__ = "agent_exec"
#6  0x0000561b05b44eea in bbs_door_exec (node=0x7f848c1b8f90, name=0x7f8430f7b960 "astqueue", args=0x0) at door.c:130

---

Comments

You must be logged in to leave a comment.

---

---

---

---

---