Incoming call from mobile phone dropped on ring group

klausg · March 30, 2021, 4:52pm

I’m using FreePBX 15.0.17.24 with PJSIP. An incoming call to a trunk that connects to a ring group gets hangup in dialparties.agi. The caller hears a short ring then gets disconnected. Funny thing is that it happens only on calls from mobile phones. Calling myself using another trunk gets through normal and the extensions ring. Everything works fine if I replace the ring group by a single phone extension as endpoint.
In the log I see AGI Script agi://127.0.0.1/dialparties.agi completed, returning 4
Any help is highly appreciated.

Here the output if dialparties.agi

[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Starting New Dialparties.agi
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Caller ID name is 'anonymous' number is 'anonymous'
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: CW Ignore is:
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: CF Ignore is:
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: CW IN_USE/BUSY is: 1
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Methodology of ring is  'ringall-prim'
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Added extension 26 to extension map
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Added extension 27 to extension map
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Extension 26 cf is disabled
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Extension 27 cf is disabled
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Extension 26 do not disturb is disabled
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: agi://127.0.0.1/dialparties.agi: Extension 27 do not disturb is disabled
[2021-03-30 10:20:42] VERBOSE[22741][C-00000016] res_agi.c: AGI Script agi://127.0.0.1/dialparties.agi completed, returning 4.

klausg · April 4, 2021, 8:36am

Can anyone help?

It happens if a dial my number from a mobile phone. The phones in the ring group ring once and then the line hangs up. Calling from a landline phone gets through nomal and all phones in the ringgroup ring. If I replace in the incoming route the ringgroup by an extension, the call get through normal. Because of that I suspect the problem is with dialparties.agi.

Here the full call log with until the line drops. AGI debugging is on.

Connected to Asterisk 16.15.0 currently running on pbx (pid = 1389)
pbx*CLI> agi set debug on
AGI Debugging Enabled
pbx*CLI> core set verbose 9
Console verbose was 1 and is now 9.
  == Setting global variable 'SIPDOMAIN' to '178.4.36.246'
    -- Executing [711XXXXXXX@from-pstn-de:1] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CALLERID(num)=00172XXXXXXX)") in new stack
    -- Executing [711XXXXXXX@from-pstn-de:2] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CALLERID(num)=0172XXXXXXX)") in new stack
    -- Executing [711XXXXXXX@from-pstn-de:3] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CALLERID(num)=XXXXXXX)") in new stack
    -- Executing [711XXXXXXX@from-pstn-de:4] Goto("PJSIP/Vodafone0711-XXXXXXX-0000007c", "from-pstn,711XXXXXXX,1") in new stack
    -- Goto (from-pstn,711XXXXXXX,1)
    -- Executing [711XXXXXXX@from-pstn:1] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__DIRECTION=INBOUND") in new stack
    -- Executing [711XXXXXXX@from-pstn:2] Gosub("PJSIP/Vodafone0711-XXXXXXX-0000007c", "sub-record-check,s,1(in,711XXXXXXX,force)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?initialized") in new stack
    -- Executing [s@sub-record-check:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:3] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "NOW=1617435022") in new stack
    -- Executing [s@sub-record-check:4] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__DAY=03") in new stack
    -- Executing [s@sub-record-check:5] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__MONTH=04") in new stack
    -- Executing [s@sub-record-check:6] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__YEAR=2021") in new stack
    -- Executing [s@sub-record-check:7] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__TIMESTR=20210403-093022") in new stack
    -- Executing [s@sub-record-check:8] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__FROMEXTEN=unknown") in new stack
    -- Executing [s@sub-record-check:9] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:10] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "2?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?sub-record-check,in,1") in new stack
    -- Goto (sub-record-check,in,1)
    -- Executing [in@sub-record-check:1] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Inbound Recording Check to 711XXXXXXX") in new stack
    -- Executing [in@sub-record-check:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "FROMEXTEN=unknown") in new stack
    -- Executing [in@sub-record-check:3] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "11?Set(FROMEXTEN=0172XXXXXXX)") in new stack
    -- Executing [in@sub-record-check:4] Gosub("PJSIP/Vodafone0711-XXXXXXX-0000007c", "recordcheck,1(force,in,711XXXXXXX)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Starting recording check against force") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/Vodafone0711-XXXXXXX-0000007c", "force") in new stack
    -- Goto (sub-record-check,recordcheck,5)
    -- Executing [recordcheck@sub-record-check:5] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__REC_POLICY_MODE=FORCE") in new stack
    -- Executing [recordcheck@sub-record-check:6] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?startrec") in new stack
    -- Goto (sub-record-check,recordcheck,16)
    -- Executing [recordcheck@sub-record-check:16] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Starting recording: in, 711XXXXXXX") in new stack
    -- Executing [recordcheck@sub-record-check:17] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__CALLFILENAME=in-711XXXXXXX-0172XXXXXXX-20210403-093022-1617435022.138") in new stack
    -- Executing [recordcheck@sub-record-check:18] MixMonitor("PJSIP/Vodafone0711-XXXXXXX-0000007c", "2021/04/03/in-711XXXXXXX-0172XXXXXXX-20210403-093022-1617435022.138.wav,abi(LOCAL_MIXMON_ID),/var/lib/asterisk/bin/wav2mp3.sh ^{CALLFILENAME} ^{UNIQUEID}") in new stack
  == Begin MixMonitor Recording PJSIP/Vodafone0711-XXXXXXX-0000007c
    -- Executing [recordcheck@sub-record-check:19] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__MIXMON_ID=0x6a84df48") in new stack
    -- Executing [recordcheck@sub-record-check:20] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__RECORD_ID=PJSIP/Vodafone0711-XXXXXXX-0000007c") in new stack
    -- Executing [recordcheck@sub-record-check:21] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__REC_STATUS=RECORDING") in new stack
    -- Executing [recordcheck@sub-record-check:22] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CDR(recordingfile)=in-711XXXXXXX-0172XXXXXXX-20210403-093022-1617435022.138.wav") in new stack
    -- Executing [recordcheck@sub-record-check:23] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [in@sub-record-check:5] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [711XXXXXXX@from-pstn:3] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CHANNEL(tonezone)=de") in new stack
    -- Executing [711XXXXXXX@from-pstn:4] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__FROM_DID=711XXXXXXX") in new stack
    -- Executing [711XXXXXXX@from-pstn:5] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "returnhere=1") in new stack
    -- Executing [711XXXXXXX@from-pstn:6] Gosub("PJSIP/Vodafone0711-XXXXXXX-0000007c", "app-blacklist-check,s,1()") in new stack
    -- Executing [s@app-blacklist-check:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?blacklisted") in new stack
    -- Executing [s@app-blacklist-check:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CALLED_BLACKLIST=1") in new stack
    -- Executing [s@app-blacklist-check:3] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [711XXXXXXX@from-pstn:7] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CDR(did)=711XXXXXXX") in new stack
    -- Executing [711XXXXXXX@from-pstn:8] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?") in new stack
    -- Executing [711XXXXXXX@from-pstn:9] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1 ?Set(CALLERID(name)=0172XXXXXXX)") in new stack
    -- Executing [711XXXXXXX@from-pstn:10] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__MOHCLASS=") in new stack
    -- Executing [711XXXXXXX@from-pstn:11] Ringing("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [711XXXXXXX@from-pstn:12] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__RINGINGSENT=TRUE") in new stack
    -- Executing [711XXXXXXX@from-pstn:13] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__REVERSAL_REJECT=FALSE") in new stack
    -- Executing [711XXXXXXX@from-pstn:14] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?post-reverse-charge") in new stack
    -- Goto (from-pstn,711XXXXXXX,16)
    -- Executing [711XXXXXXX@from-pstn:16] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [711XXXXXXX@from-pstn:17] Macro("PJSIP/Vodafone0711-XXXXXXX-0000007c", "privacy-mgr,3,10") in new stack
    -- Executing [s@macro-privacy-mgr:1] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "KEEPCID=0172XXXXXXX") in new stack
    -- Executing [s@macro-privacy-mgr:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "TESTCID=1721490121.000000") in new stack
    -- Executing [s@macro-privacy-mgr:3] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CALLERID(num)=)") in new stack
    -- Executing [s@macro-privacy-mgr:4] PrivacyManager("PJSIP/Vodafone0711-XXXXXXX-0000007c", "3,10") in new stack
    -- CallerID number present: Skipping
    -- Executing [s@macro-privacy-mgr:5] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?fail") in new stack
    -- Executing [s@macro-privacy-mgr:6] GosubIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?app-blacklist-check,s,1()") in new stack
    -- Executing [s@app-blacklist-check:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?blacklisted") in new stack
    -- Executing [s@app-blacklist-check:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CALLED_BLACKLIST=1") in new stack
    -- Executing [s@app-blacklist-check:3] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [s@macro-privacy-mgr:7] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CALLERID(num-pres)=allowed_passed_screen") in new stack
    -- Executing [s@macro-privacy-mgr:8] MacroExit("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [711XXXXXXX@from-pstn:18] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CallerID Entry Point") in new stack
    -- Executing [711XXXXXXX@from-pstn:19] Goto("PJSIP/Vodafone0711-XXXXXXX-0000007c", "ext-group,60,1") in new stack
    -- Goto (ext-group,60,1)
    -- Executing [60@ext-group:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?cid") in new stack
    -- Executing [60@ext-group:2] PlayTones("PJSIP/Vodafone0711-XXXXXXX-0000007c", "ring") in new stack
    -- Executing [60@ext-group:3] Progress("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [60@ext-group:4] Macro("PJSIP/Vodafone0711-XXXXXXX-0000007c", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "TOUCH_MONITOR=1617435022.138") in new stack
    -- Executing [s@macro-user-callerid:2] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "AMPUSER=0172XXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:3] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "HOTDESCKCHAN=Vodafone0711-XXXXXXX-0000007c") in new stack
    -- Executing [s@macro-user-callerid:4] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "HOTDESKEXTEN=Vodafone0711") in new stack
    -- Executing [s@macro-user-callerid:5] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "HOTDESKCALL=0") in new stack
    -- Executing [s@macro-user-callerid:6] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(HOTDESKCALL=1)") in new stack
    -- Executing [s@macro-user-callerid:7] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CALLERID(name)=)") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?report") in new stack
    -- Executing [s@macro-user-callerid:9] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?Set(REALCALLERIDNUM=0172XXXXXXX)") in new stack
    -- Executing [s@macro-user-callerid:10] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:11] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:12] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:13] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
    -- Executing [s@macro-user-callerid:14] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?report") in new stack
    -- Goto (macro-user-callerid,s,23)
    -- Executing [s@macro-user-callerid:23] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Macro Depth is 1") in new stack
    -- Executing [s@macro-user-callerid:24] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?report2:macroerror") in new stack
    -- Goto (macro-user-callerid,s,25)
    -- Executing [s@macro-user-callerid:25] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:26] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [s@macro-user-callerid:27] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:28] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,44)
    -- Executing [s@macro-user-callerid:44] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CALLERID(number)=0172XXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:45] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CALLERID(name)=0172XXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:46] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:47] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CDR(cnam)=0172XXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:48] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CDR(cnum)=0172XXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:49] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "CHANNEL(language)=de_DE") in new stack
    -- Executing [60@ext-group:5] Macro("PJSIP/Vodafone0711-XXXXXXX-0000007c", "blkvm-setifempty,") in new stack
    -- Executing [s@macro-blkvm-setifempty:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?init") in new stack
    -- Goto (macro-blkvm-setifempty,s,4)
    -- Executing [s@macro-blkvm-setifempty:4] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__BLKVM_CHANNEL=PJSIP/Vodafone0711-XXXXXXX-0000007c") in new stack
    -- Executing [s@macro-blkvm-setifempty:5] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "SHARED(BLKVM,PJSIP/Vodafone0711-XXXXXXX-0000007c)=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:6] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "GOSUB_RETVAL=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:7] MacroExit("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [60@ext-group:6] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?skipov") in new stack
    -- Goto (ext-group,60,9)
    -- Executing [60@ext-group:9] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "RRNODEST=") in new stack
    -- Executing [60@ext-group:10] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__NODEST=60") in new stack
    -- Executing [60@ext-group:11] GosubIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?sub-rgsetcid,s,1()") in new stack
    -- Executing [60@ext-group:12] Gosub("PJSIP/Vodafone0711-XXXXXXX-0000007c", "sub-record-check,s,1(rg,60,dontcare)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "11?initialized") in new stack
    -- Goto (sub-record-check,s,10)
    -- Executing [s@sub-record-check:10] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "REC_POLICY_MODE_SAVE=FORCE") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "2?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?sub-record-check,rg,1") in new stack
    -- Executing [s@sub-record-check:18] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Generic rg Recording Check - 0172XXXXXXX 60") in new stack
    -- Executing [s@sub-record-check:19] Gosub("PJSIP/Vodafone0711-XXXXXXX-0000007c", "recordcheck,1(dontcare,rg,60)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Starting recording check against dontcare") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/Vodafone0711-XXXXXXX-0000007c", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [recordcheck@sub-record-check:3] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [s@sub-record-check:20] Return("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
    -- Executing [60@ext-group:13] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "RingGroupMethod=ringall-prim") in new stack
    -- Executing [60@ext-group:14] Set("PJSIP/Vodafone0711-XXXXXXX-0000007c", "__ALT_CONFIRM_MSG=") in new stack
    -- Executing [60@ext-group:15] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?RGVQANNOUNCE:NORGVQANNOUNCE") in new stack
    -- Goto (ext-group,60,18)
    -- Executing [60@ext-group:18] Macro("PJSIP/Vodafone0711-XXXXXXX-0000007c", "dial,40,HhTtrQ(NO_ANSWER),20-31-23") in new stack
    -- Executing [s@macro-dial:1] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
    -- Executing [s@macro-dial:2] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:3] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:4] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:5] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [s@macro-dial:6] AGI("PJSIP/Vodafone0711-XXXXXXX-0000007c", "agi://127.0.0.1/dialparties.agi") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: dialparties.agi
