[Apr 15 00:02:34] DEBUG[8816] pbx.c: Launching 'Answer'
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- Executing [s-DIAL@macro-dialone:10] Answer("Zap/31-1", "") in new stack
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- Executing [s-DIAL@macro-dialone:11] Set("Zap/31-1", "_EXITCONTEXT=callback") in new stack
[Apr 15 00:02:34] DEBUG[8816] app_macro.c: Executed application: Set
[Apr 15 00:02:34] DEBUG[8816] pbx.c: Launching 'Set'
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- Executing [s-DIAL@macro-dialone:12] Set("Zap/31-1", "orig_exten=236") in new stack
[Apr 15 00:02:34] DEBUG[8816] app_macro.c: Executed application: Set
[Apr 15 00:02:34] DEBUG[8816] pbx.c: Launching 'Dial'
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- Executing [s-DIAL@macro-dialone:13] Dial("Zap/31-1", "SIP/236|30|dtT") in new stack
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Setting NAT on RTP to On
[Apr 15 00:02:34] DEBUG[8816] acl.c: ##### Testing 10.10.5.1 with 10.10.0.0
[Apr 15 00:02:34] DEBUG[8816] rtp.c: Channel 'Zap/31-1' has no RTP, not doing anything
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable MACRO_DEPTH.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable orig_exten.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Copying soft-transferable variable EXITCONTEXT.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable calls.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable peer.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable ARG2.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable DIALNUM.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable CFNA.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable CFBS.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable CFIM.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable COUNT.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable ARG1.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable MACRO_PRIORITY.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable MACRO_CONTEXT.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable MACRO_EXTEN.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Copying soft-transferable variable start.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Copying soft-transferable variable intern.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable CALLEDTON.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable ANI2.
[Apr 15 00:02:34] DEBUG[8816] channel.c: Not copying variable TRANSFERCAPABILITY.
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Outgoing Call for 236
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Call to peer '236' is 1 out of 10
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: ** Our capability: 0x10e (gsm|ulaw|alaw|g729) Video flag: False
[Apr 15 00:02:34] DEBUG[8816] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- Called 236
[Apr 15 00:02:34] DEBUG[8816] channel.c: Set channel SIP/236-081df8b0 to read format slin
[Apr 15 00:02:34] DEBUG[8816] channel.c: Set channel Zap/31-1 to write format slin
[Apr 15 00:02:34] DEBUG[8816] channel.c: Set channel Zap/31-1 to read format g729
[Apr 15 00:02:34] DEBUG[7616] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '45c32fd1024523451dba563865cd009f@xxx.at' Request 102: Found
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- SIP/236-081df8b0 is ringing
[Apr 15 00:02:34] DEBUG[8816] rtp.c: Channel 'Zap/31-1' has no RTP, not doing anything
[Apr 15 00:02:34] DEBUG[8816] chan_zap.c: Requested indication 3 on channel Zap/31-1
[Apr 15 00:02:34] DEBUG[7616] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '45c32fd1024523451dba563865cd009f@xxx.at' Request 102: Found
[Apr 15 00:02:34] VERBOSE[8816] logger.c:     -- SIP/236-081df8b0 is ringing
[Apr 15 00:02:34] DEBUG[8816] rtp.c: Channel 'Zap/31-1' has no RTP, not doing anything
[Apr 15 00:02:35] DEBUG[7616] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '45c32fd1024523451dba563865cd009f@xxx.at' Request 102: Found
[Apr 15 00:02:35] VERBOSE[8816] logger.c:     -- SIP/236-081df8b0 is ringing
[Apr 15 00:02:35] DEBUG[8816] rtp.c: Channel 'Zap/31-1' has no RTP, not doing anything
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: DTMF digit: 5 on Zap/31-1
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- User hit 5 to disconnect call.
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Requested indication -1 on channel Zap/31-1
[Apr 15 00:02:36] DEBUG[8816] rtp.c: Channel 'Zap/31-1' has no RTP, not doing anything
[Apr 15 00:02:36] DEBUG[8816] channel.c: Hanging up channel 'SIP/236-081df8b0'
[Apr 15 00:02:36] DEBUG[8816] chan_sip.c: Hangup call SIP/236-081df8b0, SIP callid 45c32fd1024523451dba563865cd009f@xxx.at)
[Apr 15 00:02:36] DEBUG[8816] chan_sip.c: Call to peer '236' removed from call limit 10
[Apr 15 00:02:36] DEBUG[8816] chan_sip.c: Acked pending invite 102
[Apr 15 00:02:36] DEBUG[8816] chan_sip.c: Stopping retransmission on '45c32fd1024523451dba563865cd009f@xxx.at' of Request 102: Match Found
[Apr 15 00:02:36] DEBUG[8816] app_dial.c: Exiting with DIALSTATUS=CANCEL.
[Apr 15 00:02:36] DEBUG[8816] app_macro.c: Oooh, got something to jump out with ('5')!
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Oooh, got something to jump out with ('5')!
[Apr 15 00:02:36] VERBOSE[8816] logger.c:   == CDR updated on Zap/31-1
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Launching 'AGI'
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- Executing [5@callback:1] AGI("Zap/31-1", "str_concat.sh") in new stack
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/str_concat.sh
[Apr 15 00:02:36] DEBUG[8816] db.c: Unable to find key '236' in family 'CallBack'
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- AGI Script str_concat.sh completed, returning 0
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Launching 'Hangup'
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- Executing [5@callback:2] Hangup("Zap/31-1", "") in new stack
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Spawn extension (callback,5,2) exited non-zero on 'Zap/31-1'
[Apr 15 00:02:36] VERBOSE[8816] logger.c:   == Spawn extension (callback, 5, 2) exited non-zero on 'Zap/31-1'
[Apr 15 00:02:36] DEBUG[8816] channel.c: Soft-Hanging up channel 'Zap/31-1'
[Apr 15 00:02:36] DEBUG[8816] channel.c: Hanging up channel 'Zap/31-1'
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: zt_hangup(Zap/31-1)
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/31-1
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Hangup: channel: 31 index = 0, normal = 43, callwait = -1, thirdcall = -1
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: disabled echo cancellation on channel 31
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/31-1
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Updated conferencing on 31, with 0 conference users
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/31-1
[Apr 15 00:02:36] DEBUG[8816] chan_zap.c: disabled echo cancellation on channel 31
[Apr 15 00:02:36] VERBOSE[8816] logger.c:     -- Hungup 'Zap/31-1'
[Apr 15 00:02:36] DEBUG[8816] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Apr 15 00:02:36] DEBUG[7616] chan_sip.c: Stopping retransmission on '45c32fd1024523451dba563865cd009f@xxx.at' of Request 102: Match Found
[Apr 15 00:02:36] DEBUG[7616] chan_sip.c: Stopping retransmission on '45c32fd1024523451dba563865cd009f@xxx.at' of Request 102: Match Not Found
[Apr 15 00:02:36] DEBUG[7616] chan_sip.c: Call to peer '236' removed from call limit 10
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is ''
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is ''
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '5'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'callback'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'Zap/31-1'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'SIP/236-081df8b0'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'Hangup'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is ''
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '2009-04-15 00:02:34'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '2009-04-15 00:02:34'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '2009-04-15 00:02:36'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '2'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '2'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'ANSWERED'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is 'DOCUMENTATION'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is ''
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is '1239746554.19'
[Apr 15 00:02:36] DEBUG[8816] pbx.c: Function result is ''