Onderwerp: CID werkt niet

Oorspronkelijk geplaatst door TomB

yep, binnenbellen werkt zonder problemen ... dus is wel degelijk correct geinstalleerd, verschijnt enkel niet in men Asterisk/freepbx als trunk.

Kun je misschien de logging laten zien van het binnenkomende gesprek? Ik vermoed namelijk dat het nummer op de ISDN bundel is afgemonteerd en dus op de 1e 2 lijnen aangeboden wordt. Ik zal even kijken of ik bij de configuratie van een klant van mij met 4 lijnen kan, even zien hoe ik het met een standaard Asterisk heb opgelost.

Een tijdje terug heb ik een B410p met 4 lijnen opgeleverd in een FreePBX setup dus het zou wel moeten werken.

-- dialparties.agi: Extension 60 cf is disabled
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '61' in family 'DND'
-- dialparties.agi: Extension 61 do not disturb is disabled
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '60' in family 'DND'
-- dialparties.agi: Extension 60 do not disturb is disabled
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '61' in family 'CFB'
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '61' in family 'CFU'
> dialparties.agi: extnum 61 has: cw: 1; hascfb: 0 [] hascfu: 0 []
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '60' in family 'CFB'
May 21 11:30:50 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '60' in family 'CFU'
> dialparties.agi: extnum 60 has: cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: Filtered ARG3: 61-60
> dialparties.agi: NODEST: 603 adding M(auto-blkvm) to dialopts: trM(auto-blkvm)
> dialparties.agi: NODEST: 603 blkvm enabled macro already in dialopts: trM(auto-blkvm)
May 21 11:30:50 DEBUG[23710]: manager.c:1257 process_message: Manager received command 'Logoff'
== Manager 'admin' logged off from 127.0.0.1
-- AGI Script dialparties.agi completed, returning 0
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: AGI
-- Executing NoOp("mISDN/3-1", "Returned from dialparties with hunt groups to dial ") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: NoOp
-- Executing Set("mISDN/3-1", "HuntLoop=0") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a30") in new stack
-- Goto (macro-dial,s,26)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing Set("mISDN/3-1", "HuntMember=HuntMember0") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a32:a35") in new stack
-- Goto (macro-dial,s,28)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '61'
-- Executing Set("mISDN/3-1", "CT_EXTEN=61") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Set("mISDN/3-1", "DB(CALLTRACE/61)=00478781981") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Goto("mISDN/3-1", "s|a42") in new stack
-- Goto (macro-dial,s,38)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Goto
-- Executing Dial("mISDN/3-1", "SIP/61|15|trM(auto-blkvm)") in new stack
May 21 11:30:50 DEBUG[23706]: chan_sip.c:1889 create_addr_from_peer: Setting NAT on RTP to 524288
May 21 11:30:50 DEBUG[23706]: chan_sip.c:2085 sip_call: Outgoing Call for 61
-- Called 61
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '48ba87ea7a7c16d03018a9420992b281@192.168.1.55' Request 102: Found
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1392 __sip_ack: Acked pending invite 102
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '48ba87ea7a7c16d03018a9420992b281@192.168.1.55' of Request 102: Match Found
-- Got SIP response 486 "Busy Here" back from 192.168.1.157
-- SIP/61-096e4b38 is busy
May 21 11:30:50 DEBUG[23706]: chan_sip.c:2450 sip_hangup: update_call_counter(61) - decrement call limit counter
== Everyone is busy/congested at this time (1:1/0/0)
May 21 11:30:50 DEBUG[23706]: app_dial.c:1661 dial_exec_full: Exiting with DIALSTATUS=BUSY.
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Dial
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing Set("mISDN/3-1", "HuntLoop=1") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a46") in new stack
-- Goto (macro-dial,s,42)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing Set("mISDN/3-1", "HuntMembers=1") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Goto("mISDN/3-1", "s|a22") in new stack
-- Goto (macro-dial,s,22)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Goto
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a30") in new stack
-- Goto (macro-dial,s,26)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing Set("mISDN/3-1", "HuntMember=HuntMember1") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a32:a35") in new stack
-- Goto (macro-dial,s,28)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:30:50 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '2'
May 21 11:30:50 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '60'
-- Executing Set("mISDN/3-1", "CT_EXTEN=60") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Set("mISDN/3-1", "DB(CALLTRACE/60)=00478781981") in new stack
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Goto("mISDN/3-1", "s|a42") in new stack
-- Goto (macro-dial,s,38)
May 21 11:30:50 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Goto
-- Executing Dial("mISDN/3-1", "SIP/60|15|trM(auto-blkvm)") in new stack
May 21 11:30:50 DEBUG[23706]: chan_sip.c:1889 create_addr_from_peer: Setting NAT on RTP to 524288
May 21 11:30:50 DEBUG[23706]: chan_sip.c:2085 sip_call: Outgoing Call for 60
-- Called 60
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '27005a736c82ff1e6d4dd93150806136@192.168.1.55' Request 102: Found
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '3aad92676540e297306167341c67a219@192.168.1.55' of Request 102: Match Found
May 21 11:30:50 DEBUG[4465]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '27005a736c82ff1e6d4dd93150806136@192.168.1.55' Request 102: Found
-- SIP/60-096f3d58 is ringing
May 21 11:30:56 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '19d876d45949649b2605f3212c8eebb0@192.168.1.55' of Request 102: Match Found
May 21 11:30:56 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '056c51863d4abac57d06bd0e6604963e@192.168.1.55' of Request 102: Match Found
May 21 11:30:58 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '4dffd2793aaddbd77db8ef68572f614f@192.168.1.55' of Request 102: Match Found
May 21 11:30:58 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '1b4d68131aefc09f0a4610ab27aa035c@192.168.1.55' of Request 102: Match Found
-- Nobody picked up in 15000 ms
May 21 11:31:05 DEBUG[23706]: chan_sip.c:2450 sip_hangup: update_call_counter(60) - decrement call limit counter
May 21 11:31:05 DEBUG[23706]: chan_sip.c:1392 __sip_ack: Acked pending invite 102
May 21 11:31:05 DEBUG[23706]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '27005a736c82ff1e6d4dd93150806136@192.168.1.55' of Request 102: Match Found
May 21 11:31:05 DEBUG[23706]: app_dial.c:1661 dial_exec_full: Exiting with DIALSTATUS=NOANSWER.
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Dial
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '2'
-- Executing Set("mISDN/3-1", "HuntLoop=2") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?a46") in new stack
-- Goto (macro-dial,s,42)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing Set("mISDN/3-1", "HuntMembers=0") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
-- Executing Goto("mISDN/3-1", "s|a22") in new stack
-- Goto (macro-dial,s,22)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Goto
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("mISDN/3-1", "0?a30") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:6204 pbx_builtin_gotoif: Not taking any branch
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing NoOp("mISDN/3-1", "Returning there are no members left in the hunt group to ring") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: NoOp
-- Executing Set("mISDN/3-1", "RingGroupMethod=") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("mISDN/3-1", "0?nodest") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:6204 pbx_builtin_gotoif: Not taking any branch
-- Executing Set("mISDN/3-1", "__NODEST=") in new stack
-- Executing DBdel("mISDN/3-1", "BLKVM/603/mISDN/3-1") in new stack
-- DBdel: family=BLKVM, key=603/mISDN/3-1
-- Executing Goto("mISDN/3-1", "ext-local|vmb61|1") in new stack
-- Goto (ext-local,vmb61,1)
-- Executing Macro("mISDN/3-1", "vm|61|BUSY") in new stack
-- Executing Macro("mISDN/3-1", "user-callerid|SKIPTTL") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '64000599 - Briers'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '00478781981'
-- Executing NoOp("mISDN/3-1", "user-callerid: 64000599 - Briers 00478781981") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Noop
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '00478781981'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '00478781981'
-- Executing Set("mISDN/3-1", "AMPUSER=00478781981") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("mISDN/3-1", "0?report") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:6204 pbx_builtin_gotoif: Not taking any branch
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '00478781981'
-- Executing ExecIf("mISDN/3-1", "0|Set|REALCALLERIDNUM=00478781981") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: ExecIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '00478781981'
-- Executing NoOp("mISDN/3-1", "REALCALLERIDNUM is 00478781981") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Noop
May 21 11:31:05 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '00478781981/user' in family 'DEVICE'
May 21 11:31:05 DEBUG[23706]: func_db.c:69 function_db_read: DB: DEVICE/00478781981/user not found in database.
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
-- Executing Set("mISDN/3-1", "AMPUSER=") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER'
May 21 11:31:05 DEBUG[23706]: func_db.c:69 function_db_read: DB: AMPUSER//cidname not found in database.
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
-- Executing Set("mISDN/3-1", "AMPUSERCIDNAME=") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?report") in new stack
-- Goto (macro-user-callerid,s,13)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing NoOp("mISDN/3-1", "TTL: 64 ARG1: SKIPTTL") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Noop
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?continue") in new stack
-- Goto (macro-user-callerid,s,23)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '"64000599 - Briers" <00478781981>'
-- Executing NoOp("mISDN/3-1", "Using CallerID "64000599 - Briers" <00478781981>") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Noop
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Macro
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
-- Executing Set("mISDN/3-1", "VMGAIN=") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '603/mISDN/3-1' in family 'BLKVM'
May 21 11:31:05 DEBUG[23706]: func_db.c:69 function_db_read: DB: BLKVM/603/mISDN/3-1 not found in database.
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?vmx|1") in new stack
-- Goto (macro-vm,vmx,1)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("mISDN/3-1", "0?s-BUSY|1") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:6204 pbx_builtin_gotoif: Not taking any branch
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'busy'
-- Executing Set("mISDN/3-1", "MODE=busy") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?notdirect") in new stack
-- Goto (macro-vm,vmx,5)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
May 21 11:31:05 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '61/vmx/busy/state' in family 'AMPUSER'
May 21 11:31:05 DEBUG[23706]: func_db.c:69 function_db_read: DB: AMPUSER/61/vmx/busy/state not found in database.
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
-- Executing NoOp("mISDN/3-1", "Checking if ext 61 is enabled: ") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Noop
May 21 11:31:05 DEBUG[23706]: db.c:200 ast_db_get: Unable to find key '61/vmx/busy/state' in family 'AMPUSER'
May 21 11:31:05 DEBUG[23706]: func_db.c:69 function_db_read: DB: AMPUSER/61/vmx/busy/state not found in database.
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is ''
May 21 11:31:05 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '27005a736c82ff1e6d4dd93150806136@192.168.1.55' of Request 102: Match Not Found
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '1'
-- Executing GotoIf("mISDN/3-1", "1?s-BUSY|1") in new stack
-- Goto (macro-vm,s-BUSY,1)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing NoOp("mISDN/3-1", "BUSY voicemail") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: NoOp
-- Executing Macro("mISDN/3-1", "get-vmcontext|61") in new stack
May 21 11:31:05 DEBUG[23706]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'default'
-- Executing Set("mISDN/3-1", "VMCONTEXT=default") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Set
May 21 11:31:05 DEBUG[23706]: pbx.c:1609 pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("mISDN/3-1", "0?200:300") in new stack
-- Goto (macro-get-vmcontext,s,300)
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: GotoIf
-- Executing NoOp("mISDN/3-1", "") in new stack
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: NoOp
May 21 11:31:05 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '27005a736c82ff1e6d4dd93150806136@192.168.1.55' of Request 102: Match Found
May 21 11:31:05 DEBUG[23706]: app_macro.c:326 macro_exec: Executed application: Macro
-- Executing VoiceMail("mISDN/3-1", "61@default|b") in new stack
May 21 11:31:05 DEBUG[4449]: channel.c:775 channel_find_locked: Avoiding initial deadlock for 'mISDN/3-1'
May 21 11:31:05 DEBUG[23706]: app_voicemail.c:2526 leave_voicemail: /var/spool/asterisk/voicemail/default/61/busy doesn't exist, doing what we can
-- Playing 'vm-theperson' (language 'en')
May 21 11:31:07 DEBUG[27707]: manager.c:1257 process_message: Manager received command 'Ping'
May 21 11:31:07 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '28070a4101506edc275661fd53e54dad@192.168.1.55' of Request 102: Match Found
May 21 11:31:07 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '5f6f43921cb9fe5719c0bb667fc551a4@192.168.1.55' of Request 102: Match Found
May 21 11:31:07 WARNING[23706]: file.c:592 ast_readaudio_callback: Failed to write frame
May 21 11:31:07 DEBUG[23706]: app_voicemail.c:2531 leave_voicemail: Hang up during prefile playback
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'mISDN/3-1' in macro 'vm'
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'mISDN/3-1'
May 21 11:31:07 DEBUG[23706]: chan_misdn.c:2237 misdn_hangup: misdn_hangup(mISDN/3-1)
May 21 11:31:07 DEBUG[23706]: cdr_addon_mysql.c:212 mysql_log: cdr_mysql: inserting a CDR record.
May 21 11:31:07 DEBUG[23706]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel ,lastapp,lastdata,duration,billsec,disposition,ama flags,accountcode) VALUES ('2008-05-21 11:30:50','\"64000599 - Briers\" <00478781981>','00478781981','vmb61','ext-local', 'mISDN/3-1','SIP/60-096f3d58','VoiceMail','61@default|b',17,2,'ANSWERE D',3,'')
May 21 11:31:08 DEBUG[1284]: manager.c:1257 process_message: Manager received command 'Ping'
May 21 11:31:09 DEBUG[4465]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '4f9169bd49064fac575191c40c9d2e50@192.168.1.55' of Request 102: Match Found
May 21 11:31:11 DEBUG[12863]: manager.c:1257 process_message: Manager received command 'Ping'