AGI Tx >> agi_request: agi://127.0.0.1/dialparties.agi
AGI Tx >> agi_channel: PJSIP/Vodafone0711-XXXXXXX-0000007c
AGI Tx >> agi_language: de_DE
AGI Tx >> agi_type: PJSIP
AGI Tx >> agi_uniqueid: 1617435022.138
AGI Tx >> agi_version: 16.15.0
AGI Tx >> agi_callerid: 0172XXXXXXX
AGI Tx >> agi_calleridname: 0172XXXXXXX
AGI Tx >> agi_callingpres: 1
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 711XXXXXXX
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-dial
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 6
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >> agi_threadid: 1951806480
AGI Tx >>
AGI Rx << VERBOSE "Starting New Dialparties.agi" 1
 agi://127.0.0.1/dialparties.agi: Starting New Dialparties.agi
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE CWINUSEBUSY
AGI Tx >> 200 result=1 (1)
AGI Rx << GET VARIABLE CWIGNORE
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE CFIGNORE
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE SIGNORE
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE AMPUSER
AGI Tx >> 200 result=1 ()
AGI Rx << VERBOSE "Caller ID name is '0172XXXXXXX' number is '0172XXXXXXX'" 1
 agi://127.0.0.1/dialparties.agi: Caller ID name is '0172XXXXXXX' number is '0172XXXXXXX'
