TLS trunk not disconnecting if exension hangs up first

FreePBX Providers
1

I see another individual had this issue in 2022

When i use a UDP telnyx trunk. Hangup behavior works as expected.

When I use a TLS telnyx trunk, hangup behavior fails under these conditions;
Incoming call from Telnyx to PBX to Extension.
Extension hangs up, and channel says open
I’m guessing FreePbx is not sending a corresponding BYE message to a trunk.

When I use a TLS telnyx trunk, hangup behavior works under these conidions;
Incoming call from Telnyx to PBX to Extension
Incoming call hangs up, channel closes.

Anyone experience this issue?

2

Please do not guess. Please provide definitive logs.

Also please say which version of Asterisk in use.

My guess would be that you have lost the incoming TCP connection and, for some reason, Asterisk is unable to set up an outgoing one, for the BYE.

3

Easy enough. Logs logs.

Current Asterisk Version: 18.13.0

Here is a log when a UDP channel closes

56237	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [**100@from-internal:2] Set("PJSIP/102-00000010", "PICKUP_EXTEN=102") in new stack	
56238	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [**100@from-internal:3] Pickup("PJSIP/102-00000010", "100&100@PICKUPMARK") in new stack	
56239	[2024-03-23 13:12:11] NOTICE[31342][C-0000000b] app_directed_pickup.c: PJSIP/100-0000000f pickup by PJSIP/102-00000010	
56240	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Spawn extension (from-internal, **100, 3) exited non-zero on 'PJSIP/100-0000000f'	
56241	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/100-0000000f", "hangupcall") in new stack	
56242	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/100-0000000f", "1?theend") in new stack	
56243	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
56244	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/100-0000000f", "0?Set(CDR(recordingfile)=)") in new stack	
56245	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/100-0000000f", "") in new stack	
56246	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/100-0000000f' in macro 'hangupcall'	
56247	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/100-0000000f'	
56248	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] app_stack.c: PJSIP/100-0000000f Internal Gosub(crm-hangup,s,1) start	
56249	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/100-0000000f", "Sending Hangup to CRM") in new stack	
56250	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/100-0000000f", "HANGUP CAUSE: 26") in new stack	
56251	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/100-0000000f", "0?Set(__CRM_VOICEMAIL=)") in new stack	
56252	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/100-0000000f", "MASTER CHANNEL: 1711224726.60 = 1711224725.59") in new stack	
56253	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/100-0000000f", "1?return") in new stack	
56254	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx_builtins.c: Goto (crm-hangup,s,8)	
56255	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/100-0000000f", "") in new stack	
56256	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/100-0000000f'	
56257	[2024-03-23 13:12:11] VERBOSE[31342][C-0000000b] app_stack.c: PJSIP/100-0000000f Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=	
56258	[2024-03-23 13:12:11] VERBOSE[31274][C-0000000a] app_dial.c: PJSIP/102-00000010 answered PJSIP/CA-Sacramento-HWY50-0000000e	
56259	[2024-03-23 13:12:11] VERBOSE[31344][C-0000000a] bridge_channel.c: Channel PJSIP/102-00000010 joined 'simple_bridge' basic-bridge <f3e59dbe-de9f-4733-b3ac-917617fb3459>	
56260	[2024-03-23 13:12:11] VERBOSE[31274][C-0000000a] bridge_channel.c: Channel PJSIP/CA-Sacramento-HWY50-0000000e joined 'simple_bridge' basic-bridge <f3e59dbe-de9f-4733-b3ac-917617fb3459>	
56261	[2024-03-23 13:12:21] VERBOSE[31344][C-0000000a] res_srtp.c: SRTCP unprotect failed on SSRC 425472274 because of unable to perform desired validation	
56262	[2024-03-23 13:12:26] VERBOSE[31344][C-0000000a] res_srtp.c: SRTCP unprotect failed on SSRC 425472274 because of unable to perform desired validation	
56263	[2024-03-23 13:12:31] VERBOSE[31344][C-0000000a] res_srtp.c: SRTCP unprotect failed on SSRC 425472274 because of unable to perform desired validation	
56264	[2024-03-23 13:12:34] VERBOSE[31344][C-0000000a] bridge_channel.c: Channel PJSIP/102-00000010 left 'simple_bridge' basic-bridge <f3e59dbe-de9f-4733-b3ac-917617fb3459>	
56265	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] bridge_channel.c: Channel PJSIP/CA-Sacramento-HWY50-0000000e left 'simple_bridge' basic-bridge <f3e59dbe-de9f-4733-b3ac-917617fb3459>	
56266	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_macro.c: Spawn extension (macro-dial-one, s, 63) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e' in macro 'dial-one'	
56267	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e' in macro 'exten-vm'	
56268	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Spawn extension (ext-local, 100, 3) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e'	
56269	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/CA-Sacramento-HWY50-0000000e", "hangupcall,") in new stack	
56270	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/CA-Sacramento-HWY50-0000000e", "1?theend") in new stack	
56271	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
56272	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/CA-Sacramento-HWY50-0000000e", "0?Set(CDR(recordingfile)=)") in new stack	
56273	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/CA-Sacramento-HWY50-0000000e", "") in new stack	
56274	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e' in macro 'hangupcall'	
56275	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e'	
56276	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_stack.c: PJSIP/CA-Sacramento-HWY50-0000000e Internal Gosub(crm-hangup,s,1) start	
56277	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/CA-Sacramento-HWY50-0000000e", "Sending Hangup to CRM") in new stack	
56278	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/CA-Sacramento-HWY50-0000000e", "HANGUP CAUSE: 16") in new stack	
56279	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/CA-Sacramento-HWY50-0000000e", "0?Set(__CRM_VOICEMAIL=)") in new stack	
56280	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/CA-Sacramento-HWY50-0000000e", "MASTER CHANNEL: 1711224725.59 = 1711224725.59") in new stack	
56281	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/CA-Sacramento-HWY50-0000000e", "0?return") in new stack	
56282	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/CA-Sacramento-HWY50-0000000e", "__CRM_HANGUP=1") in new stack	
56283	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/CA-Sacramento-HWY50-0000000e", "agi://127.0.0.1/sangomacrm.agi") in new stack	
56284	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] res_agi.c: <PJSIP/CA-Sacramento-HWY50-0000000e>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0	
56285	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/CA-Sacramento-HWY50-0000000e", "") in new stack	
56286	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-0000000e'	
56287	[2024-03-23 13:12:34] VERBOSE[31274][C-0000000a] app_stack.c: PJSIP/CA-Sacramento-HWY50-0000000e Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

