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

[Dec  4 01:04:26] VERBOSE[21177] logger.c:     -- Channel 0/2, span 1 got hangup request, cause 1
[Dec  4 01:04:26] DEBUG[25372] channel.c: Hanging up channel 'Zap/2-1'
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: dahdi_hangup(Zap/2-1)
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/2-1
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Hangup: channel: 2 index = 0, normal = 11, callwait = -1, thirdcall = -1
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: disabled echo cancellation on channel 2
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Updated conferencing on 2, with 0 conference users
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/2-1
[Dec  4 01:04:26] DEBUG[25372] chan_dahdi.c: disabled echo cancellation on channel 2
[Dec  4 01:04:26] VERBOSE[25372] logger.c:     -- Hungup 'Zap/2-1'
[Dec  4 01:04:26] VERBOSE[25372] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Dec  4 01:04:26] DEBUG[25372] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec  4 01:04:26] DEBUG[25372] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Dec  4 01:04:26] DEBUG[25372] app_macro.c: Executed application: Dial
[Dec  4 01:04:26] DEBUG[25372] pbx.c: Function result is 'SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)'
[Dec  4 01:04:26] DEBUG[25372] pbx.c: Launching 'Set'
[Dec  4 01:04:26] VERBOSE[25372] logger.c:     -- Executing [s@macro-to-pstn-4:4] Set("SIP/421220656110-b7d4b4d8", "CDR(userfield)=SIPURI=sip:421220656110@10.129.0.34;SIPUSERAGENT=SJphone/1.65.377a (SJ Labs);RC=1") in new stack
[Dec  4 01:04:26] DEBUG[25372] app_macro.c: Executed application: Set
[Dec  4 01:04:26] DEBUG[25372] pbx.c: Launching 'NoOp'
[Dec  4 01:04:26] VERBOSE[25372] logger.c:     -- Executing [s@macro-to-pstn-4:5] NoOp("SIP/421220656110-b7d4b4d8", "DIALSTATUS = CHANUNAVAIL") in new stack
[Dec  4 01:04:26] DEBUG[25372] app_macro.c: Executed application: NoOp
[Dec  4 01:04:26] DEBUG[25372] pbx.c: Launching 'Hangup'
[Dec  4 01:04:26] VERBOSE[25372] logger.c:     -- Executing [s@macro-to-pstn-4:6] Hangup("SIP/421220656110-b7d4b4d8", "") in new stack
[Dec  4 01:04:26] DEBUG[25372] app_macro.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-b7d4b4d8' in macro 'to-pstn-4'
[Dec  4 01:04:26] DEBUG[25372] pbx.c: Spawn extension (macro-to-pstn-4,s,6) exited non-zero on 'SIP/421220656110-b7d4b4d8'
[Dec  4 01:04:26] VERBOSE[25372] logger.c:   == Spawn extension (macro-to-pstn-4, s, 6) exited non-zero on 'SIP/421220656110-b7d4b4d8'
[Dec  4 01:04:26] DEBUG[25372] channel.c: Soft-Hanging up channel 'SIP/421220656110-b7d4b4d8'
[Dec  4 01:04:26] DEBUG[25372] channel.c: Hanging up channel 'SIP/421220656110-b7d4b4d8'
[Dec  4 01:04:26] DEBUG[25372] chan_sip.c: Hangup call SIP/421220656110-b7d4b4d8, SIP callid 4CE832E516D146448151238EFBCF84DB0x0a810022)
[Dec  4 01:04:26] DEBUG[21187] chan_sip.c: Stopping retransmission on '4CE832E516D146448151238EFBCF84DB0x0a810022' of Response 2: Match Found