AGI Tx >> 200 result=1
AGI Rx << VERBOSE "CW Ignore is: " 1
 agi://127.0.0.1/dialparties.agi: CW Ignore is:
AGI Tx >> 200 result=1
AGI Rx << VERBOSE "CF Ignore is: " 1
 agi://127.0.0.1/dialparties.agi: CF Ignore is:
AGI Tx >> 200 result=1
AGI Rx << VERBOSE "CW IN_USE/BUSY is: 1" 1
 agi://127.0.0.1/dialparties.agi: CW IN_USE/BUSY is: 1
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE QUEUEWAIT
AGI Tx >> 200 result=0
AGI Rx << SET VARIABLE __KEEPCID "TRUE"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE DIALSTATUS_CW ""
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE ARG1
AGI Tx >> 200 result=1 (40)
AGI Rx << GET VARIABLE ARG2
AGI Tx >> 200 result=1 (HhTtrQ(NO_ANSWER))
AGI Rx << GET VARIABLE RingGroupMethod
AGI Tx >> 200 result=1 (ringall-prim)
AGI Tx >> HANGUP
AGI Rx << GET VARIABLE RVOL
AGI Tx >> 200 result=0
    -- AGI Script agi://127.0.0.1/dialparties.agi completed, returning 4
AGI Tx >> HANGUP
  == Spawn extension (macro-dial, s, 6) exited non-zero on 'PJSIP/Vodafone0711-XXXXXXX-0000007c' in macro 'dial'
  == Spawn extension (ext-group, 60, 18) exited non-zero on 'PJSIP/Vodafone0711-XXXXXXX-0000007c'
    -- Executing [h@ext-group:1] Macro("PJSIP/Vodafone0711-XXXXXXX-0000007c", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] NoOp("PJSIP/Vodafone0711-XXXXXXX-0000007c", " montior file= /var/spool/asterisk/monitor/2021/04/03/in-711XXXXXXX-0172XXXXXXX-20210403-093022-1617435022.138.wav") in new stack
    -- Executing [s@macro-hangupcall:5] GotoIf("PJSIP/Vodafone0711-XXXXXXX-0000007c", "1?skipagi") in new stack
    -- Goto (macro-hangupcall,s,7)
    -- Executing [s@macro-hangupcall:7] Hangup("PJSIP/Vodafone0711-XXXXXXX-0000007c", "") in new stack
  == Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'PJSIP/Vodafone0711-XXXXXXX-0000007c' in macro 'hangupcall'
  == Spawn extension (ext-group, h, 1) exited non-zero on 'PJSIP/Vodafone0711-XXXXXXX-0000007c'
  == MixMonitor close filestream (mixed)
  == Executing [/var/lib/asterisk/bin/wav2mp3.sh in-711XXXXXXX-0172XXXXXXX-20210403-093022-1617435022.138 1617435022.138]
