I’m not sure if you need pjsip debug on and if pulling from logs is sufficient.
Here are two successive inbound lookups. This number should have been cached even before
the first lookup.
first call:
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:3] Set("PJSIP/MainRouteIn-00000c92", "CHANNEL(tonezone)=us") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:4] Set("PJSIP/MainRouteIn-00000c92", "__FROM_DID=1xxxxxx1978") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:5] Set("PJSIP/MainRouteIn-00000c92", "returnhere=1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:6] Gosub("PJSIP/MainRouteIn-00000c92", "app-blacklist-check,s,1()") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/MainRouteIn-00000c92", "0?blacklisted") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/MainRouteIn-00000c92", "CALLED_BLACKLIST=1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:7] Set("PJSIP/MainRouteIn-00000c92", "CDR(did)=1xxxxxx1978") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:8] GotoIf("PJSIP/MainRouteIn-00000c92", "0?") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:9] ExecIf("PJSIP/MainRouteIn-00000c92", "0 ?Set(CALLERID(name)=1xxxxxx7359)") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:10] Set("PJSIP/MainRouteIn-00000c92", "CHANNEL(musicclass)=stream-70s") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:11] Set("PJSIP/MainRouteIn-00000c92", "__MOHCLASS=stream-70s") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:12] Set("PJSIP/MainRouteIn-00000c92", "__REVERSAL_REJECT=FALSE") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:13] GotoIf("PJSIP/MainRouteIn-00000c92", "1?post-reverse-charge") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx_builtins.c: Goto (from-pstn,1xxxxxx1978,15)
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:15] NoOp("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:16] Set("PJSIP/MainRouteIn-00000c92", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:17] Set("PJSIP/MainRouteIn-00000c92", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:18] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:19] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:20] Gosub("PJSIP/MainRouteIn-00000c92", "cidlookup,cidlookup_1,1()") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:1] Set("PJSIP/MainRouteIn-00000c92", "CURLOPT(httptimeout)=7") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:2] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(name)=MR ZERVA") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:3] Set("PJSIP/MainRouteIn-00000c92", "DB(cidname/1xxxxxx7359)=MR ZERVA") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:4] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:21] NoOp("PJSIP/MainRouteIn-00000c92", "CallerID Entry Point") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:22] Goto("PJSIP/MainRouteIn-00000c92", "from-did-direct,206,1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx_builtins.c: Goto (from-did-direct,206,1)
second call:
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:3] Set("PJSIP/MainRouteIn-00000c92", "CHANNEL(tonezone)=us") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:4] Set("PJSIP/MainRouteIn-00000c92", "__FROM_DID=1xxxxxx1978") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:5] Set("PJSIP/MainRouteIn-00000c92", "returnhere=1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:6] Gosub("PJSIP/MainRouteIn-00000c92", "app-blacklist-check,s,1()") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/MainRouteIn-00000c92", "0?blacklisted") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/MainRouteIn-00000c92", "CALLED_BLACKLIST=1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:7] Set("PJSIP/MainRouteIn-00000c92", "CDR(did)=1xxxxxx1978") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:8] GotoIf("PJSIP/MainRouteIn-00000c92", "0?") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:9] ExecIf("PJSIP/MainRouteIn-00000c92", "0 ?Set(CALLERID(name)=1xxxxxx7359)") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:10] Set("PJSIP/MainRouteIn-00000c92", "CHANNEL(musicclass)=stream-70s") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:11] Set("PJSIP/MainRouteIn-00000c92", "__MOHCLASS=stream-70s") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:12] Set("PJSIP/MainRouteIn-00000c92", "__REVERSAL_REJECT=FALSE") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:13] GotoIf("PJSIP/MainRouteIn-00000c92", "1?post-reverse-charge") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx_builtins.c: Goto (from-pstn,1xxxxxx1978,15)
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:15] NoOp("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:16] Set("PJSIP/MainRouteIn-00000c92", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:17] Set("PJSIP/MainRouteIn-00000c92", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:18] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:19] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:20] Gosub("PJSIP/MainRouteIn-00000c92", "cidlookup,cidlookup_1,1()") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:1] Set("PJSIP/MainRouteIn-00000c92", "CURLOPT(httptimeout)=7") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:2] Set("PJSIP/MainRouteIn-00000c92", "CALLERID(name)=MR ZERVA") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:3] Set("PJSIP/MainRouteIn-00000c92", "DB(cidname/1xxxxxx7359)=MR ZERVA") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [cidlookup_1@cidlookup:4] Return("PJSIP/MainRouteIn-00000c92", "") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:21] NoOp("PJSIP/MainRouteIn-00000c92", "CallerID Entry Point") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [1xxxxxx1978@from-pstn:22] Goto("PJSIP/MainRouteIn-00000c92", "from-did-direct,206,1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx_builtins.c: Goto (from-did-direct,206,1)
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [206@from-did-direct:1] GotoIf("PJSIP/MainRouteIn-00000c92", "1?ext-local,206,1:followme-check,206,1") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx_builtins.c: Goto (ext-local,206,1)
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [206@ext-local:1] Set("PJSIP/MainRouteIn-00000c92", "__RINGTIMER=15") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [206@ext-local:2] ExecIf("PJSIP/MainRouteIn-00000c92", "0?Set(__CWIGNORE=)") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [206@ext-local:3] Macro("PJSIP/MainRouteIn-00000c92", "exten-vm,206,206,0,0,0") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/MainRouteIn-00000c92", "user-callerid,") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/MainRouteIn-00000c92", "TOUCH_MONITOR=1597441091.11115") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/MainRouteIn-00000c92", "AMPUSER=1xxxxxx7359") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/MainRouteIn-00000c92", "HOTDESCKCHAN=MainRouteIn-00000c92") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/MainRouteIn-00000c92", "HOTDESKEXTEN=MainRouteIn") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/MainRouteIn-00000c92", "HOTDESKCALL=0") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("PJSIP/MainRouteIn-00000c92", "0?Set(HOTDESKCALL=1)") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("PJSIP/MainRouteIn-00000c92", "0?Set(CALLERID(name)=)") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/MainRouteIn-00000c92", "0?report") in new stack
[2020-08-14 21:38:11] VERBOSE[25398][C-0000052c] pbx.c: Executing [s@macro-user-callerid:9] ExecIf("PJSIP/MainRouteIn-00000c92", "1?Set(REALCALLERIDNUM=1xxxxxx7359)") in new stack
Both calls show up in OpenCNAM report as charged lookups.
I’m seeing this symptom across multiple servers (all on the same version). I think it started several months ago (perhaps after some updates).