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

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()

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)

Comments

You must be logged in to leave a comment.