pbx*CLI>

klausg · April 6, 2021, 11:23am

I don’t understand what is happening here. My gut feeling is that here may be the problem:

AGI Script agi://127.0.0.1/dialparties.agi completed, returning 4

Has anybody an idea what’s causing the return of 4 here?

klausg · April 8, 2021, 8:55am

I learned how debug the sip session with PJSIP. Here the pjsip history during a call that ends in freepbx with a ringgroup as endpoint.
I don’t understand the detailed information in the PJSIP history. Can anyone help me to understand what is going on here?

This problem only occurs when calling from a mobile phone to an ringgroup endpoint. In all other cases the call gets through and the phones in the ringgroup ring. My PSTN provider is Unitymedia (a part of Vodafone). The mobile phone is connected to the Vodafone network.

pbx*CLI> pjsip show history
No.   Timestamp  (Dir) Address                  SIP Message
===== ========== ============================== ===================================
00000 1617866034 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00001 1617866034 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00002 1617866034 * ==> 192.168.10.89:47019      OPTIONS sip:[email protected]:47019;rinstance=1a932230018c5c03 SIP/2.0
00003 1617866034 * <== 192.168.10.89:47019      SIP/2.0 200 OK
00004 1617866036 * ==> 192.168.40.21:5062       OPTIONS sip:[email protected]:5062;user=phone SIP/2.0
00005 1617866036 * <== 192.168.40.21:5062       SIP/2.0 200 OK
00006 1617866042 * ==> 192.168.40.16:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00007 1617866042 * <== 192.168.40.16:5060       SIP/2.0 200 OK
00008 1617866043 * <== 192.168.10.89:47019      REGISTER sip:192.168.40.71;transport=UDP SIP/2.0
00009 1617866043 * ==> 192.168.10.89:47019      SIP/2.0 401 Unauthorized
00010 1617866043 * <== 192.168.10.89:47019      REGISTER sip:192.168.40.71;transport=UDP SIP/2.0
00011 1617866043 * ==> 192.168.10.89:47019      SIP/2.0 200 OK
00012 1617866043 * ==> 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00013 1617866043 * <== 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00014 1617866043 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00015 1617866043 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00016 1617866044 * <== 80.69.110.108:5060       INVITE sip:[email protected]:5060 SIP/2.0
00017 1617866044 * ==> 80.69.110.108:5060       SIP/2.0 100 Trying
00018 1617866044 * ==> 80.69.110.108:5060       SIP/2.0 180 Ringing
00019 1617866044 * ==> 80.69.110.108:5060       SIP/2.0 183 Session Progress
00020 1617866045 * <== 80.69.110.108:5060       CANCEL sip:[email protected]:5060 SIP/2.0
00021 1617866045 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00022 1617866045 * ==> 80.69.110.108:5060       SIP/2.0 487 Request Terminated
00023 1617866045 * <== 80.69.110.108:5060       ACK sip:[email protected]:5060 SIP/2.0
00024 1617866049 * ==> 192.168.40.19:5060       OPTIONS sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00025 1617866049 * <== 80.69.110.108:5060       INVITE sip:[email protected]:5060 SIP/2.0
00026 1617866049 * ==> 80.69.110.108:5060       SIP/2.0 100 Trying
00027 1617866049 * <== 192.168.40.19:50351      SIP/2.0 200 OK
00028 1617866049 * ==> 80.69.110.108:5060       SIP/2.0 180 Ringing
00029 1617866049 * ==> 80.69.110.108:5060       SIP/2.0 183 Session Progress
00030 1617866049 * <== 80.69.110.108:5060       CANCEL sip:[email protected]:5060 SIP/2.0
00031 1617866049 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00032 1617866049 * ==> 80.69.110.108:5060       SIP/2.0 487 Request Terminated
00033 1617866049 * <== 80.69.110.108:5060       ACK sip:[email protected]:5060 SIP/2.0
00034 1617866050 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00035 1617866050 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00036 1617866050 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00037 1617866050 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00038 1617866050 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00039 1617866050 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00040 1617866050 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00041 1617866050 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00042 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00043 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00044 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00045 1617866051 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00046 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00047 1617866051 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00048 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00049 1617866051 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00050 1617866051 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00051 1617866051 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00052 1617866051 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00053 1617866051 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00054 1617866054 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00055 1617866054 * <== 80.69.110.108:5060       SIP/2.0 401 Unauthorized
00056 1617866054 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00057 1617866054 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00058 1617866054 * ==> 145.253.88.119:5060      OPTIONS sip:[email protected]:5060 SIP/2.0
00059 1617866054 * <== 145.253.88.119:5060      SIP/2.0 200 OK
00060 1617866054 * ==> 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00061 1617866054 * <== 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00062 1617866054 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00063 1617866054 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00064 1617866056 * ==> 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00065 1617866056 * <== 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00066 1617866056 * ==> 80.69.110.108:5060       SIP/2.0 200 OK1G
00067 1617866056 * <== 80.69.110.108:5060       SIP/2.0 200 OK
pbx*CLI>

