SIP auto fallthrough with channel status 'UNKNOWN'

carriba · June 17, 2022, 10:47am

I am using Asterisk version 16.16.1 and the latest FreePBX version 16.0.21.

I am maintaining two separate trunk setups towards the same SIP provider as it can be queried with the command “sip show peers”, showing the following output:

Name/username       Host               Dyn   Forcerport  Comedia  ACL Port  Status
Adip1/555123456     191.162.216.126          Yes         Yes          5060  OK (7 ms)
Adip2/555456789     191.162.216.126          Yes         Yes          5060  OK (7 ms)

When I make a SIP call with the caller ID “555124680” towards the trunk identified with the user name “555456789” (trunk name “Adip2”), the call completion simply gets aborted, and the Asterisk log shows the following entries:

  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Executing [555456789@from-trunk-sip-Adip1:1] Set("SIP/Adip1-00000023", "GROUP()=OUT_4") in new stack
    -- Executing [555456789@from-trunk-sip-Adip1:2] Goto("SIP/Adip1-00000023", "from-trunk, 555456789,1") in new stack
    -- Goto (from-trunk,555456789,1)
    -- Executing [555456789@from-trunk:1] NoOp("SIP/Adip1-00000023", "CALLERID(num)=555124680") in new stack
    -- Executing [555456789@from-trunk:2] NoOp("SIP/Adip1-00000023", "CALLERID(name)=555124680") in new stack
    -- Executing [555456789@from-trunk:3] NoOp("SIP/Adip1-00000023", "EXTEN=555456789") in new stack
    -- Executing [555456789@from-trunk:4] NoOp("SIP/Adip1-00000023", "CHANNEL=SIP/Adip1-00000023") in new stack
    -- Executing [555456789@from-trunk:5] Set("SIP/Adip1-00000023", "CALLERID(num)=555124680") in new stack
    -- Auto fallthrough, channel 'SIP/Adip1-00000023' status is 'UNKNOWN'
    -- Executing [h@from-trunk:1] Macro("SIP/Adip1-00000023", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Adip1-00000023", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Adip1-00000023", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("SIP/Adip1-00000023", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Adip1-00000023' in macro 'hangupcall'
  == Spawn extension (from-trunk, h, 1) exited non-zero on 'SIP/Adip1-0000002

When I make a SIP call with the same caller ID “555124680” towards the trunk identified with the user name “555123456” (trunk name “Adip1”), the call gets completed and the destination rings. The Asterisk log shows the following entries:

  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Executing [555123456@from-trunk-sip-Adip1:1] Set("SIP/Adip1-00000025", "GROUP()=OUT_4") in new stack
    -- Executing [555123456@from-trunk-sip-Adip1:2] Goto("SIP/Adip1-00000025", "from-trunk,555123456,1") in new stack
    -- Goto (from-trunk,555123456,1)
    -- Executing [555123456@from-trunk:1] NoOp("SIP/Adip1-00000025", "CALLERID(num)=555124680") in new stack
    -- Executing [555123456@from-trunk:2] NoOp("SIP/Adip1-00000025", "CALLERID(name)=555124680") in new stack
    -- Executing [555123456@from-trunk:3] NoOp("SIP/Adip1-00000025", "EXTEN=555123456") in new stack
    -- Executing [555123456@from-trunk:4] NoOp("SIP/Adip1-00000025", "CHANNEL=SIP/Adip1-00000025") in new stack
    -- Executing [555123456@from-trunk:5] Set("SIP/Adip1-00000025", "CALLERID(num)=555124680") in new stack
    -- Executing [555123456@from-trunk:6] Set("SIP/Adip1-00000025", "__DIRECTION=INBOUND") in new stack
    -- Executing [555123456@from-trunk:7] Gosub("SIP/Adip1-00000025", "app-blacklist-check,s,1()") in new stack
    -- Executing [555123456@from-trunk:8] ExecIf("SIP/Adip1-00000025", "1?Set(__FROM_DID=555124680)") in new stack
    -- Executing [555123456@from-trunk:9] Set("SIP/Adip1-00000025", "CDR(did)=524858786") in new stack
    -- Executing [555123456@from-trunk:10] ExecIf("SIP/Adip1-00000025", "0 ?Set(CALLERID(name)=555124680)") in new stack
    -- Executing [555123456@from-trunk:11] Set("SIP/Adip1-00000025", "__MOHCLASS=") in new stack
    -- Executing [555123456@from-trunk:12] Set("SIP/Adip1-00000025", "__REVERSAL_REJECT=FALSE") in new stack
    -- Executing [555123456@from-trunk:13] GotoIf("SIP/Adip1-00000025", "1?post-reverse-charge") in new stack
    -- Goto (from-trunk,555123456,14)
    -- Executing [555123456@from-trunk:14] NoOp("SIP/Adip1-00000025", "") in new stack
    -- Executing [555123456@from-trunk:15] Set("SIP/Adip1-00000025", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
    -- Executing [555123456@from-trunk:16] Set("SIP/Adip1-00000025", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
    -- Executing [555123456@from-trunk:17] Set("SIP/Adip1-00000025", "CALLERID(name-pres)=allowed_not_screened") in new stack
    -- Executing [555123456@from-trunk:18] Set("SIP/Adip1-00000025", "CALLERID(num-pres)=allowed_not_screened") in new stack
    -- Executing [555123456@from-trunk:19] NoOp("SIP/Adip1-00000025", "CallerID Entry Point") in new stack
    -- Executing [555123456@from-trunk:20] Goto("SIP/Adip1-00000025", "ext-group,600,1") in new stack
    -- Goto (ext-group,600,1)
    -- Executing [600@ext-group:1] GotoIf("SIP/Adip1-00000025", "0?cid") in new stack
    -- Executing [600@ext-group:2] PlayTones("SIP/Adip1-00000025", "ring") in new stack
    -- Executing [600@ext-group:3] Progress("SIP/Adip1-00000025", "") in new stack
    -- Executing [600@ext-group:4] Macro("SIP/Adip1-00000025", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/Adip1-00000025", "TOUCH_MONITOR=1655455398.37") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/Adip1-00000025", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:3] Set("SIP/Adip1-00000025", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:4] Set("SIP/Adip1-00000025", "CHANEXTENCONTEXT=Adip1-00000025") in new stack
    -- Executing [s@macro-user-callerid:5] Set("SIP/Adip1-00000025", "CHANEXTEN=Adip1-00000025") in new stack
    -- Executing [s@macro-user-callerid:6] Set("SIP/Adip1-00000025", "CALLERID(number)=555124680") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/Adip1-00000025", "AMPUSER=555124680") in new stack
    -- Executing [s@macro-user-callerid:8] Set("SIP/Adip1-00000025", "HOTDESCKCHAN=Adip1-00000025") in new stack
    -- Executing [s@macro-user-callerid:9] Set("SIP/Adip1-00000025", "HOTDESKEXTEN=Adip1") in new stack
    -- Executing [s@macro-user-callerid:10] Set("SIP/Adip1-00000025", "HOTDESKCALL=0") in new stack
    -- Executing [s@macro-user-callerid:11] ExecIf("SIP/Adip1-00000025", "0?Set(HOTDESKCALL=1)") in new stack
    -- Executing [s@macro-user-callerid:12] ExecIf("SIP/Adip1-00000025", "0?Set(CALLERID(name)=)") in new stack
    -- Executing [s@macro-user-callerid:13] GotoIf("SIP/Adip1-00000025", "0?report") in new stack
    -- Executing [s@macro-user-callerid:14] ExecIf("SIP/Adip1-00000025", "1?Set(REALCALLERIDNUM=555124680)") in new stack
    -- Executing [s@macro-user-callerid:15] Set("SIP/Adip1-00000025", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/Adip1-00000025", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:17] Set("SIP/Adip1-00000025", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:18] ExecIf("SIP/Adip1-00000025", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
    -- Executing [s@macro-user-callerid:19] GotoIf("SIP/Adip1-00000025", "1?report") in new stack
    -- Goto (macro-user-callerid,s,27)
    -- Executing [s@macro-user-callerid:27] NoOp("SIP/Adip1-00000025", "Macro Depth is 1") in new stack
    -- Executing [s@macro-user-callerid:28] GotoIf("SIP/Adip1-00000025", "1?report2:macroerror") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] GotoIf("SIP/Adip1-00000025", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:30] Set("SIP/Adip1-00000025", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:31] GotoIf("SIP/Adip1-00000025", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,47)
    -- Executing [s@macro-user-callerid:47] Set("SIP/Adip1-00000025", "CALLERID(number)=555124680") in new stack
    -- Executing [s@macro-user-callerid:48] Set("SIP/Adip1-00000025", "CALLERID(name)=555124680") in new stack
    -- Executing [s@macro-user-callerid:49] GotoIf("SIP/Adip1-00000025", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:50] Set("SIP/Adip1-00000025", "CDR(cnam)=555124680") in new stack
    -- Executing [s@macro-user-callerid:51] Set("SIP/Adip1-00000025", "CDR(cnum)=555124680") in new stack
    -- Executing [s@macro-user-callerid:52] Set("SIP/Adip1-00000025", "CHANNEL(language)=en_GB") in new stack
    -- Executing [600@ext-group:5] Macro("SIP/Adip1-00000025", "blkvm-setifempty,") in new stack
    -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/Adip1-00000025", "1?init") in new stack
    -- Goto (macro-blkvm-setifempty,s,4)
    -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/Adip1-00000025", "__BLKVM_CHANNEL=SIP/Adip1-00000025") in new stack
    -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/Adip1-00000025", "SHARED(BLKVM,SIP/Adip1-00000025)=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/Adip1-00000025", "GOSUB_RETVAL=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/Adip1-00000025", "") in new stack
    -- Executing [600@ext-group:6] GotoIf("SIP/Adip1-00000025", "1?skipov") in new stack
    -- Goto (ext-group,600,9)
    -- Executing [600@ext-group:9] Set("SIP/Adip1-00000025", "RRNODEST=") in new stack
    -- Executing [600@ext-group:10] Set("SIP/Adip1-00000025", "__NODEST=600") in new stack
    -- Executing [600@ext-group:11] GosubIf("SIP/Adip1-00000025", "0?sub-rgsetcid,s,1()") in new stack
    -- Executing [600@ext-group:12] Gosub("SIP/Adip1-00000025", "sub-record-check,s,1(rg,600,dontcare)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("SIP/Adip1-00000025", "0?initialized") in new stack
    -- Executing [s@sub-record-check:2] Set("SIP/Adip1-00000025", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:3] Set("SIP/Adip1-00000025", "NOW=1655455398") in new stack
    -- Executing [s@sub-record-check:4] Set("SIP/Adip1-00000025", "__DAY=17") in new stack
    -- Executing [s@sub-record-check:5] Set("SIP/Adip1-00000025", "__MONTH=06") in new stack
    -- Executing [s@sub-record-check:6] Set("SIP/Adip1-00000025", "__YEAR=2022") in new stack
    -- Executing [s@sub-record-check:7] Set("SIP/Adip1-00000025", "__TIMESTR=20220617-104318") in new stack
    -- Executing [s@sub-record-check:8] Set("SIP/Adip1-00000025", "__FROMEXTEN=555124680") in new stack
    -- Executing [s@sub-record-check:9] Set("SIP/Adip1-00000025", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:10] NoOp("SIP/Adip1-00000025", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("SIP/Adip1-00000025", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("SIP/Adip1-00000025", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("SIP/Adip1-00000025", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("SIP/Adip1-00000025", "2?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("SIP/Adip1-00000025", "0?sub-record-check,rg,1") in new stack
    -- Executing [s@sub-record-check:18] NoOp("SIP/Adip1-00000025", "Generic rg Recording Check - 555124680 600") in new stack
    -- Executing [s@sub-record-check:19] Gosub("SIP/Adip1-00000025", "recordcheck,1(dontcare,rg,600)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/Adip1-00000025", "Starting recording check against dontcare") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("SIP/Adip1-00000025", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [recordcheck@sub-record-check:3] Return("SIP/Adip1-00000025", "") in new stack
    -- Executing [s@sub-record-check:20] Return("SIP/Adip1-00000025", "") in new stack
    -- Executing [600@ext-group:13] Set("SIP/Adip1-00000025", "RingGroupMethod=firstnotonphone") in new stack
    -- Executing [600@ext-group:14] Set("SIP/Adip1-00000025", "__ALT_CONFIRM_MSG=") in new stack
    -- Executing [600@ext-group:15] GotoIf("SIP/Adip1-00000025", "0?RGVQANNOUNCE:NORGVQANNOUNCE") in new stack
    -- Goto (ext-group,600,18)
    -- Executing [600@ext-group:18] Macro("SIP/Adip1-00000025", "dial,300,HhTtrQ(NO_ANSWER),210-220") in new stack
    -- Executing [s@macro-dial:1] NoOp("SIP/Adip1-00000025", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
    -- Executing [s@macro-dial:2] ExecIf("SIP/Adip1-00000025", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:3] ExecIf("SIP/Adip1-00000025", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:4] ExecIf("SIP/Adip1-00000025", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:5] ExecIf("SIP/Adip1-00000025", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [s@macro-dial:6] AGI("SIP/Adip1-00000025", "agi://127.0.0.1/dialparties.agi") in new stack
 agi://127.0.0.1/dialparties.agi: Starting New Dialparties.agi
 agi://127.0.0.1/dialparties.agi: Caller ID name is '555124680' number is '555124680'
 agi://127.0.0.1/dialparties.agi: CW Ignore is:
 agi://127.0.0.1/dialparties.agi: CF Ignore is:
 agi://127.0.0.1/dialparties.agi: CW IN_USE/BUSY is: 1
 agi://127.0.0.1/dialparties.agi: Ringgroup confirm is  :
 agi://127.0.0.1/dialparties.agi: Methodology of ring is  'firstnotonphone'
    -- agi://127.0.0.1/dialparties.agi: Added extension 210 to extension map
    -- agi://127.0.0.1/dialparties.agi: Added extension 220 to extension map
    -- agi://127.0.0.1/dialparties.agi: Extension 210 cf is disabled
    -- agi://127.0.0.1/dialparties.agi: Extension 220 cf is disabled
    -- agi://127.0.0.1/dialparties.agi: Extension 210 do not disturb is disabled
    -- agi://127.0.0.1/dialparties.agi: Extension 220 do not disturb is disabled
 agi://127.0.0.1/dialparties.agi: Extension 210 has ExtensionState: 0
    -- agi://127.0.0.1/dialparties.agi: Checking CW and CFB status for extension 210
 agi://127.0.0.1/dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
 agi://127.0.0.1/dialparties.agi: Extension 220 has ExtensionState: 0
    -- agi://127.0.0.1/dialparties.agi: Checking CW and CFB status for extension 220
 agi://127.0.0.1/dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
    -- agi://127.0.0.1/dialparties.agi: ONLY available extensions Array
    -- agi://127.0.0.1/dialparties.agi: (
    -- agi://127.0.0.1/dialparties.agi:     [0] => 210
    -- agi://127.0.0.1/dialparties.agi:     [1] => 220
    -- agi://127.0.0.1/dialparties.agi: )
    -- agi://127.0.0.1/dialparties.agi:
    -- agi://127.0.0.1/dialparties.agi: Filtered ARG3: 210-220
 agi://127.0.0.1/dialparties.agi: RVOL_MODE ''
 agi://127.0.0.1/dialparties.agi: RVOL is:
 agi://127.0.0.1/dialparties.agi: RVOLPARENT is:
    -- <SIP/Adip1-00000025>AGI Script agi://127.0.0.1/dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:7] GotoIf("SIP/Adip1-00000025", "1?huntdial") in new stack
    -- Goto (macro-dial,s,32)
    -- Executing [s@macro-dial:32] NoOp("SIP/Adip1-00000025", "Returned from dialparties with 2 hunt members to dial") in new stack
    -- Executing [s@macro-dial:33] Set("SIP/Adip1-00000025", "HuntLoop=0") in new stack
    -- Executing [s@macro-dial:34] ExecIf("SIP/Adip1-00000025", "0?Set(HuntMembers=0)") in new stack
    -- Executing [s@macro-dial:35] GotoIf("SIP/Adip1-00000025", "1?a30") in new stack
    -- Goto (macro-dial,s,38)
    -- Executing [s@macro-dial:38] Set("SIP/Adip1-00000025", "HuntMember=HuntMember0") in new stack
    -- Executing [s@macro-dial:39] GotoIf("SIP/Adip1-00000025", "1?a32:a35") in new stack
    -- Goto (macro-dial,s,40)
    -- Executing [s@macro-dial:40] Set("SIP/Adip1-00000025", "CT_EXTEN=210") in new stack
    -- Executing [s@macro-dial:41] Set("SIP/Adip1-00000025", "__EXTTOCALL=210") in new stack
    -- Executing [s@macro-dial:42] Set("SIP/Adip1-00000025", "__PICKUPMARK=210") in new stack
    -- Executing [s@macro-dial:43] Set("SIP/Adip1-00000025", "DB(CALLTRACE/210)=555124680") in new stack
    -- Executing [s@macro-dial:44] Goto("SIP/Adip1-00000025", "s,huntstart") in new stack
    -- Goto (macro-dial,s,53)
    -- Executing [s@macro-dial:53] NoOp("SIP/Adip1-00000025", "Hunt Dial Start") in new stack
    -- Executing [s@macro-dial:54] ExecIf("SIP/Adip1-00000025", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
    -- Executing [s@macro-dial:55] ExecIf("SIP/Adip1-00000025", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
    -- Executing [s@macro-dial:56] Macro("SIP/Adip1-00000025", "dial-hunt-predial-hook,") in new stack
    -- Executing [s@macro-dial-hunt-predial-hook:1] MacroExit("SIP/Adip1-00000025", "") in new stack
    -- Executing [s@macro-dial:57] ExecIf("SIP/Adip1-00000025", "0?Set(CWRING=r(callwaiting)):Set(CWRING=)") in new stack
    -- Executing [s@macro-dial:58] Dial("SIP/Adip1-00000025", "SIP/210,300,HhtrQ(NO_ANSWER)M(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- SIP/210-00000026 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/210-00000026", "Applying SIP Headers to channel SIP/210-00000026") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/210-00000026", "TECH=SIP") in new stack
    -- Executing [s@func-apply-sipheaders:3] Set("SIP/210-00000026", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:4] While("SIP/210-00000026", "0") in new stack
    -- Jumping to priority 10
    -- Executing [s@func-apply-sipheaders:11] Return("SIP/210-00000026", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/210-00000026'
    -- SIP/210-00000026 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- Called SIP/210
    -- SIP/210-00000026 is ringing
  == Spawn extension (macro-dial, s, 58) exited non-zero on 'SIP/Adip1-00000025' in macro 'dial'
  == Spawn extension (ext-group, 600, 18) exited non-zero on 'SIP/Adip1-00000025'
    -- Executing [h@ext-group:1] Macro("SIP/Adip1-00000025", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Adip1-00000025", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Adip1-00000025", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("SIP/Adip1-00000025", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Adip1-00000025' in macro 'hangupcall'
  == Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/Adip1-00000025

From both above logs files, I can observe that the “from-trunk” is always correctly set to the trunk “username”, however the trunk “name” is always kept to “Adip1” in both above scenarios.

With the call completion abort in above first scenario, I see in its log the following line entry:

-- Auto fallthrough, channel 'SIP/Adip1-00000023' status is 'UNKNOWN'

Any other further observations on the above that I may have missed?

How do I come to such a situation of a call setup failure with an “UNKOWN” status when calling the trunk with the user name “555456789” (trunk name “Adip2”)?

lgaetz · June 17, 2022, 11:37am

I can’t fully figure out what I’m looking at here. You appear to have some custom dialplan that is being executed in from-trunk which may be causing the issue. Are you using from-pstn-custom? If so, you really shouldn’t be, those lines are superseding the generated lines in from-trunk.

carriba · June 17, 2022, 12:05pm

These are normal SIP trunk configurations where I just created a file “/etc/asterisk/extensions_custom.conf” with the following contents:

[ext-did-custom]
exten => 555123456,1,NoOp(CALLERID(num)=${CALLERID(num)})
exten => 555123456,n,NoOp(CALLERID(name)=${CALLERID(name)})
exten => 555123456,n,NoOp(EXTEN=${EXTEN})
exten => 555123456,n,NoOp(CHANNEL=${CHANNEL})
exten => 555123456,n,Set(__DIRECTION=INBOUND)
exten => 555123456,n,ExecIf($["${FROM_DID}" = ""]?Set(__FROM_DID=${EXTEN}))
exten => 555123456,n,Set(CDR(did)=${FROM_DID})
exten => 555123456,n,ExecIf($[ "${CALLERID(name)}" = "" ] ?Set(CALLERID(name)=${CALLERID(num)}))
exten => 555123456,n,Set(__MOHCLASS=)
exten => 555123456,n,Set(__REVERSAL_REJECT=FALSE)
exten => 555123456,n,GotoIf($["${REVERSAL_REJECT}"!="TRUE"]?post-reverse-charge)
exten => 555123456,n,GotoIf($["${CHANNEL(reversecharge)}"="1"]?macro-hangupcall)
exten => 555123456,n(post-reverse-charge),Noop()
exten => 555123456,n,Set(__CALLINGNAMEPRES_SV=${CALLERID(name-pres)})
exten => 555123456,n,Set(__CALLINGNUMPRES_SV=${CALLERID(num-pres)})
exten => 555123456,n,Set(CALLERID(name-pres)=allowed_not_screened)
exten => 555123456,n,Set(CALLERID(num-pres)=allowed_not_screened)
exten => 555123456,n(did-cid-hook),Noop(CallerID Entry Point)
exten => 555123456,n(dest-ext),Goto(ext-group,600,1

exten => 555456789,1,NoOp(CALLERID(num)=${CALLERID(num)})
exten => 555456789,n,NoOp(CALLERID(name)=${CALLERID(name)})
exten => 555456789,n,NoOp(EXTEN=${EXTEN})
exten => 555456789,n,NoOp(CHANNEL=${CHANNEL})
exten => 555456789,n,Set(__DIRECTION=INBOUND)
exten => 555456789,n,ExecIf($["${FROM_DID}" = ""]?Set(__FROM_DID=${EXTEN}))
exten => 555456789,n,Set(CDR(did)=${FROM_DID})
exten => 555456789,n,ExecIf($[ "${CALLERID(name)}" = "" ] ?Set(CALLERID(name)=${CALLERID(num)}))
exten => 555456789,n,Set(__MOHCLASS=)
exten => 555456789,n,Set(__REVERSAL_REJECT=FALSE)
exten => 555456789,n,GotoIf($["${REVERSAL_REJECT}"!="TRUE"]?post-reverse-charge)
exten => 555456789,n,GotoIf($["${CHANNEL(reversecharge)}"="1"]?macro-hangupcall)
exten => 555456789,n(post-reverse-charge),Noop()
exten => 555456789,n,Set(__CALLINGNAMEPRES_SV=${CALLERID(name-pres)})
exten => 555456789,n,Set(__CALLINGNUMPRES_SV=${CALLERID(num-pres)})
exten => 555456789,n,Set(CALLERID(name-pres)=allowed_not_screened)
exten => 555456789,n,Set(CALLERID(num-pres)=allowed_not_screened)
exten => 555456789,n(did-cid-hook),Noop(CallerID Entry Point)
exten => 555456789,n(dest-ext),Goto(ext-group,600,1

Above file is being called by the respective sections of the “/etc/asterisk/extensions_additional.conf” file to allow me better debug the scenario with NoOp statements, and discern on what is going on here.

Hope this is now a little bit more clearer now

Stewart1 · June 17, 2022, 1:58pm

When you have two or more registrations to the same server of the same provider, the (mostly obsolete) chan_sip driver is incapable of determining on which trunk an incoming call arrived, because it just uses the source IP address and port to match the peer. This normally results in always matching the first trunk in the config.

In the vast majority of cases, this doesn’t matter, because calls can be distinguished and processed based on destination number. There are rare situations when it does matter, e.g. the trunks need to use different codecs or be billed to different departments.

The pjsip driver solves this problem (in most cases) by passing a ‘line’ parameter in the registration.

Though I don’t understand why, it appears that on the call to 555456789, the Adip2 channel somehow did get initialized, so a reference to Adip1 resulted in an error.

IMO, it’s likely that using pjsip trunks would avoid the problem, and there are many other good reasons why you should switch. If that’s not feasible, posting a log with all custom dialplan removed and with higher verbosity may give a clue as to what is wrong. A SIP trace (sip set debug on) may also be useful.

lgaetz · June 17, 2022, 2:22pm

With the custom dialplan set up the way you have, you’re just bypassing all the inbound route config in the GUI. If you want to run debug dialplan on an inbound call, a better way would be to do something like this

[from-trunk-debug]
exten => _.,1,Noop(CALLERID(num)=${CALLERID(num)})
exten => _.,n,NoOp(CALLERID(name)=${CALLERID(name)})
exten => _.,n,NoOp(EXTEN=${EXTEN})
exten => _.,n,NoOp(CHANNEL=${CHANNEL})
; additional lines as required, I suspect everything you need will be displayed using this one line ...
exten => _.,n,DumpChan()
exten => _.,n,GoTo(from-trunk,${EXTEN},1)

Then set your trunk context to from-trunk-debug and do the remainder of the config entirely in the GUI.

carriba · June 17, 2022, 3:49pm

Here a more detailled SIP debug when I make a SIP call with the caller ID “555124680 ” towards the trunk identified with the user name “555456789 ” (trunk name “Adip2 ”):

<--- SIP read from UDP:191.162.216.126:5060 --->
INVITE sip:[email protected]:25236 SIP/2.0
Record-Route: <sip:191.162.216.126;lr=on;ftag=as47a49ab7>
Via: SIP/2.0/UDP 191.162.216.126;branch=z9hG4bK8915.34449127.0
Via: SIP/2.0/UDP 191.162.216.126:5065;received=191.162.216.126;branch=z9hG4bK44690092;rport=5065
Max-Forwards: 69
From: "555124680" <sip:[email protected]:5065>;tag=as47a49ab7
To: <sip:[email protected]:5060>
Contact: <sip:[email protected]:5065>
Call-ID: [email protected]
CSeq: 102 INVITE
Date: Fri, 17 Jun 2022 14:43:17 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 387
v=0
o=- 17456061 17456061 IN IP4 191.162.216.126
s=-
c=IN IP4 191.162.216.126
t=0 0
m=audio 20366 RTP/AVP 8 18 111 0 4 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:111 G726-32/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
<------------->
--- (16 headers 18 lines) ---
Sending to 191.162.216.126:5060 (NAT)
Sending to 191.162.216.126:5060 (NAT)
Using INVITE request as basis request - [email protected]
Found peer 'Adip1' for '555124680' from 191.162.216.126:5060
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
Got SDP version 17456061 and unique parts [- 17456061 IN IP4 191.162.216.126]
Found RTP audio format 8
Found RTP audio format 18
Found RTP audio format 111
Found RTP audio format 0
Found RTP audio format 4
Found RTP audio format 101
Found audio description format PCMA for ID 8
Found audio description format G729 for ID 18
Found audio description format G726-32 for ID 111
Found audio description format PCMU for ID 0
Found audio description format G723 for ID 4
Found audio description format telephone-event for ID 101
Capabilities: us - (alaw|ulaw|g726), peer - audio=(ulaw|g723|alaw|g729|g726)/video=(nothing)/text=(nothing), combined - (alaw|ulaw|g726)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 191.162.216.126:20366
Looking for 555456789 in from-trunk-sip-Adip1 (domain 192.102.89.5)
sip_route_dump: route/path hop: <sip:191.162.216.126;lr=on;ftag=as47a49ab7>
<--- Transmitting (NAT) to 191.162.216.126:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 191.162.216.126;branch=z9hG4bK8915.34449127.0;received=191.162.216.126;rport=5060
Via: SIP/2.0/UDP 191.162.216.126:5065;received=191.162.216.126;branch=z9hG4bK44690092;rport=5065
Record-Route: <sip:191.162.216.126;lr=on;ftag=as47a49ab7>
From: "555124680" <sip:[email protected]:5065>;tag=as47a49ab7
To: <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 102 INVITE
Server: Unknown
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Length: 0
<------------>
    -- Executing [555456789@from-trunk-sip-Adip1:1] Set("SIP/Adip1-00000027", "GROUP()=OUT_4") in new stack
    -- Executing [555456789@from-trunk-sip-Adip1:2] Goto("SIP/Adip1-00000027", "from-trunk,555456789,1") in new stack
    -- Goto (from-trunk,555456789,1)
    -- Executing [555456789@from-trunk:1] NoOp("SIP/Adip1-00000027", "CALLERID(num)=555124680") in new stack
    -- Executing [555456789@from-trunk:2] NoOp("SIP/Adip1-00000027", "CALLERID(name)=555124680") in new stack
    -- Executing [555456789@from-trunk:3] NoOp("SIP/Adip1-00000027", "EXTEN=555456789") in new stack
    -- Executing [555456789@from-trunk:4] NoOp("SIP/Adip1-00000027", "CHANNEL=SIP/Adip1-00000027") in new stack
    -- Executing [555456789@from-trunk:5] Set("SIP/Adip1-00000027", "CALLERID(num)=555124680") in new stack
    -- Auto fallthrough, channel 'SIP/Adip1-00000027' status is 'UNKNOWN'
    -- Executing [h@from-trunk:1] Macro("SIP/Adip1-00000027", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Adip1-00000027", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Adip1-00000027", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("SIP/Adip1-00000027", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Adip1-00000027' in macro 'hangupcall'
  == Spawn extension (from-trunk, h, 1) exited non-zero on 'SIP/Adip1-00000027'
Scheduling destruction of SIP dialog '[email protected]' in 32000 ms (Method: INVITE)
<--- Reliably Transmitting (NAT) to 191.162.216.126:5060 --->
SIP/2.0 603 Declined
Via: SIP/2.0/UDP 191.162.216.126;branch=z9hG4bK8915.34449127.0;received=191.162.216.126;rport=5060
Via: SIP/2.0/UDP 191.162.216.126:5065;received=191.162.216.126;branch=z9hG4bK44690092;rport=5065
From: "555124680" <sip:[email protected]:5065>;tag=as47a49ab7
To: <sip:[email protected]:5060>;tag=as4722ec34
Call-ID: [email protected]
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
<------------>
<--- SIP read from UDP:191.162.216.126:5060 --->
ACK sip:[email protected]:25236 SIP/2.0
Via: SIP/2.0/UDP 191.162.216.126;branch=z9hG4bK8915.34449127.0
From: "555124680" <sip:[email protected]:5065>;tag=as47a49ab7
Call-ID: [email protected]
To: <sip:[email protected]:5060>;tag=as4722ec34
CSeq: 102 ACK
Max-Forwards: 70
Content-Length: 0

The only observation I can make right now based on the debug log is that according to

Looking for 555456789 in from-trunk-sip-Adip1 (domain 192.102.89.5)

the incoming call is looking into the “from-trunk-sip-Adip1”, but not in the “from-trunk-sip-Adip2” context.

lgaetz · June 17, 2022, 4:00pm

Inbound calls to chan_sip trunks are identified by source IP only. Since you have two trunks with the same IP, Asterisk identifies calls to both trunks as matching the first on the list. You must process calls based on DID, and forget about what trunk they use.

system · July 17, 2022, 4:00pm

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