[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Setting NAT on RTP to On
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Allocating new SIP dialog for 41629D3D6C5B441994BA78E7E2DFFB1C0xc0a80114 - INVITE (With RTP)
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Setting NAT on RTP to On
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Stopping retransmission on '41629D3D6C5B441994BA78E7E2DFFB1C0xc0a80114' of Response 1: Match Found
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Setting NAT on RTP to On
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: T38 state changed to 0 on channel <none>
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Checking SIP call limits for device 421220656110
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: Updating call counter for incoming call
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: *** Our native formats are 0x8 (alaw) 
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: *** Joint capabilities are 0xe (gsm|ulaw|alaw) 
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: *** Our capabilities are 0x8010f (g723|gsm|ulaw|alaw|g729|h263) 
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: This channel will not be able to handle video.
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: build_route: Contact hop: <sip:421220656110@10.129.0.34>
[Jan 31 22:40:52] DEBUG[6079] chan_sip.c: SIP/421220656110-0a2ebed8: New call is still down.... Trying... 
[Jan 31 22:40:52] DEBUG[6079] devicestate.c: Notification of state change to be queued on device/channel SIP/421220656110
[Jan 31 22:40:52] DEBUG[5806] chan_sip.c: Checking device state for peer 421220656110
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'AGI'
[Jan 31 22:40:52] DEBUG[5806] devicestate.c: Changing state for SIP/421220656110 - state 1 (Not in use)
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:1] AGI("SIP/421220656110-0a2ebed8", "from-customer.agi|c5") in new stack
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/from-customer.agi
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     --  from-customer.agi|c5: Maximalny pocet paralelnych hovorov je 4
[Jan 31 22:40:52] DEBUG[13324] db.c: Unable to find key '421220656110' in family 'CLIR'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- AGI Script from-customer.agi completed, returning 0
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is 's421220656110'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is '421220656110'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'NoOp'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:70] NoOp("SIP/421220656110-0a2ebed8", "OK: s421220656110: 421220656110 -> 421232000000") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is 's421220656110'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Set'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:71] Set("SIP/421220656110-0a2ebed8", "GROUP()=s421220656110") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is 's421220656110'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is '1'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Expression result is '0'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'GotoIf'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:72] GotoIf("SIP/421220656110-0a2ebed8", "0?limit") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Not taking any branch
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Set'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:73] Set("SIP/421220656110-0a2ebed8", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Goto'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [0232000000@from-c5:74] Goto("SIP/421220656110-0a2ebed8", "from-c5-routing|421232000000|1") in new stack
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Goto (from-c5-routing,421232000000,1)
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Macro'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [421232000000@from-c5-routing:1] Macro("SIP/421220656110-0a2ebed8", "to-pstn-4|421232000000") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Expression result is '0'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'GotoIf'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:1] GotoIf("SIP/421220656110-0a2ebed8", "0?clir") in new stack
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Not taking any branch
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Executed application: GotoIf
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'SetCallerPres'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:2] SetCallerPres("SIP/421220656110-0a2ebed8", "allowed") in new stack
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Executed application: SetCallerPres
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Dial'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:3] Dial("SIP/421220656110-0a2ebed8", "Zap/g4/421232000000") in new stack
[Jan 31 22:40:52] NOTICE[13324] app_dial.c: Hey! chan SIP/421220656110-0a2ebed8's context='macro-to-pstn-4', and exten='s'
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Using channel 2
[Jan 31 22:40:52] DEBUG[13324] rtp.c: Channel 'Zap/2-1' has no RTP, not doing anything
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable MACRO_DEPTH.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable ARG1.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable MACRO_PRIORITY.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable MACRO_CONTEXT.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable MACRO_EXTEN.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable AGISTATUS.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable LIMIT.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable PEER.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable RETURN_STATUS.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable NEW_EXTEN.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable SIPCALLID.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable SIPUSERAGENT.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable SIPDOMAIN.
[Jan 31 22:40:52] DEBUG[13324] channel.c: Not copying variable SIPURI.
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Requested transfer capability: 0x00 - SPEECH
[Jan 31 22:40:52] DEBUG[13324] devicestate.c: Notification of state change to be queued on device/channel Zap/2
[Jan 31 22:40:52] DEBUG[5806] devicestate.c: Changing state for Zap/2 - state 2 (In use)
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Called g4/421232000000
[Jan 31 22:40:52] DEBUG[5812] chan_dahdi.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/2 span 1
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Zap/2-1 is proceeding passing it to SIP/421220656110-0a2ebed8
[Jan 31 22:40:52] DEBUG[13324] rtp.c: Channel 'Zap/2-1' has no RTP, not doing anything
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: Setting framing from config on incoming call
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: -- Done with adding codecs to SDP
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Jan 31 22:40:52] DEBUG[13324] rtp.c: Ooh, format changed from unknown to alaw
[Jan 31 22:40:52] DEBUG[13324] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jan 31 22:40:52] DEBUG[13324] rtp.c: RTP NAT: Got audio from other end. Now sending to address 195.168.29.2:63961
[Jan 31 22:40:52] VERBOSE[5812] logger.c:     -- Channel 0/2, span 1 got hangup request, cause 1
[Jan 31 22:40:52] DEBUG[13324] channel.c: Hanging up channel 'Zap/2-1'
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: dahdi_hangup(Zap/2-1)
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/2-1
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Hangup: channel: 2 index = 0, normal = 12, callwait = -1, thirdcall = -1
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Not yet hungup...  Calling hangup once with icause=1, and clearing call
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: disabled echo cancellation on channel 2
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Updated conferencing on 2, with 0 conference users
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/2-1
[Jan 31 22:40:52] DEBUG[13324] chan_dahdi.c: disabled echo cancellation on channel 2
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Hungup 'Zap/2-1'
[Jan 31 22:40:52] DEBUG[13324] devicestate.c: Notification of state change to be queued on device/channel Zap/2
[Jan 31 22:40:52] DEBUG[5806] devicestate.c: Changing state for Zap/2 - state 0 (Unknown)
[Jan 31 22:40:52] VERBOSE[13324] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jan 31 22:40:52] NOTICE[13324] app_dial.c: Prevent Peer dup: outgoing 0xa28b8f8 chan (nil)
[Jan 31 22:40:52] DEBUG[13324] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jan 31 22:40:52] DEBUG[13324] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Executed application: Dial
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Function result is 'SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Set'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:4] Set("SIP/421220656110-0a2ebed8", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=1") in new stack
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Executed application: Set
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'NoOp'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:5] NoOp("SIP/421220656110-0a2ebed8", "DIALSTATUS = CHANUNAVAIL") in new stack
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Executed application: NoOp
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Launching 'Hangup'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:     -- Executing [s@macro-to-pstn-4:6] Hangup("SIP/421220656110-0a2ebed8", "") in new stack
[Jan 31 22:40:52] DEBUG[13324] app_macro.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-0a2ebed8' in macro 'to-pstn-4'
[Jan 31 22:40:52] DEBUG[13324] pbx.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-0a2ebed8'
[Jan 31 22:40:52] VERBOSE[13324] logger.c:   == Spawn extension (macro-to-pstn-4, s, 6) exited non-zero on 'SIP/421220656110-0a2ebed8'
[Jan 31 22:40:52] DEBUG[13324] channel.c: Soft-Hanging up channel 'SIP/421220656110-0a2ebed8'
[Jan 31 22:40:52] DEBUG[13324] channel.c: Hanging up channel 'SIP/421220656110-0a2ebed8'
[Jan 31 22:40:52] DEBUG[13324] chan_sip.c: Hangup call SIP/421220656110-0a2ebed8, SIP callid 41629D3D6C5B441994BA78E7E2DFFB1C0xc0a80114)
[Jan 31 22:40:52] DEBUG[13324] devicestate.c: Notification of state change to be queued on device/channel SIP/421220656110
[Jan 31 22:40:52] DEBUG[5806] chan_sip.c: Checking device state for peer 421220656110
[Jan 31 22:40:52] DEBUG[5806] devicestate.c: Changing state for SIP/421220656110 - state 1 (Not in use)