I see that the PSTN is sending INVITE in line 16. My FreePBX answers with TRYING, RINGING and SESSION PROGESS in lines 17 - 19. Then the PSTN sends CANCEL. Here the details of lines 16 - 20. I don’t understand what the details show and why the PSTN is sending CANCEL.

pbx*CLI> pjsip show history entry 16
<--- History Entry 16 Received from 80.69.110.108:5060 at 1617866044 --->
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 80.69.110.108:5060;received=80.69.110.108;branch=z9hG4bKscqfpf30706g6s82i0e1.1
To: 
From: ;tag=snl_0102488163_NSN_CLIENT
Call-ID: NSNSIP-a6bfa8c0-a9bfa8c0-2-21-1617866044-731748-1618597792
CSeq: 1235 INVITE
Contact: 
Supported: 100rel, timer
Accept-Language: en;q=0.0
Allow: REGISTER, INVITE, ACK, BYE, CANCEL, NOTIFY, REFER, INFO, UPDATE, PRACK
P-Service-Indication: CW
Session-Expires: 1800;refresher=uac
Min-SE: 1800
Date: Thu, 08 Apr 2021 07:14:04 GMT
Max-Forwards: 18
Content-Type: application/sdp
Content-Length: 242
Content-Type: application/sdp
Content-Length:   242

