Help needed with another inbound route

In the following log the number is ringing busy. I have a DID setup for 18622466913. I have another DID on this SIP and I am able to grab that one just fine. What am I doing wrong? Thanks.

[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-09ae4140”, “__FROM_DID=18622466913”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [186[email protected]:2] Gosub(“SIP/smason-09ae4140”, “cidlookup|cidlookup_4|1()”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-09ae4140”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] Return(“SIP/smason-09ae4140”, “”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] Gosub(“SIP/smason-09ae4140”, “app-blacklist-check|s|1()”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-09ae4140”, “”) in new stack
[2012-07-18 20:40:25] WARNING[7948] app_lookupblacklist.c: LookupBlacklist is deprecated. Please use ${BLACKLIST()} instead.
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-09ae4140”, “0?blacklisted”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-09ae4140”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-09ae4140”, “”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-09ae4140”, “CDR(did)=18622466913”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:5] ExecIf(“SIP/smason-09ae4140”, “0 |Set|CALLERID(name)=9737223860”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:6] Macro(“SIP/smason-09ae4140”, “privacy-mgr|3|7”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-09ae4140”, “KEEPCID=9737223860”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-09ae4140”, “0?CIDTEST2:CIDTEST1”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (macro-privacy-mgr,s,3)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-09ae4140”, “TESTCID=9737223861.000000”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Goto(“SIP/smason-09ae4140”, “TESTRESULT”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (macro-privacy-mgr,s,6)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Goto
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-09ae4140”, “0?CLEARCID:PRIVMGR”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (macro-privacy-mgr,s,8)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:8] PrivacyManager(“SIP/smason-09ae4140”, “3|7”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – CallerID Present: Skipping
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: PrivacyManager
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:9] GotoIf(“SIP/smason-09ae4140”, “0?fail”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:10] GosubIf(“SIP/smason-09ae4140”, “1?app-blacklist-check|s|1”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GosubIf
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Incrementing gosub_level
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-09ae4140”, “”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: LookupBlacklist
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-09ae4140”, “0?blacklisted”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-09ae4140”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-09ae4140”, “”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Return
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Decrementing gosub_level
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:11] SetCallerPres(“SIP/smason-09ae4140”, “allowed_passed_screen”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: SetCallerPres
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:7] Goto(“SIP/smason-09ae4140”, “from-did-direct|221|1”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (from-did-direct,221,1)
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-09ae4140”, “__RINGTIMER=8”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] Macro(“SIP/smason-09ae4140”, “exten-vm|novm|221|0|0|0”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Macro(“SIP/smason-09ae4140”, “user-callerid|”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-09ae4140”, “AMPUSER=9737223860”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-09ae4140”, “0?report”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] ExecIf(“SIP/smason-09ae4140”, “1|Set|REALCALLERIDNUM=9737223860”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: ExecIf
[2012-07-18 20:40:25] DEBUG[7948] func_db.c: DB: DEVICE/9737223860/user not found in database.
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-09ae4140”, “AMPUSER=”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] DEBUG[7948] func_db.c: DB: AMPUSER//cidname not found in database.
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-09ae4140”, “AMPUSERCIDNAME=”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-09ae4140”, “1?report”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (macro-user-callerid,s,12)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:12] GotoIf(“SIP/smason-09ae4140”, “0?continue”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:13] Set(“SIP/smason-09ae4140”, “__TTL=64”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:14] GotoIf(“SIP/smason-09ae4140”, “1?continue”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (macro-user-callerid,s,25)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:25] Set(“SIP/smason-09ae4140”, “CALLERID(number)=9737223860”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:26] Set(“SIP/smason-09ae4140”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Macro
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:2] Set(“SIP/smason-09ae4140”, “RingGroupMethod=none”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-09ae4140”, “__EXTTOCALL=221”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-09ae4140”, “__PICKUPMARK=221”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] DEBUG[7948] func_db.c: DB: CFU/221 not found in database.
[2012-07-18 20:40:25] DEBUG[7948] func_db.c: DB: CFB/221 not found in database.
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-09ae4140”, “RT=”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:6] Gosub(“SIP/smason-09ae4140”, “sub-record-check|s|1(exten|221|)”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Gosub
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Incrementing gosub_level
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-09ae4140”, “1?check”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (sub-record-check,s,6)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-09ae4140”, “__MON_FMT=wav”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:7] GotoIf(“SIP/smason-09ae4140”, “1?next”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (sub-record-check,s,10)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:10] ExecIf(“SIP/smason-09ae4140”, “0|Return|”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: ExecIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:11] GotoIf(“SIP/smason-09ae4140”, “0?novm|1”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: GotoIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:12] Set(“SIP/smason-09ae4140”, “__REC_STATUS=INITIALIZED”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:13] ExecIf(“SIP/smason-09ae4140”, “1|Set|__REC_POLICY_MODE=0”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: ExecIf
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:14] Set(“SIP/smason-09ae4140”, “NOW=1342658425”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:15] Set(“SIP/smason-09ae4140”, “__DAY=18”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:16] Set(“SIP/smason-09ae4140”, “__MONTH=07”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:17] Set(“SIP/smason-09ae4140”, “__YEAR=2012”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:18] Set(“SIP/smason-09ae4140”, “__TIMESTR=20120718-204025”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:19] Set(“SIP/smason-09ae4140”, “__FROMEXTEN=9737223860”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:20] Set(“SIP/smason-09ae4140”, “__CALLFILENAME=novm-221-9737223860-20120718-204025-1342658425.1”) in new stack
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Set
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Executing [[email protected]:21] Goto(“SIP/smason-09ae4140”, “novm|1”) in new stack
[2012-07-18 20:40:25] VERBOSE[7948] logger.c: – Goto (sub-record-check,novm,1)
[2012-07-18 20:40:25] DEBUG[7948] app_macro.c: Executed application: Goto
[2012-07-18 20:40:25] WARNING[7948] pbx.c: Channel ‘SIP/smason-09ae4140’ sent into invalid extension ‘novm’ in context ‘sub-record-check’, but no invalid handler
[2012-07-18 20:40:25] VERBOSE[7947] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[2012-07-18 20:40:32] VERBOSE[7958] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [2012-07-18 20:40:32] VERBOSE[7958] logger.c: Found
[2012-07-18 20:40:32] VERBOSE[7958] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [2012-07-18 20:40:32] VERBOSE[7958] logger.c: Found
[2012-07-18 20:40:32] VERBOSE[7958] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [2012-07-18 20:40:32] VERBOSE[7958] logger.c: Found

You have some loop where the route is going back out an external context with a dialed digits of 221

bump

Any clues to what could cause this loop? Thanks.