Blacklist - Not Working

MC1 · March 20, 2017, 11:06pm

Hello
I’ve tried setting up a blacklist number for:
John Doe
1-234-567-8910

In my Blacklist module I’ve added phone number 1-234-567-8910. Now the call comes in as Unknown Unknown (before it was coming in as John Doe 1-234-567-8910). So the name and number are being stripped off at the PBX.

Next I enable “Block Unknown/Blocked CallerID” and terminate the calls with a hang up. Now the call will ring 4 times before being passed onto the ring group. In other words the call isn’t being blocked. What setting am I missing?

Any help is greatly appreciated.

Thanks

dicko · March 21, 2017, 12:10am

It is unlikely that adding 1-234-567-8910 will work (it would be accepted but never matched) try adding 12345678910

MC1 · March 21, 2017, 12:32am

Hello
Thanks for the response. I’ve tried 12345678910 with the same outcome.

dicko · March 21, 2017, 12:39am

Then the built-in blacklist will without doubt block 12345678910 if it doesn’t then just post a log of a call that failed to do that.

(rasterisk -x ‘database show blacklist’ will verify your blacklist)

MC1 · March 21, 2017, 1:28pm

Hello
Here’s the blacklist. My test number 19055931770 is the number that isn’t being blocked.

/blacklist/14168524568 : Ficticious number - don’t call back
/blacklist/19055931770 : Test - ECL
/blacklist/blocked : 1
/blacklist/dest : app-blackhole,hangup,1

It appears that the number is programmed in the blacklist yet isn’t being blocked. What are my next steps?

Thanks

Marbled · March 21, 2017, 1:45pm

Hi!

As @dicko said, post some logs…

Have a nice day,

Nick

MC1 · March 21, 2017, 2:05pm

I’ve attached a log and a screen shot of my programming. 19055931770 doesn’t appear to be Blacklisted at all.

Here’s the log file from a recent call

 -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("DAHDI/1-1", "CALLERID(number)=") in new stack
    -- Executing [s@macro-user-callerid:30] Set("DAHDI/1-1", "CALLERID(name)=") in new stack
    -- Executing [s@macro-user-callerid:31] GotoIf("DAHDI/1-1", "1?cnum") in new stack
    -- Goto (macro-user-callerid,s,33)
    -- Executing [s@macro-user-callerid:33] Set("DAHDI/1-1", "CDR(cnum)=") in new stack