v=0
o=DE-STR01A-NGN-SBC00 1426410890 0 IN IP4 80.69.110.108
s=sip call
c=IN IP4 80.69.110.108
t=0 0
m=audio 40430 RTP/AVP 9 8 100
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 telephone-event/8000
a=maxptime:30
a=ptime:20

pbx*CLI> pjsip show history entry 17
<--- History Entry 17 Sent to 80.69.110.108:5060 at 1617866044 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.69.110.108:5060;rport=5060;received=80.69.110.108;branch=z9hG4bKscqfpf30706g6s82i0e1.1
Call-ID: NSNSIP-a6bfa8c0-a9bfa8c0-2-21-1617866044-731748-1618597792
From: ;tag=snl_0102488163_NSN_CLIENT
To: 
CSeq: 1235 INVITE
Server: FPBX-15.0.17.24(16.15.0)
Content-Length:  0

pbx*CLI> pjsip show history entry 18
<--- History Entry 18 Sent to 80.69.110.108:5060 at 1617866044 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 80.69.110.108:5060;rport=5060;received=80.69.110.108;branch=z9hG4bKscqfpf30706g6s82i0e1.1
Call-ID: NSNSIP-a6bfa8c0-a9bfa8c0-2-21-1617866044-731748-1618597792
From: ;tag=snl_0102488163_NSN_CLIENT
To: ;tag=2acea765-4a06-4968-abb6-b0dc8f210f9e
CSeq: 1235 INVITE
Server: FPBX-15.0.17.24(16.15.0)
Contact: 
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0


