Some calls not connecting with PJSip

paultgreen · March 1, 2024, 10:24am

Hi all, I’ve got a curious problem here - our phone system is refusing to connect calls to certain numbers with seemingly no rhyme or reason to which numbers it likes, and which numbers it dislikes… but always the same numbers. I can have two numbers on the same dialing code and it will consistently allow calls to one, but not the other. Any help would be appreciated. This was happening on 14.x but I’ve just upgraded the server to 15.0.37.4 today (Asterisk 13.38.3). We use Orbtalk for our trunk and have done for many years without too many problems. The curious thing is that when this happens, the phones do ring at the other end, as clients have called us back asking why we’ve given them a one-ring call.

From what I can see in the trace, all is the same until the successful call goes through a couple of rounds of “making progress” before ringing, whereas the failed call jumps straight to “ringing” and then throwing the following:

[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@macro-dialout-trunk:37] Dial("PJSIP/extn-00000xxx", "PJSIP/02920123456@Orbtalk_PJ,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^02920123456^02920123456^1^1709284901^^01633xxxxxx)") in new stack	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(func-apply-sipheaders,s,1(1)) start	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/Orbtalk_PJ-00000xxx", "Applying SIP Headers to channel PJSIP/Orbtalk_PJ-00000xxx") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/Orbtalk_PJ-00000xxx", "TECH=PJSIP") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/Orbtalk_PJ-00000xxx", "SIPHEADERKEYS=Alert-Info") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Orbtalk_PJ-00000xxx", "1") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/Orbtalk_PJ-00000xxx", "sipheader=unset") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?SIPRemoveHeader(Alert-Info:)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "1?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack	
[time] ERROR[1485] res_pjsip_header_funcs.c: No headers had been previously added to this session.	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?SIPAddHeader(Alert-Info:unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:13] EndWhile("PJSIP/Orbtalk_PJ-00000xxx", "") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Orbtalk_PJ-00000xxx", "0") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:14] Return("PJSIP/Orbtalk_PJ-00000xxx", "") in new stack	
[time] VERBOSE[x][C-00000xx] app_stack.c: Spawn extension (from-trunk, 02920123456, 1) exited non-zero on 'PJSIP/Orbtalk_PJ-00000xxx'	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=	
[time] VERBOSE[x][C-00000xx] app_dial.c: Called PJSIP/02920123456@Orbtalk_PJ	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is ringing	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is ringing	
[time] ERROR[13940] pjproject: sip_inv.c ....Error parsing/validating SDP body: Missing SDP rtpmap for dynamic payload type (PJMEDIA_SDP_EMISSINGRTPMAP)	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx answered PJSIP/extn-00000xxx	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(sub-send-obroute-email,s,1(02920123456,02920123456,1,1709284901,,01633xxxxxx)) start	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@sub-send-obroute-email:1] GotoIf("PJSIP/Orbtalk_PJ-00000xxx", "0?sendEmail") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@sub-send-obroute-email:2] NoOp("PJSIP/Orbtalk_PJ-00000xxx", "email notifications disabled..exiting.") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@sub-send-obroute-email:3] Return("PJSIP/Orbtalk_PJ-00000xxx", "") in new stack	
[time] VERBOSE[x][C-00000xx] app_stack.c: Spawn extension (from-trunk, , 1) exited non-zero on 'PJSIP/Orbtalk_PJ-00000xxx'	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(sub-send-obroute-email,s,1(02920123456,02920123456,1,1709284901,,01633xxxxxx)) complete GOSUB_RETVAL=	
[time] VERBOSE[31093][C-00000xx] bridge_channel.c: Channel PJSIP/Orbtalk_PJ-00000xxx joined 'simple_bridge' basic-bridge <58195129-f15d-4d45-8abc-89805e98b603>	
[time] VERBOSE[x][C-00000xx] bridge_channel.c: Channel PJSIP/extn-00000xxx joined 'simple_bridge' basic-bridge <58195129-f15d-4d45-8abc-89805e98b603>	
[time] VERBOSE[31093][C-00000xx] bridge_channel.c: Channel PJSIP/Orbtalk_PJ-00000xxx left 'simple_bridge' basic-bridge <58195129-f15d-4d45-8abc-89805e98b603>	
[time] VERBOSE[x][C-00000xx] bridge_channel.c: Channel PJSIP/extn-00000xxx left 'simple_bridge' basic-bridge <58195129-f15d-4d45-8abc-89805e98b603>

