asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> asterisk*CLI> Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:3174 sip_alloc: Allocating new SIP dialog for 9a1c6e0f590dae3e - INVITE (With RTP) Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:7225 check_user_full: Setting NAT on RTP to 524288 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:3174 sip_alloc: Allocating new SIP dialog for 9a1c6e0f590dae3e - INVITE (With RTP) Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:7225 check_user_full: Setting NAT on RTP to 524288 asterisk*CLI> Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:1402 __sip_ack: Stopping retransmission on '9a1c6e0f590dae3e' of Response 1: Match Found Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:1402 __sip_ack: Stopping retransmission on '9a1c6e0f590dae3e' of Response 1: Match Found asterisk*CLI> Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:7225 check_user_full: Setting NAT on RTP to 524288 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:10542 handle_request_invite: Checking SIP call limits for device u333 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:6205 build_route: build_route: Contact hop: Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:04 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 2 (In use) Jun 21 08:40:04 DEBUG[11448]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/u333-9f3d", "H323/0012028447171@btk|60|T") in new stack Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:1022 oh323_request: type=H323, format=(ulaw), data=0012028447171@btk. Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:1045 oh323_request: Extension: 0012028447171 Host: btk Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:926 find_peer: Found peer btk by name Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:974 create_addr: Setting NAT on RTP to 0 Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable STACK-internal-990012028447171-1. Jun 21 08:40:04 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPCALLID. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPURI. Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:433 oh323_call: Placing outgoing call to 0012028447171@212.39.70.49:1720, 101 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:7225 check_user_full: Setting NAT on RTP to 524288 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:10542 handle_request_invite: Checking SIP call limits for device u333 Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:6205 build_route: build_route: Contact hop: Jun 21 08:40:04 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:04 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 2 (In use) Jun 21 08:40:04 DEBUG[11448]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/u333-9f3d", "H323/0012028447171@btk|60|T") in new stack Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:1022 oh323_request: type=H323, format=(ulaw), data=0012028447171@btk. Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:1045 oh323_request: Extension: 0012028447171 Host: btk Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:926 find_peer: Found peer btk by name Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:974 create_addr: Setting NAT on RTP to 0 Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable STACK-internal-990012028447171-1. Jun 21 08:40:04 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPCALLID. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Jun 21 08:40:04 DEBUG[11448]: channel.c:2839 ast_channel_inherit_variables: Not copying variable SIPURI. Jun 21 08:40:04 DEBUG[11448]: chan_h323.c:433 oh323_call: Placing outgoing call to 0012028447171@212.39.70.49:1720, 101 -- Called 0012028447171@btk Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to write format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to read format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin -- Called 0012028447171@btk Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to write format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to read format slin Jun 21 08:40:04 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin asterisk*CLI> Jun 21 08:40:06 DEBUG[11448]: chan_h323.c:1250 progress: Received ALERT/PROGRESS message for inband tones Jun 21 08:40:06 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 6 (Ringing) -- H323/btk-3 is making progress passing it to SIP/u333-9f3d -- H323/btk-3 is ringing Jun 21 08:40:06 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Jun 21 08:40:06 DEBUG[11448]: chan_h323.c:1250 progress: Received ALERT/PROGRESS message for inband tones Jun 21 08:40:06 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 6 (Ringing) -- H323/btk-3 is making progress passing it to SIP/u333-9f3d -- H323/btk-3 is ringing Jun 21 08:40:06 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. asterisk*CLI> Jun 21 08:40:06 DEBUG[11448]: rtp.c:408 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 195.149.250.142:8505 Jun 21 08:40:06 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes Jun 21 08:40:06 DEBUG[11448]: rtp.c:408 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 195.149.250.142:8505 Jun 21 08:40:06 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes asterisk*CLI> Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin asterisk*CLI> Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format slin Jun 21 08:40:06 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format slin asterisk*CLI> Jun 21 08:40:07 DEBUG[11448]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to g729 Jun 21 08:40:07 DEBUG[11448]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to g729 asterisk*CLI> Jun 21 08:40:09 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 2 (In use) Jun 21 08:40:09 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- H323/btk-3 answered SIP/u333-9f3d Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to read format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to write format g729 Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:2545 sip_answer: sip_answer(SIP/u333-9f3d) Jun 21 08:40:09 DEBUG[11448]: channel.c:1948 ast_read: Dropping duplicate answer! Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:09 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 2 (In use) Jun 21 08:40:09 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 08:40:09 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 2 (In use) Jun 21 08:40:09 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- H323/btk-3 answered SIP/u333-9f3d Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to read format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to write format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel H323/btk-3 to read format g729 Jun 21 08:40:09 DEBUG[11448]: channel.c:2334 set_format: Set channel SIP/u333-9f3d to write format g729 Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:2545 sip_answer: sip_answer(SIP/u333-9f3d) Jun 21 08:40:09 DEBUG[11448]: channel.c:1948 ast_read: Dropping duplicate answer! Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:09 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 2 (In use) Jun 21 08:40:09 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '2' (In use) but we don't care because they're not a member of any queue. asterisk*CLI> Jun 21 08:40:09 DEBUG[11448]: rtp.c:480 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 195.149.250.142:8504 Jun 21 08:40:09 DEBUG[11448]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to g729 Jun 21 08:40:09 DEBUG[11448]: rtp.c:480 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 195.149.250.142:8504 Jun 21 08:40:09 DEBUG[11448]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to g729 asterisk*CLI> Jun 21 08:40:09 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes Jun 21 08:40:09 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes asterisk*CLI> Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:1402 __sip_ack: Stopping retransmission on '9a1c6e0f590dae3e' of Response 2: Match Found Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 08:40:09 DEBUG[11448]: chan_sip.c:1402 __sip_ack: Stopping retransmission on '9a1c6e0f590dae3e' of Response 2: Match Found asterisk*CLI> Jun 21 08:40:10 NOTICE[11448]: rtp.c:332 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 212.39.70.49 Jun 21 08:40:10 NOTICE[11448]: rtp.c:332 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 212.39.70.49 asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 52 bytes Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 52 bytes asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 72 bytes asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 12 bytes Jun 21 08:40:15 DEBUG[11448]: rtp.c:412 ast_rtcp_read: Got RTCP report of 12 bytes asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received BYE (8) - Command in SIP BYE Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:11191 handle_request: **** Received BYE (8) - Command in SIP BYE asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: channel.c:3292 ast_generic_bridge: Didn't get a frame from channel: SIP/u333-9f3d Jun 21 08:40:15 DEBUG[11448]: channel.c:3568 ast_channel_bridge: Bridge stops bridging channels SIP/u333-9f3d and H323/btk-3 Jun 21 08:40:15 DEBUG[11448]: channel.c:1315 ast_hangup: Hanging up channel 'H323/btk-3' Jun 21 08:40:15 DEBUG[11448]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jun 21 08:40:15 DEBUG[11448]: pbx.c:2316 __ast_pbx_run: Spawn extension (internal,990012028447171,1) exited non-zero on 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Test" <333>' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '333' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '990012028447171' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'internal' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'H323/btk-3' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'H323/0012028447171@btk|60|T' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:04' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:09' Jun 21 08:40:15 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 0 (Unknown) Jun 21 08:40:15 DEBUG[11448]: channel.c:3292 ast_generic_bridge: Didn't get a frame from channel: SIP/u333-9f3d Jun 21 08:40:15 DEBUG[11448]: channel.c:3568 ast_channel_bridge: Bridge stops bridging channels SIP/u333-9f3d and H323/btk-3 Jun 21 08:40:15 DEBUG[11448]: channel.c:1315 ast_hangup: Hanging up channel 'H323/btk-3' Jun 21 08:40:15 DEBUG[11448]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jun 21 08:40:15 DEBUG[11448]: pbx.c:2316 __ast_pbx_run: Spawn extension (internal,990012028447171,1) exited non-zero on 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Test" <333>' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '333' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '990012028447171' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'internal' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'H323/btk-3' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'H323/0012028447171@btk|60|T' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:04' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:09' Jun 21 08:40:15 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for H323/btk - state 0 (Unknown) asterisk*CLI> Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:15' Jun 21 08:40:15 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '11' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 08:40:15' Jun 21 08:40:15 DEBUG[11448]: app_queue.c:523 changethread: Device 'H323/btk' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '11' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1150868404.4' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 08:40:15 DEBUG[11448]: channel.c:1315 ast_hangup: Hanging up channel 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2417 sip_hangup: Hangup call SIP/u333-9f3d, SIP callid 9a1c6e0f590dae3e) Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2425 sip_hangup: update_call_counter(u333) - decrement call limit counter Function result is 'ANSWERED' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1150868404.4' Jun 21 08:40:15 DEBUG[11448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 08:40:15 DEBUG[11448]: channel.c:1315 ast_hangup: Hanging up channel 'SIP/u333-9f3d' Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2417 sip_hangup: Hangup call SIP/u333-9f3d, SIP callid 9a1c6e0f590dae3e) Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2425 sip_hangup: Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:15 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 1 (Not in use) Jun 21 08:40:15 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. update_call_counter(u333) - decrement call limit counter Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call Jun 21 08:40:15 DEBUG[11448]: chan_sip.c:11722 sip_devicestate: Checking device state for peer u333 Jun 21 08:40:15 DEBUG[11448]: devicestate.c:187 do_state_change: Changing state for SIP/u333 - state 1 (Not in use) Jun 21 08:40:15 DEBUG[11448]: app_queue.c:523 changethread: Device 'SIP/u333' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> Jun 21 08:40:16 DEBUG[11448]: chan_h323.c:1454 cleanup_connection: Cleaning connection to ip$localhost/8664 Jun 21 08:40:16 DEBUG[11448]: chan_h323.c:1454 cleanup_connection: Cleaning connection to ip$localhost/8664