pbx*CLI> pjsip show history entry 19
<--- History Entry 19 Sent to 80.69.110.108:5060 at 1617866044 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 80.69.110.108:5060;rport=5060;received=80.69.110.108;branch=z9hG4bKscqfpf30706g6s82i0e1.1
Call-ID: NSNSIP-a6bfa8c0-a9bfa8c0-2-21-1617866044-731748-1618597792
From: ;tag=snl_0102488163_NSN_CLIENT
To: ;tag=2acea765-4a06-4968-abb6-b0dc8f210f9e
CSeq: 1235 INVITE
Server: FPBX-15.0.17.24(16.15.0)
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: 
Content-Type: application/sdp
Content-Length:   252

v=0
o=- 1426410890 2 IN IP4 178.4.36.246
s=Asterisk
c=IN IP4 178.4.36.246
t=0 0
m=audio 12916 RTP/AVP 8 9 100
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

pbx*CLI> pjsip show history entry 20
<--- History Entry 20 Received from 80.69.110.108:5060 at 1617866045 --->
CANCEL sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 80.69.110.108:5060;received=80.69.110.108;branch=z9hG4bKscqfpf30706g6s82i0e1.1
CSeq: 1235 CANCEL
To: 
From: ;tag=snl_0102488163_NSN_CLIENT
Call-ID: NSNSIP-a6bfa8c0-a9bfa8c0-2-21-1617866044-731748-1618597792
Max-Forwards: 18
Content-Length: 0
Reason: Q.850;cause=31
Content-Length:  0

Hangup cause 31 is normal, unspecified [Q.850] according to what I found on the net. Funny is that the PSTN is sending the INVITE and CANCEL twice.

Here the a call from the same mobile phone to using an incoming route that connects to an extension. The call gets through and the entension rings. After the extension rung I hang up on my mobile.