.
.
and here is a log with a TLS trunk does not close
.
.

57018	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [**100@from-internal:1] Macro("PJSIP/102-00000013", "user-callerid,") in new stack	
57019	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/102-00000013", "TOUCH_MONITOR=1711225138.83") in new stack	
57020	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/102-00000013", "CHANCONTEXT=") in new stack	
57021	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/102-00000013", "CHANCONTEXT=") in new stack	
57022	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/102-00000013", "CHANEXTENCONTEXT=102-00000013") in new stack	
57023	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/102-00000013", "CHANEXTEN=102-00000013") in new stack	
57024	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:6] Set("PJSIP/102-00000013", "CALLERID(number)=102") in new stack	
57025	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/102-00000013", "AMPUSER=102") in new stack	
57026	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:8] Set("PJSIP/102-00000013", "HOTDESCKCHAN=102-00000013") in new stack	
57027	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/102-00000013", "HOTDESKEXTEN=102") in new stack	
57028	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/102-00000013", "HOTDESKCALL=0") in new stack	
57029	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:11] ExecIf("PJSIP/102-00000013", "0?Set(HOTDESKCALL=1)") in new stack	
57030	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:12] ExecIf("PJSIP/102-00000013", "0?Set(CALLERID(name)=)") in new stack	
57031	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/102-00000013", "0?report") in new stack	
57032	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/102-00000013", "1?Set(REALCALLERIDNUM=102)") in new stack	
57033	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:15] Set("PJSIP/102-00000013", "AMPUSER=102") in new stack	
57034	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/102-00000013", "0?limit") in new stack	
57035	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:17] Set("PJSIP/102-00000013", "AMPUSERCIDNAME=Magdalena Panscik - Cell") in new stack	
57036	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("PJSIP/102-00000013", "0?Set(__CIDMASQUERADING=TRUE)") in new stack	
57037	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("PJSIP/102-00000013", "0?report") in new stack	
57038	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/102-00000013", "AMPUSERCID=102") in new stack	
57039	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:21] Set("PJSIP/102-00000013", "__DIAL_OPTIONS=HhTtr") in new stack	
57040	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:22] Set("PJSIP/102-00000013", "CALLERID(all)="Magdalena Panscik - Cell" <102>") in new stack	
57041	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:23] ExecIf("PJSIP/102-00000013", "0?Set(CUSDIAL=)") in new stack	
57042	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:24] ExecIf("PJSIP/102-00000013", "0?Set(CALLERID(all)="Magdalena Panscik - Cell" <102>)") in new stack	
57043	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:25] GotoIf("PJSIP/102-00000013", "0?limit") in new stack	
57044	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:26] ExecIf("PJSIP/102-00000013", "0?Set(GROUP(concurrency_limit)=102)") in new stack	
57045	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:27] ExecIf("PJSIP/102-00000013", "0?Set(CHANNEL(language)=)") in new stack	
57046	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:28] NoOp("PJSIP/102-00000013", "Macro Depth is 1") in new stack	
57047	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:29] GotoIf("PJSIP/102-00000013", "1?report2:macroerror") in new stack	
57048	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx_builtins.c: Goto (macro-user-callerid,s,30)	
57049	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:30] GotoIf("PJSIP/102-00000013", "0?continue") in new stack	
57050	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:31] ExecIf("PJSIP/102-00000013", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack	
57051	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:32] Set("PJSIP/102-00000013", "__TTL=64") in new stack	
57052	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:33] GotoIf("PJSIP/102-00000013", "1?continue") in new stack	
57053	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx_builtins.c: Goto (macro-user-callerid,s,49)	
57054	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:49] Set("PJSIP/102-00000013", "CALLERID(number)=102") in new stack	
57055	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:50] Set("PJSIP/102-00000013", "CALLERID(name)=Magdalena Panscik - Cell") in new stack	
57056	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:51] GotoIf("PJSIP/102-00000013", "0?cnum") in new stack	
57057	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:52] Set("PJSIP/102-00000013", "CDR(cnam)=Magdalena Panscik - Cell") in new stack	
57058	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:53] Set("PJSIP/102-00000013", "CDR(cnum)=102") in new stack	
57059	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-user-callerid:54] Set("PJSIP/102-00000013", "CHANNEL(language)=en") in new stack	
57060	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [**100@from-internal:2] Set("PJSIP/102-00000013", "PICKUP_EXTEN=102") in new stack	
57061	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [**100@from-internal:3] Pickup("PJSIP/102-00000013", "100&100@PICKUPMARK") in new stack	
57062	[2024-03-23 13:18:58] NOTICE[1655][C-0000000d] app_directed_pickup.c: PJSIP/100-00000012 pickup by PJSIP/102-00000013	
57063	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Spawn extension (from-internal, **100, 3) exited non-zero on 'PJSIP/100-00000012'	
57064	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/100-00000012", "hangupcall") in new stack	
57065	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/100-00000012", "1?theend") in new stack	
57066	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
57067	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/100-00000012", "0?Set(CDR(recordingfile)=)") in new stack	
57068	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/100-00000012", "") in new stack	
57069	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/100-00000012' in macro 'hangupcall'	
57070	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/100-00000012'	
57071	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] app_stack.c: PJSIP/100-00000012 Internal Gosub(crm-hangup,s,1) start	
57072	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/100-00000012", "Sending Hangup to CRM") in new stack	
57073	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/100-00000012", "HANGUP CAUSE: 26") in new stack	
57074	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/100-00000012", "0?Set(__CRM_VOICEMAIL=)") in new stack	
57075	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/100-00000012", "MASTER CHANNEL: 1711225131.76 = 1711225131.75") in new stack	
57076	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/100-00000012", "1?return") in new stack	
57077	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx_builtins.c: Goto (crm-hangup,s,8)	
57078	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/100-00000012", "") in new stack	
57079	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/100-00000012'	
57080	[2024-03-23 13:18:58] VERBOSE[1655][C-0000000d] app_stack.c: PJSIP/100-00000012 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=	
57081	[2024-03-23 13:18:58] VERBOSE[1622][C-0000000c] app_dial.c: PJSIP/102-00000013 answered PJSIP/CA-Sacramento-HWY50-TLS-00000011	
57082	[2024-03-23 13:18:58] VERBOSE[1657][C-0000000c] bridge_channel.c: Channel PJSIP/102-00000013 joined 'simple_bridge' basic-bridge <4375a0f2-2cc2-495c-ae08-c471fc2fbdd3>	
57083	[2024-03-23 13:18:58] VERBOSE[1622][C-0000000c] bridge_channel.c: Channel PJSIP/CA-Sacramento-HWY50-TLS-00000011 joined 'simple_bridge' basic-bridge <4375a0f2-2cc2-495c-ae08-c471fc2fbdd3>	
57084	[2024-03-23 13:19:03] VERBOSE[1657][C-0000000c] bridge_channel.c: Channel PJSIP/102-00000013 left 'simple_bridge' basic-bridge <4375a0f2-2cc2-495c-ae08-c471fc2fbdd3>	
57085	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] bridge_channel.c: Channel PJSIP/CA-Sacramento-HWY50-TLS-00000011 left 'simple_bridge' basic-bridge <4375a0f2-2cc2-495c-ae08-c471fc2fbdd3>	
57086	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_macro.c: Spawn extension (macro-dial-one, s, 63) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011' in macro 'dial-one'	
57087	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011' in macro 'exten-vm'	
57088	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Spawn extension (ext-local, 100, 3) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011'	
57089	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "hangupcall,") in new stack	
57090	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "1?theend") in new stack	
57091	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
57092	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "0?Set(CDR(recordingfile)=)") in new stack	
57093	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "") in new stack	
57094	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011' in macro 'hangupcall'	
57095	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011'	
57096	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_stack.c: PJSIP/CA-Sacramento-HWY50-TLS-00000011 Internal Gosub(crm-hangup,s,1) start	
57097	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "Sending Hangup to CRM") in new stack	
57098	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "HANGUP CAUSE: 16") in new stack	
57099	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "0?Set(__CRM_VOICEMAIL=)") in new stack	
57100	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "MASTER CHANNEL: 1711225131.75 = 1711225131.75") in new stack	
57101	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "0?return") in new stack	
57102	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "__CRM_HANGUP=1") in new stack	
57103	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "agi://127.0.0.1/sangomacrm.agi") in new stack	
57104	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] res_agi.c: <PJSIP/CA-Sacramento-HWY50-TLS-00000011>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0	
57105	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/CA-Sacramento-HWY50-TLS-00000011", "") in new stack	
57106	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/CA-Sacramento-HWY50-TLS-00000011'	
57107	[2024-03-23 13:19:03] VERBOSE[1622][C-0000000c] app_stack.c: PJSIP/CA-Sacramento-HWY50-TLS-00000011 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
4

