[bug]: Asterisk stuck with high load after a while - no SIP possible anymore

[SipSeb]

Severity

Major

Versions

18.17.1

Components/Modules

bridge, pjsip

Operating Environment

Ubuntu Focal, Asterisk built from sources

Frequency of Occurrence

Occasional

Issue Description

We have thousands of Asterisk systems running in our cloud pbx infrastructure. We recently updated from Asterisk 18.12.1 to 18.17.1. After that update, some customers reported an outage of their Asterisk every day.

What we see is one Asterisk thread using up 100% of CPU and Asterisk not responding to REGISTERs and stuff anymore.

Example thread using up all CPU:

0x7f990b92e700 3648 bridge_channel_ind_thread started at [ 1845] bridge.c bridge_impart_internal()

I got a coredump of Asterisk and attached gdb to it. See the gdb output below. Looks to me as if there is a bug while switching bridges.

We downgraded to 18.12.1 again and had no customer complaints since.

Relevant log output

[Switching to thread 108 (Thread 0x7f990b92e700 (LWP 3648))]
#0  0x00007f991843a71b in sched_yield () at ../sysdeps/unix/syscall-template.S:78
78      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt full
#0  0x00007f991843a71b in sched_yield () at ../sysdeps/unix/syscall-template.S:78
No locals.
#1  0x000055904cad3487 in ast_unreal_lock_all (p=p@entry=0x7f99103d1920, outchan=outchan@entry=0x7f990b92da88, outowner=outowner@entry=0x7f990b92da90) at core_unreal.c:73
        chan = 0x7f99103fbf60
        owner = 0x7f991030dae0
        __PRETTY_FUNCTION__ = "ast_unreal_lock_all"
#2  0x000055904cad458c in unreal_colp_stream_topology_request_change (topology=<optimized out>, ast=0x7f99103fbf60, p=0x7f99103d1920) at core_unreal.c:592
        the_other_channel_topology = 0x55904f931c88
        i = 1
        stream = <optimized out>
        my_chan = 0x55904fac83b8
        my_owner = 0x55904f6fe758
        this_channel = <optimized out>
        this_channel_topology = 0x55904fbd4548
        the_other_channel = <optimized out>
        res = 0
        this_channel_topology = <optimized out>
        the_other_channel_topology = <optimized out>
        i = <optimized out>
        stream = <optimized out>
        my_chan = <optimized out>
        my_owner = <optimized out>
        this_channel = <optimized out>
        the_other_channel = <optimized out>
        res = <optimized out>
        __PRETTY_FUNCTION__ = "unreal_colp_stream_topology_request_change"
#3  ast_unreal_indicate (ast=0x7f99103fbf60, condition=<optimized out>, data=<optimized out>, datalen=<optimized out>) at core_unreal.c:680
        p = 0x7f99103d1920
        res = 0
        chan = 0x0
        owner = 0x0
        parameters = <optimized out>
        __PRETTY_FUNCTION__ = "ast_unreal_indicate"
        __FUNCTION__ = "ast_unreal_indicate"
#4  0x000055904cab9fdb in ast_channel_request_stream_topology_change (chan=chan@entry=0x7f99103fbf60, topology=topology@entry=0x55904fac83b8, change_source=change_source@entry=0x7f99147bd1c0 <simple_bridge>) at channel.c:11168
        res = <optimized out>
        __PRETTY_FUNCTION__ = "ast_channel_request_stream_topology_change"
#5  0x00007f99147ba99f in simple_bridge_join (bridge=<optimized out>, bridge_channel=<optimized out>) at bridge_simple.c:184
        req_top = <optimized out>
        existing_top = <optimized out>
        new_top = 0x55904fac83b8
        c0 = 0x55904fc3e8a0
        c1 = 0x7f99103fbf60
        unhold_c0 = <optimized out>
        unhold_c1 = 0
        __PRETTY_FUNCTION__ = "simple_bridge_join"
        __FUNCTION__ = "simple_bridge_join"
        __tmp = <optimized out>
