May 23 21:56:58 DEBUG[4253] chan_sip.c: Checking SIP call limits for device 54
May 23 21:56:58 DEBUG[4253] chan_sip.c: build_route: Contact hop: <sip:54@10.19.25.51:6468>
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Macro("SIP/54-d8e9", "exten-vm|novm|56") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Macro("SIP/54-d8e9", "user-callerid") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing GotoIf("SIP/54-d8e9", "0?start") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Not taking any branch
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is '54'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "REALCALLERIDNUM=54") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing NoOp("SIP/54-d8e9", "REALCALLERIDNUM is 54") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is '54'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "AMPUSER=54") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is 'rodica'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "AMPUSERCIDNAME=rodica") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing GotoIf("SIP/54-d8e9", "0?report") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Not taking any branch
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "CALLERID(all)="rodica" <54>") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is '"rodica" <54>'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing NoOp("SIP/54-d8e9", "Using CallerID "rodica" <54>") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "FROMCONTEXT=exten-vm") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "VMBOX=novm") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "EXTTOCALL=56") in new stack
May 23 21:56:58 DEBUG[4432] db.c: Unable to find key '56' in family 'CFU'
May 23 21:56:58 DEBUG[4432] func_db.c: DB: CFU/56 not found in database.
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is ''
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "CFUEXT=") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:58 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:58 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is ''
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Set("SIP/54-d8e9", "RT=") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing Macro("SIP/54-d8e9", "record-enable|56|IN") in new stack
May 23 21:56:58 DEBUG[4432] pbx.c: Function result is '0'
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing GotoIf("SIP/54-d8e9", "0 > 0?2:4") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Goto (macro-record-enable,s,4)
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Executing AGI("SIP/54-d8e9", "recordingcheck|20060523-215658|1148435818.1") in new stack
May 23 21:56:58 VERBOSE[4432] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
May 23 21:56:59 VERBOSE[4432] logger.c:   recordingcheck|20060523-215658|1148435818.1: Inbound recording not enabled
May 23 21:56:59 VERBOSE[4432] logger.c:     -- AGI Script recordingcheck completed, returning 0
May 23 21:56:59 VERBOSE[4432] logger.c:     -- Executing NoOp("SIP/54-d8e9", "No recording needed") in new stack
May 23 21:56:59 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:56:59 VERBOSE[4432] logger.c:     -- Executing GotoIf("SIP/54-d8e9", "0?dolocaldial|1") in new stack
May 23 21:56:59 DEBUG[4432] pbx.c: Not taking any branch
May 23 21:56:59 VERBOSE[4432] logger.c:     -- Executing Macro("SIP/54-d8e9", "dial||tr|56") in new stack
May 23 21:56:59 VERBOSE[4432] logger.c:     -- Executing AGI("SIP/54-d8e9", "dialparties.agi") in new stack
May 23 21:56:59 VERBOSE[4432] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
May 23 21:57:00 VERBOSE[4432] logger.c:   dialparties.agi: Starting New Dialparties.agi
May 23 21:57:00 VERBOSE[4432] logger.c:     --  dialparties.agi: priority is 1
May 23 21:57:00 VERBOSE[4432] logger.c:   dialparties.agi: Caller ID name is 'rodica' number is '54'
May 23 21:57:00 VERBOSE[4432] logger.c:   dialparties.agi: Methodology of ring is  'none'
May 23 21:57:00 VERBOSE[4432] logger.c:     --  dialparties.agi: Added extension 56 to extension map
May 23 21:57:00 DEBUG[4432] db.c: Unable to find key '56' in family 'CF'
May 23 21:57:00 VERBOSE[4432] logger.c:     --  dialparties.agi: Extension 56 cf is disabled
May 23 21:57:00 DEBUG[4432] db.c: Unable to find key '56' in family 'DND'
May 23 21:57:00 VERBOSE[4432] logger.c:     --  dialparties.agi: Extension 56 do not disturb is disabled
May 23 21:57:00 DEBUG[4432] db.c: Unable to find key '56' in family 'CFB'
May 23 21:57:00 DEBUG[4432] db.c: Unable to find key '56' in family 'CFU'
May 23 21:57:00 VERBOSE[4432] logger.c:     --  dialparties.agi: DbSet CALLTRACE/56 to 54
May 23 21:57:00 VERBOSE[4432] logger.c:     -- AGI Script dialparties.agi completed, returning 0
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Executing Dial("SIP/54-d8e9", "SIP/56||tr") in new stack
May 23 21:57:00 NOTICE[4432] app_dial.c: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
May 23 21:57:00 VERBOSE[4432] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
May 23 21:57:00 DEBUG[4432] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
May 23 21:57:00 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:57:00 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:57:00 DEBUG[4432] pbx.c: Expression result is '0'
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Executing GosubIf("SIP/54-d8e9", "0?docfu|1") in new stack
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Executing NoOp("SIP/54-d8e9", "Voicemail is novm") in new stack
May 23 21:57:00 DEBUG[4432] pbx.c: Expression result is '1'
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Executing GotoIf("SIP/54-d8e9", "1?s-CHANUNAVAIL|1") in new stack
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Goto (macro-exten-vm,s-CHANUNAVAIL,1)
May 23 21:57:00 VERBOSE[4432] logger.c:     -- Executing Congestion("SIP/54-d8e9", "") in new stack
May 23 21:57:00 VERBOSE[4432] logger.c:   == Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 1) exited non-zero on 'SIP/54-d8e9' in macro 'exten-vm'
May 23 21:57:00 VERBOSE[4432] logger.c:   == Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 1) exited non-zero on 'SIP/54-d8e9'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '"rodica" <54>'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '54'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '56'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is 'from-internal'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is 'SIP/54-d8e9'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '(null)'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is 'Congestion'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '(null)'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '2006-05-23 21:56:58'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '(null)'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '2006-05-23 21:57:00'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '2'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '0'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is 'FAILED'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is 'DOCUMENTATION'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '(null)'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '1148435818.1'
May 23 21:57:00 DEBUG[4432] pbx.c: Function result is '(null)'
May 23 21:57:00 DEBUG[4253] chan_sip.c: Failed to grab lock, trying again...
May 23 21:57:00 DEBUG[4432] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 23 21:57:00 DEBUG[4432] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-05-23 21:56:58','\"rodica\" <54>','54','56','from-internal', 'SIP/54-d8e9','','Congestion','',2,0,'FAILED',3,'','1148435818.1')
May 23 21:57:00 DEBUG[4253] chan_sip.c: Failed to grab lock, trying again...
May 23 21:57:00 DEBUG[4432] chan_sip.c: update_call_counter(54) - decrement call limit counter
May 23 21:57:00 DEBUG[4253] chan_sip.c: Stopping retransmission on 'c71c5e67a01ac12d@cmVkd2Fy' of Response 2: Match Not Found