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

simonmason · July 9, 2012, 4:35pm

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

simonmason · July 9, 2012, 5:22pm

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.