#6  0x000055904ca6dbd2 in bridge_channel_complete_join (bridge=0x55904f82a870, bridge_channel=0x7f99103cc890) at bridge.c:439
        __FUNCTION__ = "bridge_channel_complete_join"
#7  0x000055904ca72b8d in bridge_complete_join (bridge=0x55904f82a870) at bridge.c:494
        bridge_channel = 0x7f99103cc890
        bridge_channel = <optimized out>
#8  bridge_reconfigured (bridge=bridge@entry=0x55904f82a870, colp_update=colp_update@entry=0) at bridge.c:1415
No locals.
#9  0x000055904ca75812 in bridge_do_move (dst_bridge=dst_bridge@entry=0x55904f82a870, bridge_channel=bridge_channel@entry=0x7f99103cc890, attempt_recovery=attempt_recovery@entry=1, optimized=optimized@entry=1) at bridge.c:2377
        orig_bridge = 0x7f99100cf160
        was_in_bridge = 1
        res = 0
        __FUNCTION__ = "bridge_do_move"
        __PRETTY_FUNCTION__ = "bridge_do_move"
#10 0x000055904ca766c5 in try_swap_optimize_out (pvt=0x7f99103ade10, peer_bridge_channel=<optimized out>, peer_bridge=0x55904f82a870, chan_bridge_channel=0x7f9910150400, chan_bridge=0x7f99100cf160) at bridge.c:2794
        id = 225
        src_bridge_channel = 0x7f9910150400
        dst_bridge = 0x55904f82a870
        dst_bridge_channel = <optimized out>
        other = <optimized out>
        res = 1
        dst_bridge = <optimized out>
        dst_bridge_channel = <optimized out>
        src_bridge_channel = <optimized out>
        other = <optimized out>
        res = <optimized out>
        __PRETTY_FUNCTION__ = "try_swap_optimize_out"
        __FUNCTION__ = "try_swap_optimize_out"
        id = <optimized out>
        __p = <optimized out>
        __x = <optimized out>
        __p = <optimized out>
        __x = <optimized out>
#11 ast_bridge_unreal_optimize_out (chan=chan@entry=0x7f991042c400, peer=0x7f991035a6b0, pvt=pvt@entry=0x7f99103ade10) at bridge.c:2938
        chan_bridge = 0x7f99100cf160
        peer_bridge = 0x55904f82a870
        chan_bridge_channel = 0x7f9910150400
        peer_bridge_channel = <optimized out>
        res = 0
        __PRETTY_FUNCTION__ = "ast_bridge_unreal_optimize_out"
#12 0x000055904cad3fdb in got_optimized_out (p=0x7f99103ade10, ast=0x7f991042c400) at core_unreal.c:305
        res = 0
        res = <optimized out>
        __p = <optimized out>
        __x = <optimized out>
#13 ast_unreal_write_stream (ast=0x7f991042c400, stream_num=0, f=0x7f9910405f60) at core_unreal.c:355
        p = 0x7f99103ade10
        res = -1
        __PRETTY_FUNCTION__ = "ast_unreal_write_stream"
#14 0x000055904caadd60 in ast_write_stream (chan=0x7f991042c400, stream_num=stream_num@entry=0, fr=fr@entry=0x7f9910405f60) at channel.c:5517
        stream = 0x55904f995900
        default_stream = 0x55904f995900
        res = -1
        f = <optimized out>
        count = <optimized out>
        hooked = <optimized out>
        __PRETTY_FUNCTION__ = "ast_write_stream"
        __FUNCTION__ = "ast_write_stream"
        __p = <optimized out>
        __x = <optimized out>
#15 0x000055904ca8c32d in bridge_channel_handle_write (bridge_channel=0x7f9910150400) at bridge_channel.c:2469
        fr = <optimized out>
        sync_payload = <optimized out>
        num = 0
        msg = <optimized out>
        fr = <optimized out>
        sync_payload = <optimized out>
        num = <optimized out>
        msg = <optimized out>
        __PRETTY_FUNCTION__ = "bridge_channel_handle_write"
        __FUNCTION__ = "bridge_channel_handle_write"
        __list_head = <optimized out>
        __list_next = <optimized out>
        __list_prev = <optimized out>
        __list_current = <optimized out>
        __p = <optimized out>
        __x = <optimized out>
        __p = <optimized out>
        __x = <optimized out>
        __idx = <optimized out>
