Help needed with inconsistent behavior between incoming calls same SIP - different numbers

I have two numbers on the same SIP and they are behaving differently - I cannot figure out what is going on. I have a very simple setup with one incoming route for all calls. It hands off to a time of day announcement. The first number does not play the time of day announcement and proceeds to ring all phones - the log appears to show it playing but I can’t hear it when I call the number. The second number does play the time of day announcement then rings all phones. The traces are below: Any help would be greatly appreciated:

First number - does not play announcement:

[2012-07-09 12:22:54] VERBOSE[4531] logger.c: – Executing [[email protected]:1] NoOp(“SIP/smason-099eafd0”, “Catch-All DID Match - Found 19737018354 - You probably want a DID for this.”) in new stack
[2012-07-09 12:22:54] VERBOSE[4531] logger.c: – Executing [[email protected]:2] Goto(“SIP/smason-099eafd0”, “ext-did|s|1”) in new stack
[2012-07-09 12:22:54] VERBOSE[4531] logger.c: – Goto (ext-did,s,1)
[2012-07-09 12:22:54] VERBOSE[4531] logger.c: – Executing [[email protected]:1] ExecIf(“SIP/smason-099eafd0”, “1|Set|__FROM_DID=s”) in new stack
[2012-07-09 12:22:54] VERBOSE[4531] logger.c: – Executing [[email protected]:2] Gosub(“SIP/smason-099eafd0”, “cidlookup|cidlookup_4|1()”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099eafd0”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] Return(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Gosub(“SIP/smason-099eafd0”, “app-blacklist-check|s|1()”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099eafd0”, “0?blacklisted”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099eafd0”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099eafd0”, “CDR(did)=s”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:5] ExecIf(“SIP/smason-099eafd0”, “0 |Set|CALLERID(name)=9737223860”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:6] Macro(“SIP/smason-099eafd0”, “privacy-mgr|3|7”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099eafd0”, “KEEPCID=9737223860”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099eafd0”, “0?CIDTEST2:CIDTEST1”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (macro-privacy-mgr,s,3)
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099eafd0”, “TESTCID=9737223861.000000”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Goto(“SIP/smason-099eafd0”, “TESTRESULT”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (macro-privacy-mgr,s,6)
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: Goto
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-099eafd0”, “0?CLEARCID:PRIVMGR”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (macro-privacy-mgr,s,8)
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:8] PrivacyManager(“SIP/smason-099eafd0”, “3|7”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – CallerID Present: Skipping
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: PrivacyManager
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:9] GotoIf(“SIP/smason-099eafd0”, “0?fail”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:10] GosubIf(“SIP/smason-099eafd0”, “1?app-blacklist-check|s|1”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: GosubIf
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Incrementing gosub_level
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: LookupBlacklist
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099eafd0”, “0?blacklisted”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099eafd0”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: Return
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Decrementing gosub_level
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:11] SetCallerPres(“SIP/smason-099eafd0”, “allowed_passed_screen”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] app_macro.c: Executed application: SetCallerPres
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:7] Goto(“SIP/smason-099eafd0”, “timeconditions|1|1”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (timeconditions,1,1)
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIfTime(“SIP/smason-099eafd0”, “00:00-11:59|||?truestate") in new stack
[2012-07-09 12:22:55] DEBUG[4531] func_db.c: DB: TC/1 not found in database.
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099eafd0”, “0?truegoto”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] func_db.c: DB: TC/1 not found in database.
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] ExecIf(“SIP/smason-099eafd0”, “0|Set|DB(TC/1)=”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:4] GotoIf(“SIP/smason-099eafd0”, “1?timeconditions|2|1”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (timeconditions,2,1)
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIfTime(“SIP/smason-099eafd0”, "12:00-16:59|
||?truestate”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (timeconditions,2,7)
[2012-07-09 12:22:55] DEBUG[4531] func_db.c: DB: TC/2 not found in database.
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:7] GotoIf(“SIP/smason-099eafd0”, “0?falsegoto”) in new stack
[2012-07-09 12:22:55] DEBUG[4531] func_db.c: DB: TC/2 not found in database.
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:8] ExecIf(“SIP/smason-099eafd0”, “0|Set|DB(TC/2)=”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:9] GotoIf(“SIP/smason-099eafd0”, “1?app-announcement-2|s|1”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Goto (app-announcement-2,s,1)
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]app-announcement-2:1] GotoIf(“SIP/smason-099eafd0”, “0?begin”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:2] Answer(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:55] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Wait(“SIP/smason-099eafd0”, “1”) in new stack
[2012-07-09 12:22:56] VERBOSE[4531] logger.c: – Executing [[email protected]:4] NoOp(“SIP/smason-099eafd0”, “Playing announcement Good_Afternoon”) in new stack
[2012-07-09 12:22:56] VERBOSE[4531] logger.c: – Executing [[email protected]:5] Playback(“SIP/smason-099eafd0”, “custom/Good_Afternoon|noanswer”) in new stack
[2012-07-09 12:22:56] VERBOSE[4531] logger.c: – <SIP/smason-099eafd0> Playing ‘custom/Good_Afternoon’ (language ‘en’)
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:6] Goto(“SIP/smason-099eafd0”, “ext-group|600|1”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (ext-group,600,1)
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:1] Macro(“SIP/smason-099eafd0”, “user-callerid|”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099eafd0”, “AMPUSER=9737223860”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099eafd0”, “0?report”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:3] ExecIf(“SIP/smason-099eafd0”, “1|Set|REALCALLERIDNUM=9737223860”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: ExecIf
[2012-07-09 12:22:59] DEBUG[4531] func_db.c: DB: DEVICE/9737223860/user not found in database.
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099eafd0”, “AMPUSER=”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] DEBUG[4531] func_db.c: DB: AMPUSER//cidname not found in database.
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-099eafd0”, “AMPUSERCIDNAME=”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-099eafd0”, “1?report”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (macro-user-callerid,s,12)
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:12] GotoIf(“SIP/smason-099eafd0”, “0?continue”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:13] Set(“SIP/smason-099eafd0”, “__TTL=64”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:14] GotoIf(“SIP/smason-099eafd0”, “1?continue”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (macro-user-callerid,s,25)
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:25] Set(“SIP/smason-099eafd0”, “CALLERID(number)=9737223860”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:26] Set(“SIP/smason-099eafd0”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:2] Macro(“SIP/smason-099eafd0”, “blkvm-setifempty|”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099eafd0”, “1?init”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (macro-blkvm-setifempty,s,4)
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099eafd0”, “__BLKVM_OVERRIDE=BLKVM/600/SIP/smason-099eafd0”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-099eafd0”, “__BLKVM_BASE=600”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099eafd0”, “DB(BLKVM/600/SIP/smason-099eafd0)=TRUE”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:7] Set(“SIP/smason-099eafd0”, “GOSUB_RETVAL=TRUE”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:8] MacroExit(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:3] GotoIf(“SIP/smason-099eafd0”, “1?skipov”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (ext-group,600,6)
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099eafd0”, “RRNODEST=”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:7] Set(“SIP/smason-099eafd0”, “__NODEST=600”) in new stack
[2012-07-09 12:22:59] DEBUG[4531] func_db.c: DB: RINGGROUP/600/changecid not found in database.
[2012-07-09 12:22:59] DEBUG[4531] func_db.c: DB: RINGGROUP/600/changecid not found in database.
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:8] GosubIf(“SIP/smason-099eafd0”, “0?sub-rgsetcid|s|1()”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:9] Gosub(“SIP/smason-099eafd0”, “sub-record-check|s|1(rg|600|dontcare)”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099eafd0”, “1?check”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (sub-record-check,s,6)
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099eafd0”, “__MON_FMT=wav”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:7] GotoIf(“SIP/smason-099eafd0”, “1?next”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (sub-record-check,s,10)
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:10] ExecIf(“SIP/smason-099eafd0”, “1|Return|”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:10] Set(“SIP/smason-099eafd0”, “RingGroupMethod=ringall”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:11] Macro(“SIP/smason-099eafd0”, “dial|30|tr|200-201-203-205-206-207-210-215-225-402-403-500”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099eafd0”, “1?dial”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Goto (macro-dial,s,3)
[2012-07-09 12:22:59] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Executing [[email protected]:3] AGI(“SIP/smason-099eafd0”, “dialparties.agi”) in new stack
[2012-07-09 12:22:59] VERBOSE[4531] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: Starting New Dialparties.agi
[2012-07-09 12:23:00] VERBOSE[4533] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [2012-07-09 12:23:00] VERBOSE[4533] logger.c: Found
[2012-07-09 12:23:00] VERBOSE[4533] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [2012-07-09 12:23:00] VERBOSE[4533] logger.c: Found
[2012-07-09 12:23:00] VERBOSE[4533] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [2012-07-09 12:23:00] VERBOSE[4533] logger.c: Found
[2012-07-09 12:23:00] WARNING[4533] manager.c: Invalid writetimeout value ‘’ at line 10
[2012-07-09 12:23:00] VERBOSE[4533] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: Caller ID name is ‘Mason Simon’ number is ‘9737223860’
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: Methodology of ring is ‘ringall’
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 200 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 201 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 203 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 205 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 206 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 207 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 210 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 215 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 225 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 402 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 403 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Added extension 500 to extension map
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 200 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 201 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 203 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 205 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 206 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 207 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 210 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 215 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 225 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 402 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 403 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 500 cf is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 200 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 201 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 203 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 205 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 206 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 207 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 210 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 215 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 225 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 402 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 403 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Extension 500 do not disturb is disabled
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: ExtensionState: -1
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: Extension 200 has ExtensionState: -1
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Checking CW and CFB status for extension 200
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/200 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/201 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/203 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/205 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/206 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: ExtensionState: -1
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: dialparties.agi: Extension 207 has ExtensionState: -1
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Checking CW and CFB status for extension 207
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/207 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/210 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/215 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/225 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/402 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/403 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: dbset CALLTRACE/500 to 9737223860
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – dialparties.agi: Filtered ARG3: 200-201-203-205-206-207-210-215-225-402-403-500
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – AGI Script dialparties.agi completed, returning 0
[2012-07-09 12:23:00] DEBUG[4531] app_macro.c: Executed application: AGI
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Executing [[email protected]:7] Dial(“SIP/smason-099eafd0”, “SIP/201&SIP/203&SIP/205&SIP/206&ZAP/2&SIP/215&SIP/225&SIP/402&SIP/403&SIP/500|30|trM(auto-blkvm)”) in new stack
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 201
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] WARNING[4531] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] WARNING[4531] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 206
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 2
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4533] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[2012-07-09 12:23:00] WARNING[4531] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 225
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 402
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 403
[2012-07-09 12:23:00] WARNING[4531] rtp.c: Unable to set TOS to 184
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Called 500
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – SIP/206-099facb0 is ringing
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – SIP/225-09a0dff0 is ringing
[2012-07-09 12:23:00] VERBOSE[4531] logger.c: – SIP/500-09a1cc48 is ringing
[2012-07-09 12:23:01] VERBOSE[4531] logger.c: – SIP/403-09a178f8 is ringing
[2012-07-09 12:23:01] VERBOSE[612] logger.c: – Got SIP response 486 “Busy Here” back from 71.234.51.11
[2012-07-09 12:23:01] VERBOSE[4531] logger.c: – SIP/402-09a12aa0 is ringing
[2012-07-09 12:23:01] VERBOSE[4531] logger.c: – SIP/403-09a178f8 is busy
[2012-07-09 12:23:01] VERBOSE[4531] logger.c: – SIP/201-099e4678 is ringing
[2012-07-09 12:23:02] VERBOSE[4531] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Hungup ‘Zap/2-1’
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/smason-099eafd0’ in macro ‘dial’
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/smason-099eafd0’
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:1] Macro(“SIP/smason-099eafd0”, “hangupcall”) in new stack
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099eafd0”, “1?skiprg”) in new stack
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Goto (macro-hangupcall,s,3)
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:3] GotoIf(“SIP/smason-099eafd0”, “0?skipblkvm”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:4] Macro(“SIP/smason-099eafd0”, “blkvm-clr|”) in new stack
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099eafd0”, “0?ret”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:2] NoOp(“SIP/smason-099eafd0”, “Deleting: BLKVM/600/SIP/smason-099eafd0 TRUE”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: Noop
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099eafd0”, “GOSUB_RETVAL=”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: Set
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:4] MacroExit(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: Macro
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:5] GotoIf(“SIP/smason-099eafd0”, “1?theend”) in new stack
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Goto (macro-hangupcall,s,7)
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: GotoIf
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:7] ExecIf(“SIP/smason-099eafd0”, “0|Set|CDR(recordingfile)=”) in new stack
[2012-07-09 12:23:07] DEBUG[4531] app_macro.c: Executed application: ExecIf
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: – Executing [[email protected]:8] Hangup(“SIP/smason-099eafd0”, “”) in new stack
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: == Spawn extension (macro-hangupcall, s, 8) exited non-zero on ‘SIP/smason-099eafd0’ in macro ‘hangupcall’
[2012-07-09 12:23:07] VERBOSE[4531] logger.c: == Spawn extension (macro-hangupcall, s, 8) exited non-zero on ‘SIP/smason-099eafd0’

