[Sep 10 11:53:09] VERBOSE[4715] logger.c: == Starting mISDN/2-u0 at from-pstn,,1 failed so falling back to exten 's'
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:1] Set("mISDN/2-u0", "__FROM_DID=s") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:2] Gosub("mISDN/2-u0", "app-blacklist-check|s|1") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@app-blacklist-check:1] LookupBlacklist("mISDN/2-u0", "") in new stack
[Sep 10 11:53:09] WARNING[4715] app_lookupblacklist.c: LookupBlacklist is deprecated. Please use ${BLACKLIST()} instead.
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@app-blacklist-check:2] GotoIf("mISDN/2-u0", "0?blacklisted") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@app-blacklist-check:3] Return("mISDN/2-u0", "") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:3] GotoIf("mISDN/2-u0", "0 ?cidok") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:4] Set("mISDN/2-u0", "CALLERID(name)=001") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:5] NoOp("mISDN/2-u0", "CallerID is "001" <001>") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:6] Set("mISDN/2-u0", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:7] SetCallerPres("mISDN/2-u0", "allowed_not_screened") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@from-pstn:8] Goto("mISDN/2-u0", "from-did-direct|00888|1") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Goto (from-did-direct,00888,1)
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [00888@from-did-direct:1] Macro("mISDN/2-u0", "exten-vm|00888|00888") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:1] Macro("mISDN/2-u0", "user-callerid") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:1] Set("mISDN/2-u0", "AMPUSER=001") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("mISDN/2-u0", "0?report") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("mISDN/2-u0", "1|Set|REALCALLERIDNUM=001") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: ExecIf
[Sep 10 11:53:09] DEBUG[4715] func_db.c: DB: DEVICE/001/user not found in database.
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:4] Set("mISDN/2-u0", "AMPUSER=") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] DEBUG[4715] func_db.c: DB: AMPUSER//cidname not found in database.
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:5] Set("mISDN/2-u0", "AMPUSERCIDNAME=") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("mISDN/2-u0", "1?report") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Goto (macro-user-callerid,s,10)
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("mISDN/2-u0", "0?continue") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:11] Set("mISDN/2-u0", "__TTL=64") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:12] GotoIf("mISDN/2-u0", "1?continue") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Goto (macro-user-callerid,s,19)
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("mISDN/2-u0", "Using CallerID "001" <001>") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Noop
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Macro
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:2] Set("mISDN/2-u0", "RingGroupMethod=none") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:3] Set("mISDN/2-u0", "VMBOX=00888") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:4] Set("mISDN/2-u0", "EXTTOCALL=00888") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] DEBUG[4715] func_db.c: DB: CFU/00888 not found in database.
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:5] Set("mISDN/2-u0", "CFUEXT=") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] DEBUG[4715] func_db.c: DB: CFB/00888 not found in database.
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:6] Set("mISDN/2-u0", "CFBEXT=") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:7] Set("mISDN/2-u0", "RT=15") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Set
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:8] Macro("mISDN/2-u0", "record-enable|00888|IN") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("mISDN/2-u0", "1?check") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Goto (macro-record-enable,s,4)
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-record-enable:4] AGI("mISDN/2-u0", "recordingcheck|20080910-115309|1221040389.0") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Sep 10 11:53:09] VERBOSE[4715] logger.c: recordingcheck|20080910-115309|1221040389.0: Inbound recording not enabled
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- AGI Script recordingcheck completed, returning 0
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: AGI
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("mISDN/2-u0", "") in new stack
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: Macro
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-exten-vm:9] Macro("mISDN/2-u0", "dial|15|tr|00888") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-dial:1] GotoIf("mISDN/2-u0", "1?dial") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Goto (macro-dial,s,3)
[Sep 10 11:53:09] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Executing [s@macro-dial:3] AGI("mISDN/2-u0", "dialparties.agi") in new stack
[Sep 10 11:53:09] VERBOSE[4715] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Sep 10 11:53:10] VERBOSE[4715] logger.c: dialparties.agi: Starting New Dialparties.agi
[Sep 10 11:53:10] VERBOSE[4718] logger.c: == Parsing '/etc/asterisk/manager.conf': [Sep 10 11:53:10] VERBOSE[4718] logger.c: Found
[Sep 10 11:53:10] VERBOSE[4718] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Sep 10 11:53:10] VERBOSE[4718] logger.c: Found
[Sep 10 11:53:10] VERBOSE[4718] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Sep 10 11:53:10] VERBOSE[4718] logger.c: Found
[Sep 10 11:53:10] VERBOSE[4718] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Sep 10 11:53:10] VERBOSE[4715] logger.c: dialparties.agi: Caller ID name is '001' number is '001'
[Sep 10 11:53:10] VERBOSE[4715] logger.c: dialparties.agi: Methodology of ring is 'none'
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- dialparties.agi: Added extension 00888 to extension map
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- dialparties.agi: Extension 00888 cf is disabled
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- dialparties.agi: Extension 00888 do not disturb is disabled
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- dialparties.agi: dbset CALLTRACE/00888 to 001
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- dialparties.agi: Filtered ARG3: 00888
[Sep 10 11:53:10] VERBOSE[4718] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Sep 10 11:53:10] DEBUG[4715] app_macro.c: Executed application: AGI
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- Executing [s@macro-dial:7] Dial("mISDN/2-u0", "SIP/00888|15|tr") in new stack
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- Called 00888
[Sep 10 11:53:10] VERBOSE[4715] logger.c: -- SIP/00888-082213b8 is ringing
[Sep 10 11:53:11] VERBOSE[4715] logger.c: -- SIP/00888-082213b8 is ringing
[Sep 10 11:53:11] VERBOSE[4715] logger.c: -- SIP/00888-082213b8 answered mISDN/2-u0
[Sep 10 11:53:15] VERBOSE[4715] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'mISDN/2-u0' in macro 'dial'
[Sep 10 11:53:15] VERBOSE[4715] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'mISDN/2-u0' in macro 'exten-vm'
[Sep 10 11:53:15] VERBOSE[4715] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'mISDN/2-u0'
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [h@macro-dial:1] Macro("mISDN/2-u0", "hangupcall") in new stack
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("mISDN/2-u0", "w") in new stack
[Sep 10 11:53:15] DEBUG[4715] app_macro.c: Executed application: ResetCDR
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("mISDN/2-u0", "") in new stack
[Sep 10 11:53:15] DEBUG[4715] app_macro.c: Executed application: NoCDR
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("mISDN/2-u0", "1?skiprg") in new stack
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Goto (macro-hangupcall,s,6)
[Sep 10 11:53:15] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("mISDN/2-u0", "1?skipblkvm") in new stack
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Goto (macro-hangupcall,s,9)
[Sep 10 11:53:15] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("mISDN/2-u0", "1?theend") in new stack
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Goto (macro-hangupcall,s,11)
[Sep 10 11:53:15] DEBUG[4715] app_macro.c: Executed application: GotoIf
[Sep 10 11:53:15] VERBOSE[4715] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("mISDN/2-u0", "") in new stack
[Sep 10 11:53:15] VERBOSE[4715] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'mISDN/2-u0' in macro 'hangupcall'
[Sep 10 11:53:15] VERBOSE[4715] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'mISDN/2-u0'
[Sep 10 11:53:15] DEBUG[4715] chan_misdn.c: misdn_hangup(mISDN/2-u0)