#16 bridge_channel_wait (bridge_channel=0x7f9910150400) at bridge_channel.c:2782
        ms = -1
        outfd = 140
        chan = <optimized out>
        ms = <optimized out>
        outfd = <optimized out>
        chan = <optimized out>
        __PRETTY_FUNCTION__ = "bridge_channel_wait"
        __FUNCTION__ = "bridge_channel_wait"
        __p = <optimized out>
        __x = <optimized out>
#17 bridge_channel_internal_join (bridge_channel=bridge_channel@entry=0x7f9910150400) at bridge_channel.c:2947
        res = <optimized out>
        indicate_src_change = <optimized out>
        channel_features = <optimized out>
        peer = <optimized out>
        swap = 0x0
        __FUNCTION__ = "bridge_channel_internal_join"
        __PRETTY_FUNCTION__ = "bridge_channel_internal_join"
#18 0x000055904ca77262 in bridge_channel_ind_thread (data=data@entry=0x7f9910150400) at bridge.c:1751
        bridge_channel = 0x7f9910150400
        chan = <optimized out>
        __PRETTY_FUNCTION__ = "bridge_channel_ind_thread"
#19 0x000055904cbc19a8 in dummy_start (data=<optimized out>) at utils.c:1574
        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {0, -2737646064092821142, 140295299345006, 140295299345007, 140295299345280, 140295300898688, -2737666485494199958, -8209124737145747094}, __mask_was_saved = 0}}, __pad = {0x7f990b92ded0, 0x0, 0x1, 0x0}}
        __cancel_routine = <optimized out>
        __cancel_arg = 0x7f990b92e700
        __not_first_call = <optimized out>
        ret = <optimized out>
        a = {start_routine = 0x55904ca77240 <bridge_channel_ind_thread>, data = 0x7f9910150400, name = <optimized out>}
        __PRETTY_FUNCTION__ = "dummy_start"
#20 0x00007f99186d7609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140295300900608, 2680712649703967082, 140295299345006, 140295299345007, 140295299345280, 140295300898688, -2737666485487908502, -2737628744756606614}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0,
              canceltype = 0}}}
        not_first_call = 0
#21 0x00007f9918457133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Asterisk Issue Guidelines

• Yes, I have read the Asterisk Issue Guidelines

[jcolp]

Please attach the COMPLETE backtrace so the entire state of the process can be seen, not just a specific single thread. Information about what was going on at the time would also be useful to understand how it got into that state (such as a full console log).

[SipSeb]

Sorry.
I have now used the coredump script provided and attached the full coredump and the info file which shows what was going on there. The console is quiet when it occurs, doesn't log anything anymore.

core-asterisk-2023-07-12T14-05-59Z-full.txt
core-asterisk-2023-07-12T14-05-59Z-info.txt

[mbradeen]

Hi @SipSeb ,

Thank you for the full text. We're taking a look through it, trying to find out who is holding onto the lock that is causing at least one thread to wait. Please provide the full core so we can run it locally to find the culprit.

If it is possible to narrow down the version this started in, that would also be of help.

[SipSeb]

Hi @mbradeen,

thanks for looking into it. All I can say is that we used version 18.12.1 before (and are using it now again), and updated parts of our customer Asterisk systems to 18.17.1 when it appeared.

Do you have a way to provide the full core file (actually, I have two of them from different customer systems)? I don't want to upload them here because there is some sensitive information like phone numbers in them.

[mbradeen]

Hi @SipSeb ,

If you have a preferred place to host the complete coredumper output, you can email a link to asteriskteam@sangoma.com and we can download from there.

[github-actions]

This issue is stale because it has been open 7 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[SipSeb]

Hi @mbradeen,

Sorry, took a while, but I have just sent a mail with a link to the complete core dumps. Hope you can find something.