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