[Dec  4 01:04:31] DEBUG[21187] chan_sip.c: Allocating new SIP dialog for E28E152D824044C7981DEF9FBF3EB6860x0a810022 - INVITE (With RTP)
[Dec  4 01:04:31] DEBUG[21187] chan_sip.c: Setting NAT on RTP to On
[Dec  4 01:04:31] DEBUG[21187] chan_sip.c: Stopping retransmission on 'E28E152D824044C7981DEF9FBF3EB6860x0a810022' of Response 1: Match Found
[Dec  4 01:04:31] DEBUG[21187] chan_sip.c: Setting NAT on RTP to On
[Dec  4 01:04:31] DEBUG[21187] chan_sip.c: Checking SIP call limits for device 421220656110
[Dec  4 01:04:31] DEBUG[25376] pbx.c: Launching 'AGI'
[Dec  4 01:04:31] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:1] AGI("SIP/421220656110-b7d3a420", "from-customer.agi|c5") in new stack
[Dec  4 01:04:31] VERBOSE[25376] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/from-customer.agi
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     --  from-customer.agi|c5: Maximalny pocet paralelnych hovorov je 4
[Dec  4 01:04:32] VERBOSE[25376] logger.c:   from-customer.agi|c5: CLI OK, preslo kontrolou v DB
[Dec  4 01:04:32] DEBUG[25376] db.c: Unable to find key '421220656110' in family 'CLIR'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- AGI Script from-customer.agi completed, returning 0
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Function result is 's421220656110'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Function result is '421220656110'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'NoOp'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:60] NoOp("SIP/421220656110-b7d3a420", "OK: s421220656110: 421220656110 -> 421650445566") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Function result is 's421220656110'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'Set'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:61] Set("SIP/421220656110-b7d3a420", "GROUP()=s421220656110") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Function result is 's421220656110'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Function result is '1'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Expression result is '0'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'GotoIf'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:62] GotoIf("SIP/421220656110-b7d3a420", "0?limit") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Not taking any branch
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'Set'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:63] Set("SIP/421220656110-b7d3a420", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'Goto'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [0650445566@from-c5:64] Goto("SIP/421220656110-b7d3a420", "from-c5-routing|421650445566|1") in new stack
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Goto (from-c5-routing,421650445566,1)
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'Macro'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [421650445566@from-c5-routing:1] Macro("SIP/421220656110-b7d3a420", "to-pstn-4|421650445566") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Expression result is '0'
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'GotoIf'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:1] GotoIf("SIP/421220656110-b7d3a420", "0?clir") in new stack
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Not taking any branch
[Dec  4 01:04:32] DEBUG[25376] app_macro.c: Executed application: GotoIf
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'SetCallerPres'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:2] SetCallerPres("SIP/421220656110-b7d3a420", "allowed") in new stack
[Dec  4 01:04:32] DEBUG[25376] app_macro.c: Executed application: SetCallerPres
[Dec  4 01:04:32] DEBUG[25376] pbx.c: Launching 'Dial'
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:3] Dial("SIP/421220656110-b7d3a420", "Zap/g4/421650445566") in new stack
[Dec  4 01:04:32] DEBUG[25376] chan_dahdi.c: Using channel 2
[Dec  4 01:04:32] DEBUG[25376] rtp.c: Channel 'Zap/2-1' has no RTP, not doing anything
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable MACRO_DEPTH.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable ARG1.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable MACRO_PRIORITY.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable MACRO_CONTEXT.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable MACRO_EXTEN.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable AGISTATUS.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable LIMIT.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable PEER.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable RETURN_STATUS.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable NEW_EXTEN.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable SIPCALLID.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable SIPUSERAGENT.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable SIPDOMAIN.
[Dec  4 01:04:32] DEBUG[25376] channel.c: Not copying variable SIPURI.
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Requested transfer capability: 0x00 - SPEECH
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Called g4/421650445566
[Dec  4 01:04:32] DEBUG[21177] chan_dahdi.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/2 span 1
[Dec  4 01:04:32] VERBOSE[25376] logger.c:     -- Zap/2-1 is proceeding passing it to SIP/421220656110-b7d3a420
[Dec  4 01:04:32] DEBUG[25376] rtp.c: Channel 'Zap/2-1' has no RTP, not doing anything
[Dec  4 01:04:32] DEBUG[25376] chan_sip.c: Setting framing from config on incoming call
[Dec  4 01:04:32] DEBUG[25376] rtp.c: Ooh, format changed from unknown to alaw
[Dec  4 01:04:32] DEBUG[25376] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Dec  4 01:04:32] DEBUG[25376] rtp.c: RTP NAT: Got audio from other end. Now sending to address 195.168.29.2:64317

