[asterisk-bugs] [JIRA] (ASTERISK-30210) func_frame_trace: Channel masquerade triggers assertion
N A (JIRA)
noreply at issues.asterisk.org
Wed Sep 7 08:40:09 CDT 2022
[ https://issues.asterisk.org/jira/browse/ASTERISK-30210?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=260032#comment-260032 ]
N A commented on ASTERISK-30210:
--------------------------------
The only thing I noticed that was odd is that once Bridge was called and the masquerade occurred, local channel optimizations occurred which completely screwed everything up - for one, I had groups assigned on some of the local channels and they got optimized out. Funny thing is I have /n on all the relevant Dial()s for these channels so I can't think why Bridge() is optimizing these out. Because the masquerade where this assert happened literally screwed everything up, I wonder if it's related. For instance, if nobody has reported this before, than either FRAME_TRACE is seldom used (which it probably is, except for debugging), or for some reason this is an unusual masquerade scenario, though I can't see why.
That said, if it was a scenario where we didn't care about optimization, no groups or anything, etc. then I think this would be A-OK and the assert is very inappropriate.
As a workaround, I ended up putting both channels in the same temp ConfBridge, which avoids the masquerade issue and thus screwing with my groups, but that requires additional logic to make it work like Bridge() so somewhat clunky. I hadn't noticed this before and I'm assuming Bridge shouldn't be optimizing local channels of its own volition? Alternately, if there is a way to Bridge() without involving a masquerade (assuming the other channel is just doing Wait() or the like, not anything media-related), that might work around it.
> func_frame_trace: Channel masquerade triggers assertion
> -------------------------------------------------------
>
> Key: ASTERISK-30210
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-30210
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Core/Bridging, Functions/General
> Affects Versions: 18.14.0
> Reporter: N A
> Assignee: N A
>
> A new kind of crash/assertion that I encountered today. Whenever I transfer a call (not using Transfer, this is manually using Wait + Bridge) and a masquerade occurs, Asterisk crashes due to this assertion:
> Looking at the code, this is because AST_CONTROL_MASQUERADE_NOTIFY in func_frame_trace => assert(0);
> I sometimes use FRAME_TRACE for debugging, more so recently, so this might be why I've not seen this before.
> This reproduces consistently.
> I think this assertion is bogus, because if I comment it out in func_frame_trace, nothing happens. No crash, nothing out of the ordinary.
> What's the reason for it? If it's not really good, it should probably be removed, or changed to an error or warning instead of an assert.
> {noformat}
> Thread 1 (Thread 0x7f85e5daf700 (LWP 4265)):
> #0 0x00007f85e7f987bb in __GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> set = {__val = {134238211, 0, 922805718333277103, 8940060396390496210, 1, 13979173243358019584, 579005069656919567, 283686952306183, 12014427501342296478, 189258333318898, 4668459621267030470, 13037061474637634319, 1559441997760, 94060151642313, 25, 0}}
> pid = <optimized out>
> tid = <optimized out>
> #1 0x00007f85e7f83535 in __GI_abort () at abort.c:79
> save_stage = 1
> act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0 <repeats 11 times>, 94060152032149, 3758907856, 140213063691408, 140212966553968, 140213063691456}}, sa_flags = -402316636, sa_restorer = 0x7f85e0107970}
> sigs = {__val = {32, 0 <repeats 15 times>}}
> #2 0x0000558c15e3e2c0 in ast_do_crash () at utils.c:2764
> #3 0x0000558c15e3e35f in __ast_assert_failed (condition=0, condition_str=0x7f85e4b71448 "0", file=0x7f85e4b7109e "func_frame_trace.c", line=348, function=0x7f85e4b71a38 <__PRETTY_FUNCTION__.15272> "print_frame") at utils.c:2793
> #4 0x00007f85e4b6f2aa in _ast_assert (condition=0, condition_str=0x7f85e4b71448 "0", file=0x7f85e4b7109e "func_frame_trace.c", line=348, function=0x7f85e4b71a38 <__PRETTY_FUNCTION__.15272> "print_frame") at /usr/src/asterisk-18.14.0/include/asterisk/utils.h:730
> #5 0x00007f85e4b703b6 in print_frame (frame=0x7f85e00b04e0) at func_frame_trace.c:348
> __FUNCTION__ = "print_frame"
> __PRETTY_FUNCTION__ = "print_frame"
> #6 0x00007f85e4b6f4b2 in hook_event_cb (chan=0x7f85dc064190, frame=0x7f85e00b04e0, event=AST_FRAMEHOOK_EVENT_WRITE, data=0x7f85c80a53f0) at func_frame_trace.c:150
> i = 4
> show_frame = 1
> framedata = 0x7f85c80a53f0
> __FUNCTION__ = "hook_event_cb"
> #7 0x0000558c15d4ba54 in framehook_list_push_event (framehooks=0x7f85d0053de0, frame=0x7f85e00b04e0, event=AST_FRAMEHOOK_EVENT_WRITE) at framehook.c:116
> __list_head = 0x7f85d0053de8
> __list_next = 0x0
> __list_prev = 0x0
> __list_current = 0x7f85c80a54d0
> num = 0
> framehook = 0x7f85c80a54d0
> original_frame = 0x7f85e00b04e0
> skip = 0x7f85e5daad60
> skip_size = 4
> #8 0x0000558c15d4c34e in ast_framehook_list_write_event (framehooks=0x7f85d0053de0, frame=0x7f85e00b04e0) at framehook.c:315
> #9 0x0000558c15ce33a7 in ast_indicate_data (chan=0x7f85dc064190, _condition=34, data=0x7f85e5dab1e4, datalen=4) at channel.c:4720
> frame = {frametype = AST_FRAME_CONTROL, subclass = {integer = 34, {format = 0x0, topology = 0x0}, frame_ending = 0}, datalen = 4, samples = 0, mallocd = 0, mallocd_hdr_len = 0, offset = 0, src = 0x0, data = {ptr = 0x7f85e5dab1e4, uint32 = 3856314852, pad = "344261332345205177000"}, delivery = {tv_sec = 0, tv_usec = 0}, frame_list = {next = 0x0}, flags = 0, ts = 0, len = 0, seqno = 0, stream_num = 0}
> res = 0
> awesome_frame = 0x7f85e00b04e0
> __PRETTY_FUNCTION__ = "ast_indicate_data"
> #10 0x0000558c15ceb0d4 in channel_do_masquerade (original=0x7f85e012c960, clonechan=0x7f85dc064190) at channel.c:6975
> x = 1
> origstate = 21900
> orig_disablestatecache = 367924755
> clone_disablestatecache = 32645
> generator_fd = -603569856
> visible_indication = 21900
> clone_hold_state = 32645
> moh_is_playing = 0
> current = 0x4
> t = 0x0
> t_pvt = 0x7f85dc07cbc0
> exchange = {handlers = {first = 0x558c15f13530, last = 0x0}, dialed = {number = {str = 0x558c15f13530 "stasis_message.c", plan = 0}, subaddress = {str = 0xffffffff00000089 <error: Cannot access memory at address 0xffffffff00000089>, type = -536173824, odd_even_indicator = 133 '205', valid = 127 '177'}, transit_network_select = -603459216}, caller = {id = {name = {str = 0x558c15f13530 "stasis_message.c", char_set = 0, presentation = 0, valid = 137 '211'}, number = {str = 0x7f85e00aa300 "255ޭޭޭޭޭޭޭޭ", <incomplete sequence 336>, plan = -603459216, presentation = 32645, valid = 0 '000'}, subaddress = {str = 0x7f85dc07f170 "", type = 599622, odd_even_indicator = 0 '000', valid = 0 '000'}, tag = 0x7f85e5dab0c0 "3031355025214U"}, ani = {name = {str = 0x558c15c9793a <__ao2_unlock+237> "211E364351", <incomplete sequence 317>, char_set = -438652736, presentation = 32645, valid = 50 '2'}, number = {str = 0x22e15ca4db3 <error: Cannot access memory at address 0x22e15ca4db3>, plan = 367864744, presentation = 21900, valid = 0 '000'}, subaddress = {str = 0xe0091d00 <error: Cannot access memory at address 0xe0091d00>, type = 368649264, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x15f92428 <error: Cannot access memory at address 0x15f92428>}, priv = {name = {str = 0x558c15f92430 <reglock+48> "", char_set = 368649256, presentation = 21900, valid = 16 '020'}, number = {str = 0x558c15d60c3a <__ast_pthread_mutex_unlock+1072> "211E", <incomplete sequence 330>, plan = -438652640, presentation = 32645, valid = 58 ':'}, subaddress = {str = 0x558c15ed1933 "®lock", type = 368649216, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x558c15ed1933 "®lock"}, ani2 = 367863576}, connected = {id = {name = {str = 0x558c15f13530 "stasis_message.c", char_set = 0, presentation = 0, valid = 137 '211'}, number = {str = 0x7f85e00aa300 "255ޭޭޭޭޭޭޭޭ", <incomplete sequence 336>, plan = -603459216, presentation = 32645, valid = 0 '000'}, subaddress = {str = 0x7f85dc07f170 "", type = 599622, odd_even_indicator = 0 '000', valid = 0 '000'}, tag = 0x7f85e5dab0c0 "3031355025214U"}, ani = {name = {str = 0x558c15c9793a <__ao2_unlock+237> "211E364351", <incomplete sequence 317>, char_set = -438652736, presentation = 32645, valid = 50 '2'}, number = {str = 0x22e15ca4db3 <error: Cannot access memory at address 0x22e15ca4db3>, plan = 367864744, presentation = 21900, valid = 0 '000'}, subaddress = {str = 0xe0091d00 <error: Cannot access memory at address 0xe0091d00>, type = 368649264, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x15f92428 <error: Cannot access memory at address 0x15f92428>}, priv = {name = {str = 0x558c15f92430 <reglock+48> "", char_set = 368649256, presentation = 21900, valid = 16 '020'}, number = {str = 0x558c15d60c3a <__ast_pthread_mutex_unlock+1072> "211E", <incomplete sequence 330>, plan = -438652640, presentation = 32645, valid = 58 ':'}, subaddress = {str = 0x558c15ed1933 "®lock", type = 368649216, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x558c15ed1933 "®lock"}, ani2 = 367863576, source = 21900}, redirecting = {orig = {name = {str = 0x558c15f13530 "stasis_message.c", char_set = 0, presentation = 0, valid = 137 '211'}, number = {str = 0x7f85e00aa300 "255ޭޭޭޭޭޭޭޭ", <incomplete sequence 336>, plan = -603459216, presentation = 32645, valid = 0 '000'}, subaddress = {str = 0x7f85dc07f170 "", type = 599622, odd_even_indicator = 0 '000', valid = 0 '000'}, tag = 0x7f85e5dab0c0 "3031355025214U"}, from = {name = {str = 0x558c15c9793a <__ao2_unlock+237> "211E364351", <incomplete sequence 317>, char_set = -438652736, presentation = 32645, valid = 50 '2'}, number = {str = 0x22e15ca4db3 <error: Cannot access memory at address 0x22e15ca4db3>, plan = 367864744, presentation = 21900, valid = 0 '000'}, subaddress = {str = 0xe0091d00 <error: Cannot access memory at address 0xe0091d00>, type = 368649264, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x15f92428 <error: Cannot access memory at address 0x15f92428>}, to = {name = {str = 0x558c15f92430 <reglock+48> "", char_set = 368649256, presentation = 21900, valid = 16 '020'}, number = {str = 0x558c15d60c3a <__ast_pthread_mutex_unlock+1072> "211E", <incomplete sequence 330>, plan = -438652640, presentation = 32645, valid = 58 ':'}, subaddress = {str = 0x558c15ed1933 "®lock", type = 368649216, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x558c15ed1933 "®lock"}, priv_orig = {name = {str = 0x558c15ed2718 <__PRETTY_FUNCTION__.9272> "region_free", char_set = 0, presentation = 371, valid = 0 '000'}, number = {str = 0x0, plan = -535791248, presentation = 32645, valid = 80 'P'}, subaddress = {str = 0x558c15fc7fc0 <enddata> "033[0m", type = -536491923, odd_even_indicator = 133 '205', valid = 127 '177'}, tag = 0x7f85d403aa32 "Local/2122 at REDACTED-originate-local-00000001;2"}, priv_from = {name = {str = 0x558c15fc7fc0 <enddata> "033[0m", char_set = 365511119, presentation = 21900, valid = 208 '320'}, number = {str = 0x558c15fbc9a0 <whales> "200031345030214U", plan = 0, presentation = 0, valid = 128 '200'}, subaddress = {str = 0x7f85e5dab190 "в332345205177", type = 365512163, odd_even_indicator = 140 '214', valid = 85 'U'}, tag = 0x558c15ed2ba8 <__PRETTY_FUNCTION__.9410> "__ao2_ref"}, priv_to = {name = {str = 0x28515e08d36 <error: Cannot access memory at address 0x28515e08d36>, char_set = 367864064, presentation = 21900, valid = 96 '`'}, number = {str = 0x7f85e5dab200 "", plan = -535586608, presentation = 32645, valid = 208 '320'}, subaddress = {str = 0x558c15c9866c <__ao2_ref+1971> "351", <incomplete sequence 305>, type = 368869312, odd_even_indicator = 212 '324', valid = 5 '005'}, tag = 0x558c15f12be0 <__PRETTY_FUNCTION__.17048> "ast_channel_publish_blob"}, reason = {str = 0x558c15f11921 "stasis_channels.c", code = 0}, orig_reason = {str = 0xffffffff0000047e <error: Cannot access memory at address 0xffffffff0000047e>, code = 367228233}, count = 3656}}
> bridged = 0x7f85e00cd580
> rformat = 0x558c15c9793a <__ao2_unlock+237>
> wformat = 0x7f85e0107970
> tmp_format = 0x2a8700000000
> tmp_cap = 0x7f85e00cd580
> tmp_name = " 261332345205177000000z002326025214U000000063031355025214U000000000$371025214U000000063031355025214U000000030'355025214U000000 261332345k001000000311030355025214U000000062)355025214U000000260065361025214U000"
> clone_sending_dtmf_digit = -27 '345'
> clone_sending_dtmf_tv = {tv_sec = 140213063692560, tv_usec = 94060150129274}
> __PRETTY_FUNCTION__ = "channel_do_masquerade"
> __FUNCTION__ = "channel_do_masquerade"
> #11 0x0000558c15cf6ff8 in ast_channel_move (dest=0x7f85e012c960, source=0x7f85dc064190) at channel.c:10889
> blob = 0x7f85e0107970
> lock = 0x558c15f930c0 <channel_move_lock>
> __PRETTY_FUNCTION__ = "ast_channel_move"
> __FUNCTION__ = "ast_channel_move"
> #12 0x0000558c15cf6c90 in ast_channel_yank (yankee=0x7f85dc064190) at channel.c:10835
> yanked_chan = 0x7f85e012c960
> my_vars = {accountcode = 0x7f85e5dab420 "", exten = 0x7f85e5dab400 "s", context = 0x7f85e5dab3e0 "REDACTED-transferred", name = 0x7f85e5dab380 "Local/2123 at REDACTED-originate-local-00000005;1", amaflags = 3, priority = 4, readformat = 0x558c175080a8, writeformat = 0x558c175080a8}
> __PRETTY_FUNCTION__ = "ast_channel_yank"
> __FUNCTION__ = "ast_channel_yank"
> #13 0x0000558c15cae625 in ast_bridge_add_channel (bridge=0x7f85c00be270, chan=0x7f85dc064190, features=0x7f85e00fdb60, play_tone=0, xfersound=0x7f85e0092af2 "beep") at bridge.c:2515
> chan_bridge = 0x0
> yanked_chan = 0x0
> __PRETTY_FUNCTION__ = "ast_bridge_add_channel"
> __FUNCTION__ = "ast_bridge_add_channel"
> #14 0x0000558c15e84422 in bridge_exec (chan=0x7f85d4039d50, data=0x7f85e5daba30 "Local/2123 at REDACTED-originate-local-00000005;1,F(REDACTED-transferred,done,1)") at features.c:1115
> current_dest_chan = 0x7f85dc064190
> tmp_data = 0x7f85e5dab620 "Local/2123 at REDACTED-originate-local-00000005;1"
> opts = {flags = 4096}
> bconfig = {features_caller = {flags = 0}, features_callee = {flags = 0}, start_time = {tv_sec = 0, tv_usec = 0}, nexteventts = {tv_sec = 0, tv_usec = 0}, feature_start_time = {tv_sec = 0, tv_usec = 0}, feature_timer = 0, timelimit = 0, play_warning = 0, warning_freq = 0, warning_sound = 0x0, end_sound = 0x0, start_sound = 0x0, flags = 0, end_bridge_callback = 0x0, end_bridge_callback_data = 0x0, end_bridge_callback_data_fixup = 0x0, answer_topology = 0x0}
> opt_args = {0x7f85e5dab810 "", 0x558c15f0e35f "topic", 0x7f85e5dab64f "REDACTED-transferred,done,1"}
> calldurationlimit = {tv_sec = 0, tv_usec = 0}
> context = 0x7f85e5dab600 "REDACTED-transferred"
> extension = 0x7f85e5dab5a0 "Local/2123 at REDACTED-originate-local-00000005;1"
> priority = 3
> bridge_add_failed = 21900
> res = -1
> chan_features = {dtmf_hooks = 0x7f85cc4fa730, other_hooks = 0x7f85c00cf850, interval_hooks = 0x7f85e00e18d0, feature_flags = {flags = 0}, interval_sequence = 0, usable = 0, mute = 0, dtmf_passthrough = 1, inhibit_colp = 0, text_messaging = 1}
> peer_features = 0x7f85e00fdb60
> bridge = 0x7f85c00be270
> xfer_cfg = 0x7f85c00ca8c0
> args = {argc = 2, {argv = {0x7f85e5dab620 "Local/2123 at REDACTED-originate-local-00000005;1", 0x7f85e5dab64d "F(REDACTED-transferred,done,1"}, {dest_chan = 0x7f85e5dab620 "Local/2123 at REDACTED-originate-local-00000005;1", options = 0x7f85e5dab64d "F(REDACTED-transferred,done,1"}}}
> __PRETTY_FUNCTION__ = "bridge_exec"
> __FUNCTION__ = "bridge_exec"
> #15 0x0000558c15d986c5 in pbx_exec (c=0x7f85d4039d50, app=0x558c168b89e0, data=0x7f85e5daba30 "Local/2123 at REDACTED-originate-local-00000005;1,F(REDACTED-transferred,done,1)") at pbx_app.c:492
> res = 21900
> u = 0x0
> saved_c_appl = 0x0
> saved_c_data = 0x0
> __PRETTY_FUNCTION__ = "pbx_exec"
> #16 0x0000558c15d82726 in pbx_extension_helper (c=0x7f85d4039d50, con=0x0, context=0x7f85d403a710 "REDACTED-transferred", exten=0x7f85d403a760 "Local/2123 at REDACTED-originate-local-00000005;1", priority=3, label=0x0, callerid=0x7f85d40460a0 "REDACTED", action=E_SPAWN, found=0x7f85e5daeccc, combined_find_spawn=1) at pbx.c:2948
> e = 0x558c19709330
> app = 0x558c168b89e0
> substitute = 0x7f85e5dab9a0 "${EXTEN},F(REDACTED-transferred,done,1)"
> q = {incstack = {0x0 <repeats 512 times>}, stacklen = 0, status = 5, swo = 0x0, data = 0x0, foundcontext = 0x7f85d403a710 "REDACTED-transferred"}
> passdata = "Local/2123 at REDACTED-originate-local-00000005;1,F(REDACTED-transferred,done,1)", '000' <repeats 8118 times>
> matching_action = 0
> __PRETTY_FUNCTION__ = "pbx_extension_helper"
> __FUNCTION__ = "pbx_extension_helper"
> #17 0x0000558c15d86a26 in ast_spawn_extension (c=0x7f85d4039d50, context=0x7f85d403a710 "REDACTED-transferred", exten=0x7f85d403a760 "Local/2123 at REDACTED-originate-local-00000005;1", priority=3, callerid=0x7f85d40460a0 "REDACTED", found=0x7f85e5daeccc, combined_find_spawn=1) at pbx.c:4203
> #18 0x0000558c15d877b5 in __ast_pbx_run (c=0x7f85d4039d50, args=0x0) at pbx.c:4377
> digit = 0
> invalid = 0
> timeout = 0
> dst_exten = '000' <repeats 56 times>, "Iu343025214U000000H016000000000000000000 at 7373025214U000000256255{272205177000000200325f340205177000000060354332345205177000000Iu343025214U000000H016000000000000000000 at 7373025214U000000~320354025214U000000200325f340205177000000 at 354332345205177000000T242343025214U000000260355332345205177000000220023371025214U000000257255{272205177000000200325f340205177000000260355332345205177000000"...
> pos = 0
> found = 1
> res = 0
> autoloopflag = 0
> error = 0
> pbx = 0x7f85e00d3180
> callid = 0
> __FUNCTION__ = "__ast_pbx_run"
> __PRETTY_FUNCTION__ = "__ast_pbx_run"
> #19 0x0000558c15d8915e in pbx_thread (data=0x7f85d4039d50) at pbx.c:4701
> c = 0x7f85d4039d50
> #20 0x0000558c15e3b2ac in dummy_start (data=0x558c1a8fd8b0) at utils.c:1574
> __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {0, 1473881673984446825, 140212336045486, 140212336045487, 140213063710464, 140212898376640, 1473881674009612649, 4640862523344753001}, __mask_was_saved = 0}}, __pad = {0x7f85e5daeed0, 0x0, 0xcfb6bd8bede52c00, 0x7f85c0000bb0}}
> __cancel_routine = 0x558c15c892f5 <ast_unregister_thread>
> __cancel_arg = 0x7f85e5daf700
> __not_first_call = 0
> ret = 0x7f85e5daf700
> a = {start_routine = 0x558c15d89139 <pbx_thread>, data = 0x7f85d4039d50, name = 0x7f85cc4f7cc0 "pbx_thread", ' ' <repeats 11 times>, "started at [ 4727] pbx.c ast_pbx_start()"}
> lock_info = 0x7f85e00cd580
> mutex_attr = {__size = "001000000", __align = 1}
> __PRETTY_FUNCTION__ = "dummy_start"
> #21 0x00007f85e85c5fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
> ret = <optimized out>
> pd = <optimized out>
> now = <optimized out>
> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140213063710464, -1477308053359619735, 140212336045486, 140212336045487, 140213063710464, 140212898376640, 1473881673973961065, 1473904819000250729}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
> not_first_call = <optimized out>
> #22 0x00007f85e8059eff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list