I have a video showing the TLS trunk not closing the connection.

Have a look at this video. In the video I first show a UDP trunk properly closing the connection, then I show a TLS trunk not properly closing the connection

5

Not really useful. We need technical data, in particular, the “pjsip set logger on” output, although if the TCP connection is being dropped we made need some level of debug logging, or a tcpdump/wireshark capture, to see when the TCP connection, under the TLS one, is dropped.

6

Alrighty… some more logs. 3x to be exact. I will explain the difference of each log at the top of each log.

UDP trunk.
Call origination: from cell phone
Call answered: On extension
Call termination initiated: On extension

.
.
.
.
.
.
TLS trunk.
Call origination: from cell phone
Call answered: On extension
Call termination initiated: On extension

.
.
.
.
…
TLS trunk.
Call origination: from cell phone
Call answered: On extension
Call termination initiated: On extension
Then call termination initiated: On cellphone

7

Unfortunately, this file will not copy and paste cleanly and won’t save into a revisable form, but line 9635 shows Asterisk attempting to stop the incoming leg but getting no error or reply.

Also shows Asterisk sending BYE without a response. It then receives BYE, but ignores it, because it considers the call long since dead:

SIP/2.0 481 Call/Transaction Does Not Exist

I think we would need tcpdump/wireshark output, with matching timestamps, to see what was happening on the TLS connection (although encrypted, one would see that something was sent and probably see connections being taken down.

The recommended way of providing logs is as plain text, taken from the Asterisk full log file, and posted to a pastebin server.

8

Just wanted to comment that I have a Telnyx TLS trunk working and can compare your configuration to mine if you’d like to share it.

9

Sure bill. Sounds like a easy enough.

How would you like to receive my settings. do you want a copy of my pjsip.conf file? Or a screenshot of the GUI?

10

I have some additional info regarding this issue. Which leans towards this being a PBX issue, not a Telnyx issue.

Due to the nature of TLS, TLS logs at Telnyx are not available.

However the ladder is available. Here is the Telnyx ladder;

The ladder shows Telnyx not receiving the BYE command from the PBX, then later when the external caller terminates Telnyx responding with its own BYE command, then the PBX saying that the call/transaction does not exist.

When an incoming call to the PBX is first terminated by an internal extension, I believe the PBX is not sending a BYE command to Telnyx.

image
image452×817 17.9 KB

11

Where’s the first BYE?

12

Hi Bill,

I got it wrong and have corrected my post.

The ladder shows Telnyx not receiving the BYE command from the PBX, then later when the external caller terminates Telnyx responding with its own BYE command, then the PBX saying that the call/transaction does not exist.

When an incoming call to the PBX is first terminated by an internal extension, I believe the PBX is not sending a BYE command to Telnyx.

This same behavior is corroborated in the previous PBX logs where the PBX does not show a BYE command in the logs when a incoming call is first terminated by an internal extension.

I am leaning towards this being a PBX issue.

In the spirit of pushing forward with an additional test to offer more clues, is there a CLI command that can be used to send a BYE command to a trunk? Or a similar technique…

13

Your logs from Asterisk show Asterisk sending the BYE. I suspect you lost the TLS session. Even though you can’t see the clear text of the contents, you can still see the timing and lengths, and possibly some of the TLS session control, so you should be able to work out whether the TLS connection was down and whether a BYE was sent, over TLS.

14

Sigh… logs make me cross-eyed.

Is there a way for me to SSH into the PBX and send a command to force a trunk to issue a BYE command?

Just looking for other tests I can run here.

15

Just a thought. Do you have “Rewrite Contact” set to no in your trunk advanced settings? (You should)

I am suspicious that Asterisk is modifying the Contact it receives and thus not sending BYE requests to the correct address.

16

Good thought bill. I confirm “Rewrite Contact” is set for “No”

17

I now have a clean install of PBX 18.13.0 on a Vultr VM.
Its for testing and giving this issue full attention.

It has one TLS trunk and one extension.

I am getting the exact same behavior.

(1) Call originates from outside
(2) Call routes through to an internal extension
(3) Extension answers, audio flows both directions
(4) Extension hangs up
(5) Telnyx acts like they didn’t receive a BYE command
(6) External phone never terminates.

What other TLS trunk providers are people using? I would like to test 2 other TLS trunk providers to do a proof of where the issue is at.

If the other 2 providers function properly and Telnyx does not function properly, its a Telnyx issue.
If the other 2 providers do not function similar to Telnyx, then its a freepbx issue.

18

How is the behavior on outbound calls to Telnyx?

19

I dont believe I have done this specific test. An outbound call also has the same issue if the internal extension hangs up first, the outside phone remains connected.

20

I upgraded freepbx to the most recent Current Asterisk Version: 18.20.2

Same issue…

I then decided to get away from Telnyx and deploy a Twilio trunk.

Same issue…

What should I try next?