[Dec  4 01:04:33] VERBOSE[21177] logger.c:     -- Channel 0/2, span 1 got hangup request, cause 3
[Dec  4 01:04:33] DEBUG[25376] channel.c: Hanging up channel 'Zap/2-1'
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: dahdi_hangup(Zap/2-1)
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/2-1
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Hangup: channel: 2 index = 0, normal = 11, callwait = -1, thirdcall = -1
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: disabled echo cancellation on channel 2
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Updated conferencing on 2, with 0 conference users
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/2-1
[Dec  4 01:04:33] DEBUG[25376] chan_dahdi.c: disabled echo cancellation on channel 2
[Dec  4 01:04:33] VERBOSE[25376] logger.c:     -- Hungup 'Zap/2-1'
[Dec  4 01:04:33] VERBOSE[25376] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Dec  4 01:04:33] DEBUG[25376] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec  4 01:04:33] DEBUG[25376] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Dec  4 01:04:33] DEBUG[25376] app_macro.c: Executed application: Dial
[Dec  4 01:04:33] DEBUG[25376] pbx.c: Function result is 'SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)'
[Dec  4 01:04:33] DEBUG[25376] pbx.c: Launching 'Set'
[Dec  4 01:04:33] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:4] Set("SIP/421220656110-b7d3a420", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=3") in new stack
[Dec  4 01:04:33] DEBUG[25376] app_macro.c: Executed application: Set
[Dec  4 01:04:33] DEBUG[25376] pbx.c: Launching 'NoOp'
[Dec  4 01:04:33] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:5] NoOp("SIP/421220656110-b7d3a420", "DIALSTATUS = CHANUNAVAIL") in new stack
[Dec  4 01:04:33] DEBUG[25376] app_macro.c: Executed application: NoOp
[Dec  4 01:04:33] DEBUG[25376] pbx.c: Launching 'Hangup'
[Dec  4 01:04:33] VERBOSE[25376] logger.c:     -- Executing [s@macro-to-pstn-4:6] Hangup("SIP/421220656110-b7d3a420", "") in new stack
[Dec  4 01:04:33] DEBUG[25376] app_macro.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-b7d3a420' in macro 'to-pstn-4'
[Dec  4 01:04:33] DEBUG[25376] pbx.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-b7d3a420'
[Dec  4 01:04:33] VERBOSE[25376] logger.c:   == Spawn extension (macro-to-pstn-4, s, 6) exited non-zero on 'SIP/421220656110-b7d3a420'
[Dec  4 01:04:33] DEBUG[25376] channel.c: Soft-Hanging up channel 'SIP/421220656110-b7d3a420'
[Dec  4 01:04:33] DEBUG[25376] channel.c: Hanging up channel 'SIP/421220656110-b7d3a420'
[Dec  4 01:04:33] DEBUG[25376] chan_sip.c: Hangup call SIP/421220656110-b7d3a420, SIP callid E28E152D824044C7981DEF9FBF3EB6860x0a810022)
[Dec  4 01:04:33] DEBUG[25376] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Dec  4 01:04:33] DEBUG[25376] 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 ('2008-12-04 01:04:31','\"unknown\" <421220656110>','421220656110','421650445566','from-c5-routing', 'SIP/421220656110-b7d3a420','Zap/2-1','Hangup','',2,0,'FAILED',3,'s421220656110','SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=3')