| Summary: | ASTERISK-30210: func_frame_trace: Channel masquerade triggers assertion | ||
| Reporter: | N A (InterLinked) | Labels: | |
| Date Opened: | 2022-09-03 20:10:41 | Date Closed: | 2022-09-12 07:49:29 |
| Priority: | Minor | Regression? | |
| Status: | Closed/Complete | Components: | Core/Bridging Functions/General |
| Versions: | 18.14.0 | Frequency of Occurrence | Constant |
| Related Issues: | |||
| Environment: | Attachments: | ||
| Description: | 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@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@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@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@REDACTED-originate-local-00000005;1,F(REDACTED-transferred,done,1)") at features.c:1115 current_dest_chan = 0x7f85dc064190 tmp_data = 0x7f85e5dab620 "Local/2123@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@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@REDACTED-originate-local-00000005;1", 0x7f85e5dab64d "F(REDACTED-transferred,done,1"}, {dest_chan = 0x7f85e5dab620 "Local/2123@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@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@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@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@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@7373025214U000000256255{272205177000000200325f340205177000000060354332345205177000000Iu343025214U000000H016000000000000000000@7373025214U000000~320354025214U000000200325f340205177000000@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} | ||
| Comments: | By: Asterisk Team (asteriskteam) 2022-09-03 20:10:45.813-0500 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur. Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/]. By: George Joseph (gjoseph) 2022-09-07 05:03:28.812-0500 bq. 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. I can only guess that [~rmudgett] thought it should never happen at the time he added that assert back in 2014 but something changed in the 8 years since. I'd be OK with replacing the assert with the appropriate ast_verbose message. By: N A (InterLinked) 2022-09-07 08:38:54.063-0500 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. By: Richard Mudgett (rmudgett) 2022-09-08 08:04:21.721-0500 I did not think it would happen with frame trace. However, frame trace is attached to a channel by frame hooks and thus can legitimately get it before it is passed to the channel driver. The case should be changed to decode the frame like the other cases. By: Richard Mudgett (rmudgett) 2022-09-08 08:22:10.404-0500 You are using the bridge application to move a channel from where it was to bridge with the current channel. If the channel you are bridging with is itself not in a bridge or it is in a ConfBridge then a masquerade must be done for you to bridge with it. Masquerades are not used for local channel optimizations anymore. There is no description and logs showing what you are doing in dialplan to determine what is going on to see why the application had to use masquerade. If local channel optimizations happened after the Bridge application operation, then there may be a bug there which should be reported in its own issue. By: N A (InterLinked) 2022-09-08 09:02:00.302-0500 I guess that's my question then: I have channel A call Wait(1) and channel B call Bridge(${CHANNEL_A}) so that B bridges to A, which is waiting to get bridged by B. A masquerade happens because Wait will still require a masquerade for the Bridge to succeed. Is there something else I can have channel A do that will not entail a masquerade when B calls Bridge? I didn't save the exact logs from when this was happening and have since slightly rearchitected some things, though I'd like to switch from ConfBridge back to Bridge so perhaps I can get it to happen again (though I could not just now... for the moment, I'm not getting masquerades that cause the groups to disappear). However, now and then, I was seeing stuff like this: {noformat} [2022-09-08 13:48:58] -- Executing [Local/2*4002702123*2122@outgoing-00000010;2@transferred:4] Bridge("Local/2*4002702123*2424@outgoing-0000000d;2", "Local/2*4002702123*2122@outgoing-00000010;2,F(transferred,done,1)") in new stack [2022-09-08 13:48:58] DEBUG[31872][C-00000006]: pbx.c:4463 __ast_pbx_run: Spawn extension (transferred,s,3) exited non-zero on 'Surrogate/Local/2*4002702123*2122@outgoing-00000010;2' [2022-09-08 13:48:58] == Spawn extension (transferred, s, 3) exited non-zero on 'Surrogate/Local/2*4002702123*2122@outgoing-00000010;2' [2022-09-08 13:48:58] -- Local/2*4002702123*2122@outgoing-00000010;1 requested media update control 26, passing it to Local/2122@originate-local-00000011;1 [2022-09-08 13:48:58] -- Channel Local/2*4002702123*2122@outgoing-00000010;2 joined 'simple_bridge' basic-bridge <893d361d-b0aa-4aa7-a2de-1045911f36e5> [2022-09-08 13:48:58] -- Channel Local/2*4002702123*2424@outgoing-0000000d;2 joined 'simple_bridge' basic-bridge <893d361d-b0aa-4aa7-a2de-1045911f36e5> [2022-09-08 13:48:58] -- Local/2*4002702123*2122@outgoing-00000010;1 requested media update control 26, passing it to Local/2122@originate-local-00000011;1 [2022-09-08 13:48:58] > Move-swap optimizing Local/2*4002702123*2424@outgoing-0000000d;1 <-- Local/2*4002702123*2122@outgoing-00000010;2. [2022-09-08 13:48:58] -- Channel Local/2*4002702123*2122@outgoing-00000010;2 left 'simple_bridge' basic-bridge <893d361d-b0aa-4aa7-a2de-1045911f36e5> [2022-09-08 13:48:58] -- Channel Local/2*4002702123*2424@outgoing-0000000d;1 left 'simple_bridge' basic-bridge <a2c0bb81-76a3-4059-8905-48c60bc95a16> [2022-09-08 13:48:58] -- Channel Local/2*4002702123*2122@outgoing-00000010;2 swapped with Local/2*4002702123*2424@outgoing-0000000d;1 into 'simple_bridge' basic-bridge <a2c0bb81-76a3-4059-8905-48c60bc95a16> [2022-09-08 13:48:58] DEBUG[31860][C-00000006]: pbx.c:4463 __ast_pbx_run: Spawn extension (outgoing-ring,2424,2) exited non-zero on 'Local/2*4002702123*2424@outgoing-0000000d;1' [2022-09-08 13:48:58] == Spawn extension (outgoing-ring, 2424, 2) exited non-zero on 'Local/2*4002702123*2424@outgoing-0000000d;1' {noformat} What is "Move-swap optimizing Local <-- Local" supposed to mean, other than a local channel optimization? In this particular case, it did not cause an issue, but when this was causing issues, several of those were happening and it basically pulled the rug out completely from my call, essentially corrupting my state and requiring all channels to manually be hung up, since at that point, those channels would never hang up on their own since the essential state information was lost. For now I'm a bit hesitant to use Bridge as it seems that, perhaps subject to some race condition, unwanted optimizations can occur, but if there's a way to use Bridge() without triggering one, e.g. like a WaitToBeBridged() for channel A, then maybe that would be more foolproof. ConfBridge() doesn't require a masquerade since each channel is entering a bridge on its own volition, and I'd like to basically emulate that with Bridge. By: Richard Mudgett (rmudgett) 2022-09-08 13:04:58.406-0500 The BridgeWait application was created for this situation as that application puts the channel into a holding bridge to wait for the other channel to use the Bridge application on it. This way the channel can be bridged without a masquerade. If local channel optimization happened to local channels that were created with the /n option then there would be a bug there. Local channel optimization is only checked when both ends of the local channel are in a bridge. By: Friendly Automation (friendly-automation) 2022-09-12 07:49:30.926-0500 Change 19175 merged by Friendly Automation: func_frame_trace: Remove bogus assertion. [https://gerrit.asterisk.org/c/asterisk/+/19175|https://gerrit.asterisk.org/c/asterisk/+/19175] By: Friendly Automation (friendly-automation) 2022-09-12 07:49:33.960-0500 Change 19174 merged by Friendly Automation: func_frame_trace: Remove bogus assertion. [https://gerrit.asterisk.org/c/asterisk/+/19174|https://gerrit.asterisk.org/c/asterisk/+/19174] By: Friendly Automation (friendly-automation) 2022-09-12 07:49:39.057-0500 Change 19150 merged by Friendly Automation: func_frame_trace: Remove bogus assertion. [https://gerrit.asterisk.org/c/asterisk/+/19150|https://gerrit.asterisk.org/c/asterisk/+/19150] By: Friendly Automation (friendly-automation) 2022-09-12 07:49:43.388-0500 Change 19173 merged by Friendly Automation: func_frame_trace: Remove bogus assertion. [https://gerrit.asterisk.org/c/asterisk/+/19173|https://gerrit.asterisk.org/c/asterisk/+/19173] By: Friendly Automation (friendly-automation) 2022-09-12 07:49:45.448-0500 Change 19172 merged by Friendly Automation: func_frame_trace: Remove bogus assertion. [https://gerrit.asterisk.org/c/asterisk/+/19172|https://gerrit.asterisk.org/c/asterisk/+/19172] | ||