Second Number - does play announcement:

[2012-07-09 12:00:31] VERBOSE[4461] logger.c: – Executing [[email protected]:1] NoOp(“SIP/smason-099ee450”, “Catch-All DID Match - Found 18622466913 - You probably want a DID for this.”) in new stack
[2012-07-09 12:00:31] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Goto(“SIP/smason-099ee450”, “ext-did|s|1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (ext-did,s,1)
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] ExecIf(“SIP/smason-099ee450”, “1|Set|__FROM_DID=s”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Gosub(“SIP/smason-099ee450”, “cidlookup|cidlookup_4|1()”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099ee450”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Return(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Gosub(“SIP/smason-099ee450”, “app-blacklist-check|s|1()”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099ee450”, “0?blacklisted”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099ee450”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099ee450”, “CDR(did)=s”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:5] ExecIf(“SIP/smason-099ee450”, “0 |Set|CALLERID(name)=9737223860”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:6] Macro(“SIP/smason-099ee450”, “privacy-mgr|3|7”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099ee450”, “KEEPCID=9737223860”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099ee450”, “0?CIDTEST2:CIDTEST1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (macro-privacy-mgr,s,3)
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099ee450”, “TESTCID=9737223861.000000”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Goto(“SIP/smason-099ee450”, “TESTRESULT”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (macro-privacy-mgr,s,6)
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: Goto
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-099ee450”, “0?CLEARCID:PRIVMGR”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (macro-privacy-mgr,s,8)
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:8] PrivacyManager(“SIP/smason-099ee450”, “3|7”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – CallerID Present: Skipping
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: PrivacyManager
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:9] GotoIf(“SIP/smason-099ee450”, “0?fail”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:10] GosubIf(“SIP/smason-099ee450”, “1?app-blacklist-check|s|1”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: GosubIf
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Incrementing gosub_level
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] LookupBlacklist(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: LookupBlacklist
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099ee450”, “0?blacklisted”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099ee450”, “CALLED_BLACKLIST=1”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Return(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: Return
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Decrementing gosub_level
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:11] SetCallerPres(“SIP/smason-099ee450”, “allowed_passed_screen”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] app_macro.c: Executed application: SetCallerPres
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:7] Goto(“SIP/smason-099ee450”, “timeconditions|1|1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (timeconditions,1,1)
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIfTime(“SIP/smason-099ee450”, “00:00-11:59|||?truestate") in new stack
[2012-07-09 12:00:32] DEBUG[4461] func_db.c: DB: TC/1 not found in database.
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]econditions:2] GotoIf(“SIP/smason-099ee450”, “0?truegoto”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] func_db.c: DB: TC/1 not found in database.
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] ExecIf(“SIP/smason-099ee450”, “0|Set|DB(TC/1)=”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:4] GotoIf(“SIP/smason-099ee450”, “1?timeconditions|2|1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (timeconditions,2,1)
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIfTime(“SIP/smason-099ee450”, "12:00-16:59|
||?truestate”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (timeconditions,2,7)
[2012-07-09 12:00:32] DEBUG[4461] func_db.c: DB: TC/2 not found in database.
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:7] GotoIf(“SIP/smason-099ee450”, “0?falsegoto”) in new stack
[2012-07-09 12:00:32] DEBUG[4461] func_db.c: DB: TC/2 not found in database.
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:8] ExecIf(“SIP/smason-099ee450”, “0|Set|DB(TC/2)=”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:9] GotoIf(“SIP/smason-099ee450”, “1?app-announcement-2|s|1”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Goto (app-announcement-2,s,1)
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099ee450”, “0?begin”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Answer(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:32] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Wait(“SIP/smason-099ee450”, “1”) in new stack
[2012-07-09 12:00:33] VERBOSE[4461] logger.c: – Executing [[email protected]:4] NoOp(“SIP/smason-099ee450”, “Playing announcement Good_Afternoon”) in new stack
[2012-07-09 12:00:33] VERBOSE[4461] logger.c: – Executing [[email protected]:5] Playback(“SIP/smason-099ee450”, “custom/Good_Afternoon|noanswer”) in new stack
[2012-07-09 12:00:33] VERBOSE[4461] logger.c: – <SIP/smason-099ee450> Playing ‘custom/Good_Afternoon’ (language ‘en’)
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:6] Goto(“SIP/smason-099ee450”, “ext-group|600|1”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Goto (ext-group,600,1)
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Macro(“SIP/smason-099ee450”, “user-callerid|”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099ee450”, “AMPUSER=9737223860”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:2] GotoIf(“SIP/smason-099ee450”, “0?report”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:3] ExecIf(“SIP/smason-099ee450”, “1|Set|REALCALLERIDNUM=9737223860”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: ExecIf
[2012-07-09 12:00:36] DEBUG[4461] func_db.c: DB: DEVICE/9737223860/user not found in database.
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099ee450”, “AMPUSER=”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] DEBUG[4461] func_db.c: DB: AMPUSER//cidname not found in database.
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-099ee450”, “AMPUSERCIDNAME=”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:6] GotoIf(“SIP/smason-099ee450”, “1?report”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Goto (macro-user-callerid,s,12)
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:12] GotoIf(“SIP/smason-099ee450”, “0?continue”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:13] Set(“SIP/smason-099ee450”, “__TTL=64”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:14] GotoIf(“SIP/smason-099ee450”, “1?continue”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Goto (macro-user-callerid,s,25)
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:25] Set(“SIP/smason-099ee450”, “CALLERID(number)=9737223860”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:26] Set(“SIP/smason-099ee450”, "CALLERID(name)=Mason Simon ") in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Macro(“SIP/smason-099ee450”, “blkvm-setifempty|”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099ee450”, “1?init”) in new stack
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Goto (macro-blkvm-setifempty,s,4)
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:4] Set(“SIP/smason-099ee450”, “__BLKVM_OVERRIDE=BLKVM/600/SIP/smason-099ee450”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:5] Set(“SIP/smason-099ee450”, “__BLKVM_BASE=600”) in new stack
[2012-07-09 12:00:36] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:36] VERBOSE[4461] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099ee450”, “DB(BLKVM/600/SIP/smason-099ee450)=TRUE”) in new stack
[2012-07-09 12:00:37] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:7] Set(“SIP/smason-099ee450”, “GOSUB_RETVAL=TRUE”) in new stack
[2012-07-09 12:00:37] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:8] MacroExit(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:3] GotoIf(“SIP/smason-099ee450”, “1?skipov”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Goto (ext-group,600,6)
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099ee450”, “RRNODEST=”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:7] Set(“SIP/smason-099ee450”, “__NODEST=600”) in new stack
[2012-07-09 12:00:37] DEBUG[4461] func_db.c: DB: RINGGROUP/600/changecid not found in database.
[2012-07-09 12:00:37] DEBUG[4461] func_db.c: DB: RINGGROUP/600/changecid not found in database.
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:8] GosubIf(“SIP/smason-099ee450”, “0?sub-rgsetcid|s|1()”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:9] Gosub(“SIP/smason-099ee450”, “sub-record-check|s|1(rg|600|dontcare)”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099ee450”, “1?check”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Goto (sub-record-check,s,6)
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:6] Set(“SIP/smason-099ee450”, “__MON_FMT=wav”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:7] GotoIf(“SIP/smason-099ee450”, “1?next”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Goto (sub-record-check,s,10)
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:10] ExecIf(“SIP/smason-099ee450”, “1|Return|”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:10] Set(“SIP/smason-099ee450”, “RingGroupMethod=ringall”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:11] Macro(“SIP/smason-099ee450”, “dial|30|tr|200-201-203-205-206-207-210-215-225-402-403-500”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099ee450”, “1?dial”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Goto (macro-dial,s,3)
[2012-07-09 12:00:37] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:3] AGI(“SIP/smason-099ee450”, “dialparties.agi”) in new stack
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: Starting New Dialparties.agi
[2012-07-09 12:00:37] VERBOSE[4463] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [2012-07-09 12:00:37] VERBOSE[4463] logger.c: Found
[2012-07-09 12:00:37] VERBOSE[4463] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [2012-07-09 12:00:37] VERBOSE[4463] logger.c: Found
[2012-07-09 12:00:37] VERBOSE[4463] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [2012-07-09 12:00:37] VERBOSE[4463] logger.c: Found
[2012-07-09 12:00:37] WARNING[4463] manager.c: Invalid writetimeout value ‘’ at line 10
[2012-07-09 12:00:37] VERBOSE[4463] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: Caller ID name is ‘Mason Simon’ number is ‘9737223860’
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: Methodology of ring is ‘ringall’
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 200 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 201 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 203 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 205 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 206 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 207 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 210 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 215 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 225 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 402 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 403 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Added extension 500 to extension map
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 200 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 201 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 203 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 205 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 206 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 207 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 210 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 215 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 225 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 402 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 403 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 500 cf is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 200 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 201 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 203 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 205 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 206 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 207 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 210 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 215 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 225 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 402 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 403 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Extension 500 do not disturb is disabled
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: ExtensionState: -1
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: Extension 200 has ExtensionState: -1
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Checking CW and CFB status for extension 200
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/200 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/201 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/203 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/205 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/206 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: ExtensionState: -1
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: dialparties.agi: Extension 207 has ExtensionState: -1
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Checking CW and CFB status for extension 207
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/207 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/210 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/215 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/225 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/402 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/403 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: dbset CALLTRACE/500 to 9737223860
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – dialparties.agi: Filtered ARG3: 200-201-203-205-206-207-210-215-225-402-403-500
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – AGI Script dialparties.agi completed, returning 0
[2012-07-09 12:00:37] DEBUG[4461] app_macro.c: Executed application: AGI
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Executing [[email protected]:7] Dial(“SIP/smason-099ee450”, “SIP/201&SIP/203&SIP/205&SIP/206&ZAP/2&SIP/215&SIP/225&SIP/402&SIP/403&SIP/500|30|trM(auto-blkvm)”) in new stack
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 201
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] WARNING[4461] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] WARNING[4461] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 206
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 2
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4463] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[2012-07-09 12:00:37] WARNING[4461] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 225
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 402
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 403
[2012-07-09 12:00:37] WARNING[4461] rtp.c: Unable to set TOS to 184
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Called 500
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – SIP/206-099e49d8 is ringing
[2012-07-09 12:00:37] VERBOSE[4461] logger.c: – SIP/225-09a0b320 is ringing
[2012-07-09 12:00:38] VERBOSE[4461] logger.c: – SIP/500-09a191d0 is ringing
[2012-07-09 12:00:38] VERBOSE[4461] logger.c: – SIP/403-09a13e58 is ringing
[2012-07-09 12:00:38] VERBOSE[612] logger.c: – Got SIP response 486 “Busy Here” back from 71.234.51.11
[2012-07-09 12:00:38] VERBOSE[4461] logger.c: – SIP/403-09a13e58 is busy
[2012-07-09 12:00:38] VERBOSE[4461] logger.c: – SIP/402-09a0f298 is ringing
[2012-07-09 12:00:38] VERBOSE[4461] logger.c: – SIP/201-099eafd0 is ringing
[2012-07-09 12:00:39] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:00:45] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:00:51] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:00:57] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:01:03] VERBOSE[4461] logger.c: – Zap/2-1 is ringing
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Nobody picked up in 30000 ms
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Hungup ‘Zap/2-1’
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: Dial
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:8] Set(“SIP/smason-099ee450”, “DIALSTATUS=NOANSWER”) in new stack
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:9] GosubIf(“SIP/smason-099ee450”, “0?NOANSWER|1”) in new stack
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: GosubIf
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:12] Gosub(“SIP/smason-099ee450”, “sub-record-cancel|s|1()”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:1] ExecIf(“SIP/smason-099ee450”, “1|Return|”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:13] Set(“SIP/smason-099ee450”, “RingGroupMethod=”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:14] GotoIf(“SIP/smason-099ee450”, “0?nodest”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:15] Set(“SIP/smason-099ee450”, “__NODEST=”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:16] Macro(“SIP/smason-099ee450”, “blkvm-clr|”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:1] GotoIf(“SIP/smason-099ee450”, “0?ret”) in new stack
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: GotoIf
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:2] NoOp(“SIP/smason-099ee450”, “Deleting: BLKVM/600/SIP/smason-099ee450 TRUE”) in new stack
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: Noop
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099ee450”, “GOSUB_RETVAL=”) in new stack
[2012-07-09 12:01:08] DEBUG[4461] app_macro.c: Executed application: Set
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:4] MacroExit(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:17] Goto(“SIP/smason-099ee450”, “ivr-2|s|1”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Goto (ivr-2,s,1)
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Set(“SIP/smason-099ee450”, “_IVR_CONTEXT_ivr-2=”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:2] Set(“SIP/smason-099ee450”, “_IVR_CONTEXT=ivr-2”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:3] Set(“SIP/smason-099ee450”, “__IVR_RETVM=”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:4] GotoIf(“SIP/smason-099ee450”, “1?skip”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Goto (ivr-2,s,7)
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:7] Set(“SIP/smason-099ee450”, “IVR_MSG=custom/GeneralMessage1”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:8] Set(“SIP/smason-099ee450”, “TIMEOUT(digit)=3”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Digit timeout set to 3
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – Executing [[email protected]:9] ExecIf(“SIP/smason-099ee450”, “1|Background|custom/GeneralMessage1”) in new stack
[2012-07-09 12:01:08] VERBOSE[4461] logger.c: – <SIP/smason-099ee450> Playing ‘custom/GeneralMessage1’ (language ‘en’)
[2012-07-09 12:01:13] NOTICE[612] chan_sip.c: Disconnecting call ‘SIP/smason-099ee450’ for lack of RTP activity in 31 seconds
[2012-07-09 12:01:13] VERBOSE[4461] logger.c: == Spawn extension (ivr-2, s, 9) exited non-zero on ‘SIP/smason-099ee450’
[2012-07-09 12:01:13] VERBOSE[4461] logger.c: – Executing [[email protected]:1] Hangup(“SIP/smason-099ee450”, “”) in new stack
[2012-07-09 12:01:13] VERBOSE[4461] logger.c: == Spawn extension (ivr-2, h, 1) exited non-zero on ‘SIP/smason-099ee450’
[2012-07-09 12:02:02] VERBOSE[4471] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [2012-07-09 12:02:02] VERBOSE[4471] logger.c: Found
[2012-07-09 12:02:02] VERBOSE[4471] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [2012-07-09 12:02:02] VERBOSE[4471] logger.c: Found
[2012-07-09 12:02:02] VERBOSE[4471] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [2012-07-09 12:02:02] VERBOSE[4471] logger.c: Found
[2012-07-09 12:02:02] WARNING[4471] manager.c: Invalid writetimeout value ‘’ at line 10
[2012-07-09 12:02:02] VERBOSE[4471] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[2012-07-09 12:02:02] VERBOSE[4471] logger.c: == Manager ‘admin’ logged off from 127.0.0.1

Some additional information - I just disabled Privacy Manager and everything now works as planned. Can anyone elaborate on how Privacy Manager might interfere with the incoming call routing? Thanks.