On a working call, the same section of the log is:

[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@macro-dialout-trunk:37] Dial("PJSIP/extn-00000xxx", "PJSIP/02920123456@Orbtalk_PJ,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^02920123456^02920123456^1^1709286729^^01633xxxxxx)") in new stack	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(func-apply-sipheaders,s,1(1)) start	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/Orbtalk_PJ-00000xxx", "Applying SIP Headers to channel PJSIP/Orbtalk_PJ-00000xxx") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/Orbtalk_PJ-00000xxx", "TECH=PJSIP") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/Orbtalk_PJ-00000xxx", "SIPHEADERKEYS=Alert-Info") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Orbtalk_PJ-00000xxx", "1") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/Orbtalk_PJ-00000xxx", "sipheader=unset") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?SIPRemoveHeader(Alert-Info:)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "1?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack	
[time] ERROR[7998] res_pjsip_header_funcs.c: No headers had been previously added to this session.	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?SIPAddHeader(Alert-Info:unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/Orbtalk_PJ-00000xxx", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:13] EndWhile("PJSIP/Orbtalk_PJ-00000xxx", "") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Orbtalk_PJ-00000xxx", "0") in new stack	
[time] VERBOSE[x][C-00000xx] pbx.c: Executing [s@func-apply-sipheaders:14] Return("PJSIP/Orbtalk_PJ-00000xxx", "") in new stack	
[time] VERBOSE[x][C-00000xx] app_stack.c: Spawn extension (from-trunk, 02920123456, 1) exited non-zero on 'PJSIP/Orbtalk_PJ-00000xxx'	
[time] VERBOSE[x][C-00000xx] app_stack.c: PJSIP/Orbtalk_PJ-00000xxx Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=	
[time] VERBOSE[x][C-00000xx] app_dial.c: Called PJSIP/02920123456@Orbtalk_PJ	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is making progress passing it to PJSIP/extn-00000xxx	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is making progress passing it to PJSIP/extn-00000xxx	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is making progress passing it to PJSIP/extn-00000xxx	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is making progress passing it to PJSIP/extn-00000xxx	
[time] SECURITY[2624] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2024-03-01T09:52:11.593+0000",Severity="Informational",Service="AMI",EventVersion="1",AccountID="myadminuser",SessionID="0x7f13e00d2498",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/41726",UsingPassword="0",SessionTV="2024-03-01T09:52:11.593+0000"	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is ringing	
[time] VERBOSE[x][C-00000xx] app_dial.c: PJSIP/Orbtalk_PJ-00000xxx is ringing

Stewart1 · March 1, 2024, 11:10am

Possibly, an encryption issue. Test with Media Encryption set to None (I know nothing about Orbtalk; you may have to also turn it off on their portal).

Possibly, a codec issue. As a test, on the Codecs tab for the trunk, enable only alaw and ulaw. If it still fails, turn on pjsip logger, paste a new log at pastebin.com and post the link here.

If alaw/ulaw works: Does Orbtalk support wideband calls, e.g. when the remote party is VoLTE capable? If not, call it fixed. If yes, provide details so we can get wideband working.

david55 · March 1, 2024, 12:35pm

My guess would be that the incoming packet has been truncated. First make sure that you are not enabling all codecs. If you are specifying a reasonable number, use the CLI pjsip set logger on command to capture the actual SDP received.

paultgreen · March 1, 2024, 1:08pm

Thanks Stewart. Dropping down to the basic codecs has done the trick. Currently got a ticket open with them to see how we go about/if we can enable any others.

system · March 8, 2024, 1:08pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.