[2017-03-21 09:57:03] WARNING[2637]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value)
    -- Executing [s@macro-user-callerid:34] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
    -- Executing [600@ext-group:5] Macro("DAHDI/1-1", "blkvm-setifempty,") in new stack
    -- Executing [s@macro-blkvm-setifempty:1] GotoIf("DAHDI/1-1", "1?init") in new stack
    -- Goto (macro-blkvm-setifempty,s,4)
    -- Executing [s@macro-blkvm-setifempty:4] Set("DAHDI/1-1", "__BLKVM_CHANNEL=DAHDI/1-1") in new stack
    -- Executing [s@macro-blkvm-setifempty:5] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/1-1)=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:6] Set("DAHDI/1-1", "GOSUB_RETVAL=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:7] MacroExit("DAHDI/1-1", "") in new stack
    -- Executing [600@ext-group:6] GotoIf("DAHDI/1-1", "1?skipov") in new stack
    -- Goto (ext-group,600,9)
    -- Executing [600@ext-group:9] Set("DAHDI/1-1", "RRNODEST=") in new stack
    -- Executing [600@ext-group:10] Set("DAHDI/1-1", "__NODEST=600") in new stack
    -- Executing [600@ext-group:11] GosubIf("DAHDI/1-1", "0?sub-rgsetcid,s,1()") in new stack
    -- Executing [600@ext-group:12] Gosub("DAHDI/1-1", "sub-record-check,s,1(rg,600,never)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("DAHDI/1-1", "7?initialized") in new stack
    -- Goto (sub-record-check,s,10)
    -- Executing [s@sub-record-check:10] NoOp("DAHDI/1-1", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("DAHDI/1-1", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("DAHDI/1-1", "REC_POLICY_MODE_SAVE=NO") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("DAHDI/1-1", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("DAHDI/1-1", "2?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("DAHDI/1-1", "0?sub-record-check,rg,1") in new stack
    -- Executing [s@sub-record-check:18] NoOp("DAHDI/1-1", "Generic rg Recording Check - unknown 600") in new stack
    -- Executing [s@sub-record-check:19] Gosub("DAHDI/1-1", "recordcheck,1(never,rg,600)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("DAHDI/1-1", "Starting recording check against never") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("DAHDI/1-1", "never") in new stack
    -- Goto (sub-record-check,recordcheck,14)
    -- Executing [recordcheck@sub-record-check:14] Set("DAHDI/1-1", "__REC_POLICY_MODE=NEVER") in new stack
    -- Executing [recordcheck@sub-record-check:15] Goto("DAHDI/1-1", "stoprec") in new stack
    -- Goto (sub-record-check,recordcheck,25)
    -- Executing [recordcheck@sub-record-check:25] NoOp("DAHDI/1-1", "Stopping recording: rg, 600") in new stack
    -- Executing [recordcheck@sub-record-check:26] Set("DAHDI/1-1", "__REC_STATUS=STOPPED") in new stack
    -- Executing [recordcheck@sub-record-check:27] System("DAHDI/1-1", "/var/lib/asterisk/bin/stoprecording.php "DAHDI/1-1"") in new stack
    -- Executing [recordcheck@sub-record-check:28] Return("DAHDI/1-1", "") in new stack
    -- Executing [s@sub-record-check:20] Return("DAHDI/1-1", "") in new stack
    -- Executing [600@ext-group:13] Set("DAHDI/1-1", "RingGroupMethod=ringall") in new stack
    -- Executing [600@ext-group:14] Macro("DAHDI/1-1", "dial,45,Ttr,202-206-207-303") in new stack
    -- Executing [s@macro-dial:1] NoOp("DAHDI/1-1", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
    -- Executing [s@macro-dial:2] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:3] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:4] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:5] ExecIf("DAHDI/1-1", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [s@macro-dial:6] AGI("DAHDI/1-1", "dialparties.agi") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
 dialparties.agi: Starting New Dialparties.agi
 dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
 dialparties.agi: CW Ignore is:
 dialparties.agi: CF Ignore is:
 dialparties.agi: CW IN_USE/BUSY is: 1
       > dialparties.agi: USE_CONFIRMATION:  'FALSE'
       > dialparties.agi: RINGGROUP_INDEX:   ''
 dialparties.agi: Methodology of ring is  'ringall'
    -- dialparties.agi: Added extension 202 to extension map
    -- dialparties.agi: Added extension 206 to extension map
    -- dialparties.agi: Added extension 207 to extension map
    -- dialparties.agi: Added extension 303 to extension map
    -- dialparties.agi: Extension 202 cf is disabled
    -- dialparties.agi: Extension 206 cf is disabled
    -- dialparties.agi: Extension 207 cf is disabled
    -- dialparties.agi: Extension 303 cf is disabled
    -- dialparties.agi: Extension 202 do not disturb is disabled
    -- dialparties.agi: Extension 206 do not disturb is disabled
    -- dialparties.agi: Extension 207 do not disturb is disabled
    -- dialparties.agi: Extension 303 do not disturb is disabled
       > dialparties.agi: extnum 202 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: DbDel CALLTRACE/202 - Caller ID is not defined
       > dialparties.agi: extnum 206 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
 dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
 dialparties.agi: Extension 206 has ExtensionState: 0
    -- dialparties.agi: Checking CW and CFB status for extension 206
    -- dialparties.agi: DbDel CALLTRACE/206 - Caller ID is not defined
       > dialparties.agi: extnum 207 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: DbDel CALLTRACE/207 - Caller ID is not defined
       > dialparties.agi: extnum 303 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: DbDel CALLTRACE/303 - Caller ID is not defined
    -- dialparties.agi: Filtered ARG3: 202-206-207-303
       > dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: TtrM(auto-blkvm)
       > dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: TtrM(auto-blkvm)
    -- <DAHDI/1-1>AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:9] NoOp("DAHDI/1-1", "Returned from dialparties with groups to dial") in new stack
    -- Executing [s@macro-dial:10] Set("DAHDI/1-1", "LOOPCNT=4") in new stack
    -- Executing [s@macro-dial:11] Set("DAHDI/1-1", "ITER=1") in new stack
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=202") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 202") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=2") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=206") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 206") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=3") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=207") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 207") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=4") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=303") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 303") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=5") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "0?ndloopbegin") in new stack
    -- Executing [s@macro-dial:18] Macro("DAHDI/1-1", "dial-ringall-predial-hook,") in new stack
    -- Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("DAHDI/1-1", "") in new stack
    -- Executing [s@macro-dial:19] Dial("DAHDI/1-1", "SIP/202&SIP/206&DAHDI/3&SIP/99303&SIP/303,45,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[2017-03-21 09:57:05] WARNING[24851][C-00006430]: app_dial.c:2525 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- SIP/202-00000286 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/202-00000286", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/202-00000286", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/202-00000286", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/202-00000286", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/202-00000286'
    -- SIP/202-00000286 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- SIP/206-00000287 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/206-00000287", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/206-00000287", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/206-00000287", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/206-00000287", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/206-00000287'
    -- SIP/206-00000287 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("DAHDI/3-1", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("DAHDI/3-1", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("DAHDI/3-1", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("DAHDI/3-1", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'DAHDI/3-1'
    -- DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- SIP/303-00000288 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/303-00000288", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/303-00000288", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/303-00000288", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/303-00000288", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/303-00000288'
    -- SIP/303-00000288 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- Called SIP/202
    -- Called SIP/206
    -- Called DAHDI/3
    -- Called SIP/303
    -- SIP/303-00000288 connected line has changed. Saving it until answer for DAHDI/1-1
    -- DAHDI/3-1 is ringing
    -- SIP/206-00000287 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/202-00000286 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/206-00000287 is ringing
    -- SIP/202-00000286 is ringing
    -- SIP/303-00000288 is ringing
[2017-03-21 09:57:06] WARNING[2763]: chan_sip.c:4120 retrans_pkt: Timeout on b682ec338b5340d73ecdcdf15ef26c60 on non-critical invite transaction.
    -- DAHDI/3-1 is ringing
[2017-03-21 09:57:11] WARNING[2763]: chan_sip.c:4120 retrans_pkt: Timeout on bb5cbd459b3595d004a80c03f9ef9e17 on non-critical invite transaction.
    -- DAHDI/3-1 is ringing
    -- SIP/202-00000286 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/202-00000286 answered DAHDI/1-1
    -- Hanging up on 'DAHDI/3-1'
    -- Hungup 'DAHDI/3-1'
    -- Executing [s@macro-auto-blkvm:1] Set("SIP/202-00000286", "__MACRO_RESULT=") in new stack
    -- Executing [s@macro-auto-blkvm:2] Set("SIP/202-00000286", "CFIGNORE=") in new stack
    -- Executing [s@macro-auto-blkvm:3] Set("SIP/202-00000286", "MASTER_CHANNEL(CFIGNORE)=") in new stack
    -- Executing [s@macro-auto-blkvm:4] Set("SIP/202-00000286", "FORWARD_CONTEXT=from-internal") in new stack
    -- Executing [s@macro-auto-blkvm:5] Set("SIP/202-00000286", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
    -- Executing [s@macro-auto-blkvm:6] Macro("SIP/202-00000286", "blkvm-clr,") in new stack
    -- Executing [s@macro-blkvm-clr:1] Set("SIP/202-00000286", "SHARED(BLKVM,DAHDI/1-1)=") in new stack
    -- Executing [s@macro-blkvm-clr:2] Set("SIP/202-00000286", "GOSUB_RETVAL=") in new stack
    -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/202-00000286", "") in new stack
    -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/202-00000286", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=202)") in new stack
    -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/202-00000286", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Office)") in new stack
    -- Channel SIP/202-00000286 joined 'simple_bridge' basic-bridge <1751c3e7-5e63-4b86-a84c-c06ed4b84020>
    -- Channel DAHDI/1-1 joined 'simple_bridge' basic-bridge <1751c3e7-5e63-4b86-a84c-c06ed4b84020>
       > 0x7f9a68d42570 -- Probation passed - setting RTP source address to 192.168.2.71:12100
    -- Channel SIP/202-00000286 left 'simple_bridge' basic-bridge <1751c3e7-5e63-4b86-a84c-c06ed4b84020>
    -- Channel DAHDI/1-1 left 'simple_bridge' basic-bridge <1751c3e7-5e63-4b86-a84c-c06ed4b84020>
  == Spawn extension (macro-dial, s, 19) exited non-zero on 'DAHDI/1-1' in macro 'dial'
  == Spawn extension (ext-group, 600, 14) exited non-zero on 'DAHDI/1-1'
    -- Executing [h@ext-group:1] Macro("DAHDI/1-1", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("DAHDI/1-1", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("DAHDI/1-1", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("DAHDI/1-1", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'DAHDI/1-1' in macro 'hangupcall'
  == Spawn extension (ext-group, h, 1) exited non-zero on 'DAHDI/1-1'
    -- Hanging up on 'DAHDI/1-1'
    -- Hungup 'DAHDI/1-1'

Thanks

dicko · March 21, 2017, 2:40pm

You will need to get CID working on your POTS line first.

-- Executing [s@macro-user-callerid:29] Set("DAHDI/1-1", "CALLERID(number)=") in new stack
-- Executing [s@macro-user-callerid:30] Set("DAHDI/1-1", "CALLERID(name)=") in new stack
-- Executing [s@macro-user-callerid:31] GotoIf("DAHDI/1-1", "1?cnum") in new stack
-- Goto (macro-user-callerid,s,33)````

MC1 · March 21, 2017, 4:13pm

CID is working on the POTs line. When the number is Blacklisted that’s when CID stops working. I’ve removed the number from the Blacklist module and redialed it. You’ll see in the log file that the name and number are now showing up. So some how the name and number are being dropped by the PBX when a number is blacklisted. This causes the the Black list to not function. Am I correct?

Log file: Call made to 19055931770

new stack
    -- Executing [s@macro-user-callerid:16] ExecIf("DAHDI/1-1", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [s@macro-user-callerid:17] Set("DAHDI/1-1", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:18] GotoIf("DAHDI/1-1", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("DAHDI/1-1", "CALLERID(number)=19055931770") in new stack
    -- Executing [s@macro-user-callerid:30] Set("DAHDI/1-1", "CALLERID(name)=Michael Coulton") in new stack
    -- Executing [s@macro-user-callerid:31] GotoIf("DAHDI/1-1", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:32] Set("DAHDI/1-1", "CDR(cnam)=Michael Coulton") in new stack
    -- Executing [s@macro-user-callerid:33] Set("DAHDI/1-1", "CDR(cnum)=19055931770") in new stack
    -- Executing [s@macro-user-callerid:34] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
    -- Executing [600@ext-group:5] Macro("DAHDI/1-1", "blkvm-setifempty,") in new stack
    -- Executing [s@macro-blkvm-setifempty:1] GotoIf("DAHDI/1-1", "1?init") in new stack
    -- Goto (macro-blkvm-setifempty,s,4)
    -- Executing [s@macro-blkvm-setifempty:4] Set("DAHDI/1-1", "__BLKVM_CHANNEL=DAHDI/1-1") in new stack
    -- Executing [s@macro-blkvm-setifempty:5] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/1-1)=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:6] Set("DAHDI/1-1", "GOSUB_RETVAL=TRUE") in new stack
    -- Executing [s@macro-blkvm-setifempty:7] MacroExit("DAHDI/1-1", "") in new stack
    -- Executing [600@ext-group:6] GotoIf("DAHDI/1-1", "1?skipov") in new stack
    -- Goto (ext-group,600,9)
    -- Executing [600@ext-group:9] Set("DAHDI/1-1", "RRNODEST=") in new stack
    -- Executing [600@ext-group:10] Set("DAHDI/1-1", "__NODEST=600") in new stack
    -- Executing [600@ext-group:11] GosubIf("DAHDI/1-1", "0?sub-rgsetcid,s,1()") in new stack
    -- Executing [600@ext-group:12] Gosub("DAHDI/1-1", "sub-record-check,s,1(rg,600,never)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("DAHDI/1-1", "11?initialized") in new stack
    -- Goto (sub-record-check,s,10)
    -- Executing [s@sub-record-check:10] NoOp("DAHDI/1-1", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("DAHDI/1-1", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("DAHDI/1-1", "REC_POLICY_MODE_SAVE=NO") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("DAHDI/1-1", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("DAHDI/1-1", "2?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("DAHDI/1-1", "0?sub-record-check,rg,1") in new stack
    -- Executing [s@sub-record-check:18] NoOp("DAHDI/1-1", "Generic rg Recording Check - 19055931770 600") in new stack
    -- Executing [s@sub-record-check:19] Gosub("DAHDI/1-1", "recordcheck,1(never,rg,600)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("DAHDI/1-1", "Starting recording check against never") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("DAHDI/1-1", "never") in new stack
    -- Goto (sub-record-check,recordcheck,14)
    -- Executing [recordcheck@sub-record-check:14] Set("DAHDI/1-1", "__REC_POLICY_MODE=NEVER") in new stack
    -- Executing [recordcheck@sub-record-check:15] Goto("DAHDI/1-1", "stoprec") in new stack
    -- Goto (sub-record-check,recordcheck,25)
    -- Executing [recordcheck@sub-record-check:25] NoOp("DAHDI/1-1", "Stopping recording: rg, 600") in new stack
    -- Executing [recordcheck@sub-record-check:26] Set("DAHDI/1-1", "__REC_STATUS=STOPPED") in new stack
    -- Executing [recordcheck@sub-record-check:27] System("DAHDI/1-1", "/var/lib/asterisk/bin/stoprecording.php "DAHDI/1-1"") in new stack
    -- Executing [recordcheck@sub-record-check:28] Return("DAHDI/1-1", "") in new stack
    -- Executing [s@sub-record-check:20] Return("DAHDI/1-1", "") in new stack
    -- Executing [600@ext-group:13] Set("DAHDI/1-1", "RingGroupMethod=ringall") in new stack
    -- Executing [600@ext-group:14] Macro("DAHDI/1-1", "dial,45,Ttr,202-206-207-303") in new stack
    -- Executing [s@macro-dial:1] NoOp("DAHDI/1-1", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
    -- Executing [s@macro-dial:2] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:3] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:4] ExecIf("DAHDI/1-1", "0?Set(ALERT_INFO=)") in new stack
    -- Executing [s@macro-dial:5] ExecIf("DAHDI/1-1", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [s@macro-dial:6] AGI("DAHDI/1-1", "dialparties.agi") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
 dialparties.agi: Starting New Dialparties.agi
 dialparties.agi: Caller ID name is 'Michael Coulton' number is '19055931770'
 dialparties.agi: CW Ignore is:
 dialparties.agi: CF Ignore is:
 dialparties.agi: CW IN_USE/BUSY is: 1
       > dialparties.agi: USE_CONFIRMATION:  'FALSE'
       > dialparties.agi: RINGGROUP_INDEX:   ''
 dialparties.agi: Methodology of ring is  'ringall'
    -- dialparties.agi: Added extension 202 to extension map
    -- dialparties.agi: Added extension 206 to extension map
    -- dialparties.agi: Added extension 207 to extension map
    -- dialparties.agi: Added extension 303 to extension map
    -- dialparties.agi: Extension 202 cf is disabled
    -- dialparties.agi: Extension 206 cf is disabled
    -- dialparties.agi: Extension 207 cf is disabled
    -- dialparties.agi: Extension 303 cf is disabled
    -- dialparties.agi: Extension 202 do not disturb is disabled
    -- dialparties.agi: Extension 206 do not disturb is disabled
    -- dialparties.agi: Extension 207 do not disturb is disabled
    -- dialparties.agi: Extension 303 do not disturb is disabled
       > dialparties.agi: extnum 202 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: dbset CALLTRACE/202 to 19055931770
       > dialparties.agi: extnum 206 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
 dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
 dialparties.agi: Extension 206 has ExtensionState: 0
    -- dialparties.agi: Checking CW and CFB status for extension 206
    -- dialparties.agi: dbset CALLTRACE/206 to 19055931770
       > dialparties.agi: extnum 207 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: dbset CALLTRACE/207 to 19055931770
       > dialparties.agi: extnum 303 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
    -- dialparties.agi: dbset CALLTRACE/303 to 19055931770
    -- dialparties.agi: Filtered ARG3: 202-206-207-303
       > dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: TtrM(auto-blkvm)
       > dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: TtrM(auto-blkvm)
    -- <DAHDI/1-1>AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:9] NoOp("DAHDI/1-1", "Returned from dialparties with groups to dial") in new stack
    -- Executing [s@macro-dial:10] Set("DAHDI/1-1", "LOOPCNT=4") in new stack
    -- Executing [s@macro-dial:11] Set("DAHDI/1-1", "ITER=1") in new stack
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=202") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 202") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=2") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=206") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 206") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=3") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=207") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 207") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=4") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
    -- Goto (macro-dial,s,12)
    -- Executing [s@macro-dial:12] Set("DAHDI/1-1", "EXTTOCALL=303") in new stack
    -- Executing [s@macro-dial:13] NoOp("DAHDI/1-1", "Working with 303") in new stack
    -- Executing [s@macro-dial:14] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:15] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
    -- Executing [s@macro-dial:16] Set("DAHDI/1-1", "ITER=5") in new stack
    -- Executing [s@macro-dial:17] GotoIf("DAHDI/1-1", "0?ndloopbegin") in new stack
    -- Executing [s@macro-dial:18] Macro("DAHDI/1-1", "dial-ringall-predial-hook,") in new stack
    -- Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("DAHDI/1-1", "") in new stack
    -- Executing [s@macro-dial:19] Dial("DAHDI/1-1", "SIP/202&SIP/206&DAHDI/3&SIP/99303&SIP/303,45,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[2017-03-21 12:05:29] WARNING[15265][C-00006519]: app_dial.c:2525 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- SIP/202-00000297 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/202-00000297", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/202-00000297", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/202-00000297", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/202-00000297", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/202-00000297'
    -- SIP/202-00000297 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- SIP/206-00000298 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/206-00000298", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/206-00000298", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/206-00000298", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/206-00000298", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/206-00000298'
    -- SIP/206-00000298 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("DAHDI/3-1", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("DAHDI/3-1", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("DAHDI/3-1", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("DAHDI/3-1", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'DAHDI/3-1'
    -- DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- SIP/303-00000299 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/303-00000299", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("SIP/303-00000299", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("SIP/303-00000299", "0") in new stack
    -- Jumping to priority 6
    -- Executing [s@func-apply-sipheaders:7] Return("SIP/303-00000299", "") in new stack
  == Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/303-00000299'
    -- SIP/303-00000299 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- Called SIP/202
    -- Called SIP/206
    -- Called DAHDI/3
    -- Called SIP/303
    -- SIP/303-00000299 connected line has changed. Saving it until answer for DAHDI/1-1
    -- DAHDI/3-1 is ringing
    -- SIP/206-00000298 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/202-00000297 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/202-00000297 is ringing
    -- SIP/206-00000298 is ringing
    -- SIP/303-00000299 is ringing
    -- SIP/202-00000297 connected line has changed. Saving it until answer for DAHDI/1-1
    -- SIP/202-00000297 answered DAHDI/1-1
    -- Hanging up on 'DAHDI/3-1'
    -- Hungup 'DAHDI/3-1'
    -- Executing [s@macro-auto-blkvm:1] Set("SIP/202-00000297", "__MACRO_RESULT=") in new stack
    -- Executing [s@macro-auto-blkvm:2] Set("SIP/202-00000297", "CFIGNORE=") in new stack
    -- Executing [s@macro-auto-blkvm:3] Set("SIP/202-00000297", "MASTER_CHANNEL(CFIGNORE)=") in new stack
    -- Executing [s@macro-auto-blkvm:4] Set("SIP/202-00000297", "FORWARD_CONTEXT=from-internal") in new stack
    -- Executing [s@macro-auto-blkvm:5] Set("SIP/202-00000297", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
    -- Executing [s@macro-auto-blkvm:6] Macro("SIP/202-00000297", "blkvm-clr,") in new stack
    -- Executing [s@macro-blkvm-clr:1] Set("SIP/202-00000297", "SHARED(BLKVM,DAHDI/1-1)=") in new stack
    -- Executing [s@macro-blkvm-clr:2] Set("SIP/202-00000297", "GOSUB_RETVAL=") in new stack
    -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/202-00000297", "") in new stack
    -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/202-00000297", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=202)") in new stack
    -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/202-00000297", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Office)") in new stack
    -- Channel SIP/202-00000297 joined 'simple_bridge' basic-bridge <baaf0fd1-d59b-4d56-ba9e-1138616f443b>
    -- Channel DAHDI/1-1 joined 'simple_bridge' basic-bridge <baaf0fd1-d59b-4d56-ba9e-1138616f443b>
       > 0x7f9a68d42570 -- Probation passed - setting RTP source address to 192.168.2.71:12100
    -- Channel SIP/202-00000297 left 'simple_bridge' basic-bridge <baaf0fd1-d59b-4d56-ba9e-1138616f443b>
    -- Channel DAHDI/1-1 left 'simple_bridge' basic-bridge <baaf0fd1-d59b-4d56-ba9e-1138616f443b>
  == Spawn extension (macro-dial, s, 19) exited non-zero on 'DAHDI/1-1' in macro 'dial'
  == Spawn extension (ext-group, 600, 14) exited non-zero on 'DAHDI/1-1'
    -- Executing [h@ext-group:1] Macro("DAHDI/1-1", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("DAHDI/1-1", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("DAHDI/1-1", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("DAHDI/1-1", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'DAHDI/1-1' in macro 'hangupcall'
  == Spawn extension (ext-group, h, 1) exited non-zero on 'DAHDI/1-1'
    -- Hanging up on 'DAHDI/1-1'
    -- Hungup 'DAHDI/1-1'
localhost*CLI> exit
Asterisk cleanly ending (0).
Executing last minute cleanups

dicko · March 21, 2017, 6:12pm

You will have to post the logs from the REAL start of the call to where you started your posted logs to see what is not normal.

MC1 · March 21, 2017, 7:28pm

Hello
These logs are from the CLI and contain all the information associated with the call. What other log files are there pertaining to the call? From the CLI I type asterisk -vvvvvvr, then I place a call. Once the call is complete I copy and paste the call info from the CLI. If there is more information found in the full log file, then I can post it tomorrow. Please advise and thanks for the help.

dicko · March 21, 2017, 8:15pm

Actually you are absolutely wrong, you start with

s@macro-user-callerid:16

this is WAY WAY later than the start of the call it, is even WAY later than the entry into the macro. Please understand that 16 is > 1

your call would almost ALWAYS start close to

from-trunk:1

or in your case

from-dahdi:1

(which should get there pretty damn quick)

Please accept that reality.

from-trunk:2 will ALWAYS be a call to app-blacklist-check

If it is not doing that then you are doing something horribly wrong

MC1 · March 21, 2017, 8:27pm

Hello
Okay. Thanks for the clarification. I’ll look at the log file and post the findings. So the CLI doesn’t display everything associated with the call?

dicko · March 21, 2017, 8:33pm

That would depend if you have changed anything, by default the console verbosity would be 3 and would reveal the call fully, the log file “full”, would be also be at verbosity 3 unless you REALLY messed with things. /var/log/asterisk/full should thusly have EVERYTHING you need including time stamps and a somewhat uniqueid (at least for the last 64K calls since your last reboot )

MC1 · March 22, 2017, 1:08pm

Hello
What is the best way to post a large file? It’s over 7K characters and exceeds the posting limit.

Thanks

dicko · March 22, 2017, 1:18pm

You only need to post rhe first few linrs of the call , app-blacklist is called very early. If a exact CID(number) number is in the list the call log will be extremely short .

MC1 · March 22, 2017, 1:38pm

Hello
Hope this is what you need. Thanks

Call coming from 19055931770, however it has been Blacklisted:

[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] sig_analog.c: Starting simple switch on ‘DAHDI/1-1’
[2017-03-21 09:57:03] ERROR[24851][C-00006430] callerid.c: No start bit found in fsk data.
[2017-03-21 09:57:03] WARNING[24851][C-00006430] chan_dahdi.c: Failed to decode CallerID
[2017-03-21 09:57:03] WARNING[24851][C-00006430] sig_analog.c: CallerID returned with error on channel ‘DAHDI/1-1’
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:1] NoOp(“DAHDI/1-1”, "Entering from-dahdi with DID == ") in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:2] Ringing(“DAHDI/1-1”, “”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:3] Set(“DAHDI/1-1”, “DID=s”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:4] NoOp(“DAHDI/1-1”, “DID is now s”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:5] GotoIf(“DAHDI/1-1”, “1?dahdiok:checkzap”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx_builtins.c: Goto (from-analog,s,9)
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:9] NoOp(“DAHDI/1-1”, “Is a DAHDi Channel”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:10] Set(“DAHDI/1-1”, “CHAN=1-1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:11] Set(“DAHDI/1-1”, “CHAN=1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@from-analog:12] Macro(“DAHDI/1-1”, “from-dahdi-1,s,1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@macro-from-dahdi-1:1] NoOp(“DAHDI/1-1”, “Entering macro-from-dahdi-1 with DID = s and setting to: 7054870926”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@macro-from-dahdi-1:2] Set(“DAHDI/1-1”, “__FROM_DID=7054870926”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@macro-from-dahdi-1:3] Goto(“DAHDI/1-1”, “from-trunk,7054870926,1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx_builtins.c: Goto (from-trunk,7054870926,1)
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] app_macro.c: Channel ‘DAHDI/1-1’ jumping out of macro ‘from-dahdi-1’
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [7054870926@from-trunk:1] Set(“DAHDI/1-1”, “__DIRECTION=INBOUND”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [7054870926@from-trunk:2] Gosub(“DAHDI/1-1”, “sub-record-check,s,1(in,7054870926,no)”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:1] GotoIf(“DAHDI/1-1”, “0?initialized”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:2] Set(“DAHDI/1-1”, “__REC_STATUS=INITIALIZED”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:3] Set(“DAHDI/1-1”, “NOW=1490104623”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:4] Set(“DAHDI/1-1”, “__DAY=21”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:5] Set(“DAHDI/1-1”, “__MONTH=03”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:6] Set(“DAHDI/1-1”, “__YEAR=2017”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:7] Set(“DAHDI/1-1”, “__TIMESTR=20170321-095703”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:8] Set(“DAHDI/1-1”, “__FROMEXTEN=unknown”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:9] Set(“DAHDI/1-1”, “__MON_FMT=wav”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:10] NoOp(“DAHDI/1-1”, “Recordings initialized”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:11] ExecIf(“DAHDI/1-1”, “0?Set(ARG3=dontcare)”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:12] Set(“DAHDI/1-1”, “REC_POLICY_MODE_SAVE=”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:13] ExecIf(“DAHDI/1-1”, “0?Set(REC_STATUS=NO)”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:14] GotoIf(“DAHDI/1-1”, “2?checkaction”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@sub-record-check:17] GotoIf(“DAHDI/1-1”, “1?sub-record-check,in,1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [in@sub-record-check:1] NoOp(“DAHDI/1-1”, “Inbound Recording Check to 7054870926”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [in@sub-record-check:2] Set(“DAHDI/1-1”, “FROMEXTEN=unknown”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [in@sub-record-check:3] ExecIf(“DAHDI/1-1”, “0?Set(FROMEXTEN=)”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [in@sub-record-check:4] Gosub(“DAHDI/1-1”, “recordcheck,1(no,in,7054870926)”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“DAHDI/1-1”, “Starting recording check against no”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“DAHDI/1-1”, “no”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx_builtins.c: Goto (sub-record-check,recordcheck,12)
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [recordcheck@sub-record-check:12] Set(“DAHDI/1-1”, “__REC_POLICY_MODE=NO”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [recordcheck@sub-record-check:13] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [in@sub-record-check:5] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [7054870926@from-trunk:3] Gosub(“DAHDI/1-1”, “app-blacklist-check,s,1()”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“DAHDI/1-1”, “0?blacklisted”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@app-blacklist-check:2] Set(“DAHDI/1-1”, “CALLED_BLACKLIST=1”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [s@app-blacklist-check:3] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 09:57:03] VERBOSE[24851][C-00006430] pbx.c: Executing [7054870926@from-trunk:4] Set(“DAHDI/1-1”, “__FROM_DID=7054870926”) in new stack

Call coming from 19055931770, however it has not been Blacklisted:

[2017-03-21 12:05:26] VERBOSE[15265][C-00006519] sig_analog.c: Starting simple switch on ‘DAHDI/1-1’
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:1] NoOp(“DAHDI/1-1”, "Entering from-dahdi with DID == ") in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:2] Ringing(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:3] Set(“DAHDI/1-1”, “DID=s”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:4] NoOp(“DAHDI/1-1”, “DID is now s”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:5] GotoIf(“DAHDI/1-1”, “1?dahdiok:checkzap”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (from-analog,s,9)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:9] NoOp(“DAHDI/1-1”, “Is a DAHDi Channel”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:10] Set(“DAHDI/1-1”, “CHAN=1-1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:11] Set(“DAHDI/1-1”, “CHAN=1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@from-analog:12] Macro(“DAHDI/1-1”, “from-dahdi-1,s,1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-from-dahdi-1:1] NoOp(“DAHDI/1-1”, “Entering macro-from-dahdi-1 with DID = s and setting to: 7054870926”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-from-dahdi-1:2] Set(“DAHDI/1-1”, “__FROM_DID=7054870926”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-from-dahdi-1:3] Goto(“DAHDI/1-1”, “from-trunk,7054870926,1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (from-trunk,7054870926,1)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] app_macro.c: Channel ‘DAHDI/1-1’ jumping out of macro ‘from-dahdi-1’
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:1] Set(“DAHDI/1-1”, “__DIRECTION=INBOUND”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:2] Gosub(“DAHDI/1-1”, “sub-record-check,s,1(in,7054870926,no)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:1] GotoIf(“DAHDI/1-1”, “0?initialized”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:2] Set(“DAHDI/1-1”, “__REC_STATUS=INITIALIZED”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:3] Set(“DAHDI/1-1”, “NOW=1490112327”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:4] Set(“DAHDI/1-1”, “__DAY=21”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:5] Set(“DAHDI/1-1”, “__MONTH=03”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:6] Set(“DAHDI/1-1”, “__YEAR=2017”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:7] Set(“DAHDI/1-1”, “__TIMESTR=20170321-120527”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:8] Set(“DAHDI/1-1”, “__FROMEXTEN=unknown”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:9] Set(“DAHDI/1-1”, “__MON_FMT=wav”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:10] NoOp(“DAHDI/1-1”, “Recordings initialized”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:11] ExecIf(“DAHDI/1-1”, “0?Set(ARG3=dontcare)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:12] Set(“DAHDI/1-1”, “REC_POLICY_MODE_SAVE=”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:13] ExecIf(“DAHDI/1-1”, “0?Set(REC_STATUS=NO)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:14] GotoIf(“DAHDI/1-1”, “2?checkaction”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@sub-record-check:17] GotoIf(“DAHDI/1-1”, “1?sub-record-check,in,1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [in@sub-record-check:1] NoOp(“DAHDI/1-1”, “Inbound Recording Check to 7054870926”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [in@sub-record-check:2] Set(“DAHDI/1-1”, “FROMEXTEN=unknown”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [in@sub-record-check:3] ExecIf(“DAHDI/1-1”, “11?Set(FROMEXTEN=19055931770)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [in@sub-record-check:4] Gosub(“DAHDI/1-1”, “recordcheck,1(no,in,7054870926)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“DAHDI/1-1”, “Starting recording check against no”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“DAHDI/1-1”, “no”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (sub-record-check,recordcheck,12)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [recordcheck@sub-record-check:12] Set(“DAHDI/1-1”, “__REC_POLICY_MODE=NO”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [recordcheck@sub-record-check:13] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [in@sub-record-check:5] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:3] Gosub(“DAHDI/1-1”, “app-blacklist-check,s,1()”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“DAHDI/1-1”, “0?blacklisted”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@app-blacklist-check:2] Set(“DAHDI/1-1”, “CALLED_BLACKLIST=1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@app-blacklist-check:3] Return(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:4] Set(“DAHDI/1-1”, “__FROM_DID=7054870926”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:5] Set(“DAHDI/1-1”, “CDR(did)=7054870926”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:6] ExecIf(“DAHDI/1-1”, “0 ?Set(CALLERID(name)=19055931770)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:7] Set(“DAHDI/1-1”, “__MOHCLASS=”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:8] Ringing(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:9] Set(“DAHDI/1-1”, “__RINGINGSENT=TRUE”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:10] Set(“DAHDI/1-1”, “__REVERSAL_REJECT=FALSE”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:11] GotoIf(“DAHDI/1-1”, “1?post-reverse-charge”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (from-trunk,7054870926,13)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:13] NoOp(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:14] Set(“DAHDI/1-1”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:15] Set(“DAHDI/1-1”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:16] Set(“DAHDI/1-1”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:17] Set(“DAHDI/1-1”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:18] NoOp(“DAHDI/1-1”, “CallerID Entry Point”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [7054870926@from-trunk:19] Goto(“DAHDI/1-1”, “ext-group,600,1”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx_builtins.c: Goto (ext-group,600,1)
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [600@ext-group:1] GotoIf(“DAHDI/1-1”, “0?cid”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [600@ext-group:2] PlayTones(“DAHDI/1-1”, “ring”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [600@ext-group:3] Progress(“DAHDI/1-1”, “”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [600@ext-group:4] Macro(“DAHDI/1-1”, “user-callerid,”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-user-callerid:1] Set(“DAHDI/1-1”, “TOUCH_MONITOR=1490112326.1418”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-user-callerid:2] Set(“DAHDI/1-1”, “AMPUSER=19055931770”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“DAHDI/1-1”, “0?report”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“DAHDI/1-1”, “1?Set(REALCALLERIDNUM=19055931770)”) in new stack
[2017-03-21 12:05:27] VERBOSE[15265][C-00006519] pbx.c: Executing [s@macro-user-callerid:5] Set(“DAHDI/1-1”, “AMPUSER=”) in new stack

cynjut · March 22, 2017, 1:47pm

In line 1, the call gets sent to the blacklist check and comes back “not blacklisted”. The value of the return is ‘0’ and is displayed in in the GotoIf.

You can check the arguments for the Blacklist-Check module here.

The ‘s’ argument looks suspicious to me.

dicko · March 22, 2017, 2:07pm

Your first call has no callerid number you can see from your log the fsk failed, so it can’t be checked.

MC1 · March 22, 2017, 3:13pm

Hello.
Thanks for the feed back. I don’t think the Blacklist module is working as designed. From the DB 19055931770 has been successfully added to the Blacklist module. The logs show that 19055931770 isn’t being presented when it’s blacklisted and is being presented when it isn’t blacklisted. I’m not familiar with the bug reporting process. Is there a specific forum that I report it to or open a ticket with?