[LBBS-121] mod_asterisk_queues: Memory corruption or use after free in agent list
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.
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:130Comments
You must be logged in to leave a comment.