[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Setting NAT on RTP to On
[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Allocating new SIP dialog for 46FE5F33A05C464A88B6700BFC9AD4990xc0a80114 - INVITE (With RTP)
[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Setting NAT on RTP to On
[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Stopping retransmission on '46FE5F33A05C464A88B6700BFC9AD4990xc0a80114' of Response 1: Match Found
[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Setting NAT on RTP to On
[Jan 30 23:21:11] DEBUG[13436] chan_sip.c: Checking SIP call limits for device 421220656110
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'AGI'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:1] AGI("SIP/421220656110-09bdbac0", "from-customer.agi|c5") in new stack
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/from-customer.agi
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     --  from-customer.agi|c5: Maximalny pocet paralelnych hovorov je 4
[Jan 30 23:21:11] DEBUG[15442] db.c: Unable to find key '421220656110' in family 'CLIR'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- AGI Script from-customer.agi completed, returning 0
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Function result is 's421220656110'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Function result is '421220656110'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'NoOp'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:70] NoOp("SIP/421220656110-09bdbac0", "OK: s421220656110: 421220656110 -> 421650445566") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Function result is 's421220656110'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'Set'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:71] Set("SIP/421220656110-09bdbac0", "GROUP()=s421220656110") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Function result is 's421220656110'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Function result is '1'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Expression result is '0'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'GotoIf'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:72] GotoIf("SIP/421220656110-09bdbac0", "0?limit") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Not taking any branch
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'Set'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:73] Set("SIP/421220656110-09bdbac0", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'Goto'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [0650445566@from-c5:74] Goto("SIP/421220656110-09bdbac0", "from-c5-routing|421650445566|1") in new stack
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Goto (from-c5-routing,421650445566,1)
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'Macro'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [421650445566@from-c5-routing:1] Macro("SIP/421220656110-09bdbac0", "to-pstn-4|421650445566") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Expression result is '0'
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'GotoIf'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:1] GotoIf("SIP/421220656110-09bdbac0", "0?clir") in new stack
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Not taking any branch
[Jan 30 23:21:11] DEBUG[15442] app_macro.c: Executed application: GotoIf
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'SetCallerPres'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:2] SetCallerPres("SIP/421220656110-09bdbac0", "allowed") in new stack
[Jan 30 23:21:11] DEBUG[15442] app_macro.c: Executed application: SetCallerPres
[Jan 30 23:21:11] DEBUG[15442] pbx.c: Launching 'Dial'
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:3] Dial("SIP/421220656110-09bdbac0", "Zap/g4/421650445566") in new stack
[Jan 30 23:21:11] NOTICE[15442] app_dial.c: Hey! chan SIP/421220656110-09bdbac0's context='macro-to-pstn-4', and exten='s'
[Jan 30 23:21:11] DEBUG[15442] chan_dahdi.c: Using channel 3
[Jan 30 23:21:11] DEBUG[15442] rtp.c: Channel 'Zap/3-1' has no RTP, not doing anything
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable MACRO_DEPTH.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable ARG1.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable MACRO_PRIORITY.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable MACRO_CONTEXT.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable MACRO_EXTEN.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable AGISTATUS.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable LIMIT.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable PEER.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable RETURN_STATUS.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable NEW_EXTEN.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable SIPCALLID.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable SIPUSERAGENT.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable SIPDOMAIN.
[Jan 30 23:21:11] DEBUG[15442] channel.c: Not copying variable SIPURI.
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Requested transfer capability: 0x00 - SPEECH
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Called g4/421650445566
[Jan 30 23:21:11] DEBUG[13157] chan_dahdi.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/3 span 1
[Jan 30 23:21:11] VERBOSE[15442] logger.c:     -- Zap/3-1 is proceeding passing it to SIP/421220656110-09bdbac0
[Jan 30 23:21:11] DEBUG[15442] rtp.c: Channel 'Zap/3-1' has no RTP, not doing anything
[Jan 30 23:21:11] DEBUG[15442] chan_sip.c: Setting framing from config on incoming call
[Jan 30 23:21:11] DEBUG[15442] rtp.c: Ooh, format changed from unknown to alaw
[Jan 30 23:21:11] DEBUG[15442] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jan 30 23:21:11] DEBUG[15442] rtp.c: RTP NAT: Got audio from other end. Now sending to address 195.168.29.2:61384
[Jan 30 23:21:13] VERBOSE[13157] logger.c:     -- Channel 0/3, span 1 got hangup request, cause 3
[Jan 30 23:21:13] DEBUG[15442] channel.c: Hanging up channel 'Zap/3-1'
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: dahdi_hangup(Zap/3-1)
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/3-1
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Hangup: channel: 3 index = 0, normal = 13, callwait = -1, thirdcall = -1
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Not yet hungup...  Calling hangup once with icause=3, and clearing call
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: disabled echo cancellation on channel 3
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on Zap/3-1
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Updated conferencing on 3, with 0 conference users
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/3-1
[Jan 30 23:21:13] DEBUG[15442] chan_dahdi.c: disabled echo cancellation on channel 3
[Jan 30 23:21:13] VERBOSE[15442] logger.c:     -- Hungup 'Zap/3-1'
[Jan 30 23:21:13] VERBOSE[15442] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jan 30 23:21:13] DEBUG[15442] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jan 30 23:21:13] DEBUG[15442] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jan 30 23:21:13] DEBUG[15442] app_macro.c: Executed application: Dial
[Jan 30 23:21:13] DEBUG[15442] pbx.c: Function result is 'SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)'
[Jan 30 23:21:13] DEBUG[15442] pbx.c: Launching 'Set'
[Jan 30 23:21:13] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:4] Set("SIP/421220656110-09bdbac0", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=3") in new stack
[Jan 30 23:21:13] DEBUG[15442] app_macro.c: Executed application: Set
[Jan 30 23:21:13] DEBUG[15442] pbx.c: Launching 'NoOp'
[Jan 30 23:21:13] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:5] NoOp("SIP/421220656110-09bdbac0", "DIALSTATUS = CHANUNAVAIL") in new stack
[Jan 30 23:21:13] DEBUG[15442] app_macro.c: Executed application: NoOp
[Jan 30 23:21:13] DEBUG[15442] pbx.c: Launching 'Hangup'
[Jan 30 23:21:13] VERBOSE[15442] logger.c:     -- Executing [s@macro-to-pstn-4:6] Hangup("SIP/421220656110-09bdbac0", "") in new stack
[Jan 30 23:21:13] DEBUG[15442] app_macro.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-09bdbac0' in macro 'to-pstn-4'
[Jan 30 23:21:13] DEBUG[15442] pbx.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-09bdbac0'
[Jan 30 23:21:13] VERBOSE[15442] logger.c:   == Spawn extension (macro-to-pstn-4, s, 6) exited non-zero on 'SIP/421220656110-09bdbac0'
[Jan 30 23:21:13] DEBUG[15442] channel.c: Soft-Hanging up channel 'SIP/421220656110-09bdbac0'
[Jan 30 23:21:13] DEBUG[15442] channel.c: Hanging up channel 'SIP/421220656110-09bdbac0'
[Jan 30 23:21:13] DEBUG[15442] chan_sip.c: Hangup call SIP/421220656110-09bdbac0, SIP callid 46FE5F33A05C464A88B6700BFC9AD4990xc0a80114)
[Jan 30 23:21:13] DEBUG[15442] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 30 23:21:13] DEBUG[15442] 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,userfield) VALUES ('2009-01-30 23:21:11','\"421220656110\" <421220656110>','421220656110','421650445566','from-c5-routing', 'SIP/421220656110-09bdbac0','Zap/3-1','Hangup','',2,0,'FAILED',3,'s421220656110','SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=3')