pbx*CLI> pjsip show history
No.   Timestamp  (Dir) Address                  SIP Message
===== ========== ============================== ===================================
00000 1617869196 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00001 1617869196 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00002 1617869200 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00003 1617869200 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00004 1617869200 * ==> 192.168.40.18:5060       OPTIONS sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00005 1617869200 * <== 192.168.40.18:50087      SIP/2.0 200 OK
00006 1617869204 * ==> 192.168.40.15:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00007 1617869204 * <== 192.168.40.15:5060       SIP/2.0 200 OK
00008 1617869205 * ==> 192.168.100.254:5060     OPTIONS sip:[email protected]:5060;uniq=B1E6E9BAEC32C4F7B020D7587FE6B SIP/2.0
00009 1617869205 * <== 192.168.100.254:5060     SIP/2.0 200 OK
00010 1617869206 * ==> 217.10.79.9:5060         OPTIONS sip:[email protected]:5060 SIP/2.0
00011 1617869206 * <== 217.10.79.9:5060         SIP/2.0 200 OK
00012 1617869209 * ==> 192.168.40.19:5060       OPTIONS sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00013 1617869209 * <== 192.168.40.19:51637      SIP/2.0 200 OK
00014 1617869209 * ==> 192.168.40.21:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00015 1617869209 * <== 80.69.110.108:5060       INVITE sip:[email protected]:5060 SIP/2.0
00016 1617869210 * ==> 80.69.110.108:5060       SIP/2.0 100 Trying
00017 1617869210 * <== 192.168.40.21:5060       SIP/2.0 200 OK
00018 1617869210 * ==> 80.69.110.108:5060       SIP/2.0 180 Ringing
00019 1617869210 * ==> 192.168.40.18:5060       INVITE sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00020 1617869210 * ==> 80.69.110.108:5060       SIP/2.0 180 Ringing
00021 1617869210 * <== 192.168.40.18:53120      SIP/2.0 100 Trying
00022 1617869211 * <== 192.168.40.18:53120      SIP/2.0 180 Ringing
00023 1617869211 * ==> 80.69.110.108:5060       SIP/2.0 180 Ringing
00024 1617869215 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00025 1617869216 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00026 1617869216 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00027 1617869216 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00028 1617869216 * ==> 192.168.40.21:5062       OPTIONS sip:[email protected]:5062;user=phone SIP/2.0
00029 1617869216 * <== 192.168.40.21:5062       SIP/2.0 200 OK
00030 1617869216 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00031 1617869216 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00032 1617869216 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00033 1617869216 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00034 1617869216 * <== 192.168.10.89:47019      REGISTER sip:192.168.40.71;transport=UDP SIP/2.0
00035 1617869216 * ==> 192.168.10.89:47019      SIP/2.0 401 Unauthorized
00036 1617869216 * <== 192.168.10.89:47019      REGISTER sip:192.168.40.71;transport=UDP SIP/2.0
00037 1617869216 * ==> 192.168.10.89:47019      SIP/2.0 200 OK
00038 1617869216 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00039 1617869216 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00040 1617869220 * ==> 80.69.110.108:5060       REGISTER sip:hiq5a-sbcv461a.kabelbw.de:5060 SIP/2.0
00041 1617869220 * <== 80.69.110.108:5060       SIP/2.0 200 OK
00042 1617869220 * <== 80.69.110.108:5060       CANCEL sip:[email protected]:5060 SIP/2.0
00043 1617869220 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00044 1617869220 * ==> 80.69.110.108:5060       SIP/2.0 487 Request Terminated
00045 1617869220 * ==> 192.168.40.18:5060       CANCEL sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00046 1617869220 * <== 192.168.40.18:53120      SIP/2.0 200 OK
00047 1617869220 * <== 192.168.40.18:53120      SIP/2.0 487 Request Cancelled
00048 1617869220 * ==> 192.168.40.18:5060       ACK sip:klaus%[email protected]:5060;transport=udp SIP/2.0
00049 1617869220 * <== 80.69.110.108:5060       ACK sip:[email protected]:5060 SIP/2.0
00050 1617869222 * ==> 192.168.40.16:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00051 1617869222 * <== 192.168.40.16:5060       SIP/2.0 200 OK
00052 1617869223 * ==> 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00053 1617869223 * <== 80.69.110.108:5060       OPTIONS sip:[email protected]:5060 SIP/2.0
00054 1617869223 * ==> 80.69.110.108:5060       SIP/2.0 200 OK
00055 1617869223 * <== 80.69.110.108:5060       SIP/2.0 200 OK
pbx*CLI>

Here the sequence is <- INVITE, ->TRYING, <- OK, -> RINGING. Then the connection is set up in revers -> INVITE, -> RINGING, <- TRYING, <- RINGING.

What is different when the endpoint of the call is a ringgroup vs. an extension? Any comment or help is appreciated.

klausg · April 16, 2021, 9:24am

Nobody and hint for me?

dirk2358 · April 16, 2021, 5:30pm

Your logs are pretty unreadable for me. Would be good to have a better overview. Please let asterisk write a pcap file of the complete broken call and then take a look at it with sngrep.

asterisk -x "pjsip set logger on"
asterisk -x "pjsip set logger verbose off"
asterisk -x "pjsip set logger pcap trace.pcap"

This adds a trace.pcap file in /var/lib/asterisk most probably. You can disable logging with “pjsip set logger off”.

When reading the file with sngrep (sngrep -c -I /tmp/trace.pcap), you can see the different legs which can be displayed together (you must select the relevant legs before). It looks like this:

On the right site of the screen (I removed it here), you can see the SIP messages. Because you are facing the problem mainly related to mobile devices, I suspect there could be SDP problems. But this could be seen in the trace. But you must be familiar with reading sip traces to understand what’s going on. You could compare them with a working example and search for differences.

klausg · April 26, 2021, 9:48am

Thanks dirk2358. That’s a very good hint. I had always trouble to understand the logs. I will do that in the future.

I just noticed that the problem went away in the past days. Now everything works fine again. Calls from a mobile phone targeting a call group get through again. Looks to me like a problem on the provider side.

system · June 3, 2021, 11:12pm

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