Asterisk SVN-branch-1.4-r51241M, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= == Parsing '/etc/asterisk/asterisk.conf': Parsing /etc/asterisk/asterisk.conf Found == Parsing '/etc/asterisk/extconfig.conf': Parsing /etc/asterisk/extconfig.conf Found == Binding sip_db.conf to odbc/odbc-asterisk/pbx_config == Binding sip_register_db.conf to odbc/odbc-asterisk/pbx_config == Binding followme.conf to odbc/odbc-asterisk/pbx_config == Binding extensions_db.conf to odbc/odbc-asterisk/pbx_config == Binding meetme.conf to odbc/odbc-asterisk/pbx_config == Binding queues.conf to odbc/odbc-asterisk/pbx_config == Binding agents.conf to odbc/odbc-asterisk/pbx_config == Binding voicemail.conf to odbc/odbc-asterisk/pbx_config == Binding musiconhold.conf to odbc/odbc-asterisk/pbx_config == Binding features_db.conf to odbc/odbc-asterisk/pbx_config == Binding zapata_db.conf to odbc/odbc-asterisk/pbx_config Connected to Asterisk SVN-branch-1.4-r51241M currently running on weon (pid = 14619) Verbosity is at least 37 Core debug is at least 35 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 2101034982452964000 Our tag: as66f2b4b8 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 53A570CC-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 2100667486775245684 Our tag: as2577faa5 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 - INVITE (With RTP) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 Their Tag 2101063791802876654 Our tag: as5b247bf8 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on 'FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192' of Response 1: Match Not Found [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 Their Tag 2101063791802876654 Our tag: as5b247bf8 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:13290 handle_request_invite: Checking SIP call limits for device 5050 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3040 update_call_counter: Call from user '5050' is 1 out of 10 [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3760 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:7894 build_route: build_route: Contact hop: [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:13365 handle_request_invite: SIP/5050-085f5120: New call is still down.... Trying... [Feb 1 10:10:46] DEBUG[14632]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085f5120 [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [1000@extensions:1] Macro("SIP/5050-085f5120", "dialinexten|1000") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:1] GotoIf("SIP/5050-085f5120", "0?callrouting:checkredir") in new stack -- Goto (macro-dialinexten,s,2) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:2] GotoIf("SIP/5050-085f5120", "0?:checkboss") in new stack -- Goto (macro-dialinexten,s,5) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected $end, expecting '-' or '!' or '(' or ''; Input: "" != "" & 5050 != ^ [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:5] GotoIf("SIP/5050-085f5120", "0?:checkfindme") in new stack -- Goto (macro-dialinexten,s,9) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:9] GotoIf("SIP/5050-085f5120", "0?:dial") in new stack -- Goto (macro-dialinexten,s,12) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dialinexten:12] Macro("SIP/5050-085f5120", "dial|SIP/1000|45|Tt|E1000-CAL|E1000-IN|E1000-OUT|1000") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/5050-085f5120", "Contexto da macro: "macro-dialinexten"") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:2] GotoIf("SIP/5050-085f5120", "0?outpstn") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:5930 pbx_builtin_gotoif: Not taking any branch [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:3] GotoIf("SIP/5050-085f5120", "1?inexten") in new stack -- Goto (macro-dial,s,9) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:9] NoOp("SIP/5050-085f5120", "Chamando o ramal 1000") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dial:10] Macro("SIP/5050-085f5120", "monitor|5050|1000") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:1] Set("SIP/5050-085f5120", "status = ") in new stack [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = outgoing | = both ^ [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:2] GotoIf("SIP/5050-085f5120", "?3:5") in new stack -- Goto (macro-monitor,s,5) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:5] Set("SIP/5050-085f5120", "status=") in new stack [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = incoming | = both ^ [Feb 1 10:10:46] WARNING[17514]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:6] GotoIf("SIP/5050-085f5120", "?7:9") in new stack -- Goto (macro-monitor,s,9) [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-monitor:9] NoOp("SIP/5050-085f5120", "Checagem de gravacao da chamada finalizada!") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:11] Set("SIP/5050-085f5120", "CDR(userfield)=Entrante") in new stack [Feb 1 10:10:46] DEBUG[17514]: pbx.c:1768 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:12] Dial("SIP/5050-085f5120", "SIP/1000|45|Tt") in new stack [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:15155 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3760 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3763 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-12. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-11. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG2. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-9. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-6. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-5. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-2. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status . [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-1. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-9. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG7. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG6. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG5. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG4. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG3. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-12. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-9. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-5. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-2. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-1. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-extensions-1000-1. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 1 10:10:46] DEBUG[17514]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:2804 sip_call: Outgoing Call for 1000 [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:3040 update_call_counter: Call to peer '1000' is 1 out of 10 [Feb 1 10:10:46] DEBUG[17514]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000 [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:2818 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:6121 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:6139 add_sdp: This call needs video offers, but there's no video support enabled! [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Feb 1 10:10:46] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:46] DEBUG[17514]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) -- Called 1000 [Feb 1 10:10:46] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:10:46] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:10:46] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 1 (Not in use) [Feb 1 10:10:46] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:10:46] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:10:46] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 6 (Ringing) [Feb 1 10:10:46] DEBUG[17515]: app_queue.c:546 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 10:10:46] DEBUG[17516]: app_queue.c:546 changethread: Device 'SIP/1000' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag Our tag: as40e96d1a [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39aa0bef70c443fe1d76ab5407219e77@172.16.0.197' Request 102: Found [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 100 to standard invite [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag Our tag: as40e96d1a [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39aa0bef70c443fe1d76ab5407219e77@172.16.0.197' Request 102: Found [Feb 1 10:10:46] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 101 to standard invite [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag 1996341685 Our tag: as40e96d1a [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:2047 __sip_ack: Acked pending invite 102 [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '39aa0bef70c443fe1d76ab5407219e77@172.16.0.197' of Request 102: Match Not Found [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 200 to standard invite [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel SIP/1000-0859dc78 [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:5146 process_sdp: We have an owner, now see if we need to change this call [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:10:48] DEBUG[14632]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000 [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:7894 build_route: build_route: Contact hop: [Feb 1 10:10:48] DEBUG[17514]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000-0859dc78 -- SIP/1000-0859dc78 answered SIP/5050-085f5120 [Feb 1 10:10:48] DEBUG[17514]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085f5120 [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:3420 sip_answer: SIP answering channel: SIP/5050-085f5120 [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:6353 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:6121 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Feb 1 10:10:48] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:48] DEBUG[17514]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:10:48] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 2 (In use) [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:10:48] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 2 (In use) [Feb 1 10:10:48] DEBUG[17517]: app_queue.c:546 changethread: Device 'SIP/1000' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 10:10:48] DEBUG[17518]: app_queue.c:546 changethread: Device 'SIP/1000' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:10:48] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:10:48] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 1 (Not in use) [Feb 1 10:10:48] DEBUG[17519]: app_queue.c:546 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 10:10:48] DEBUG[17514]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 10:10:48] DEBUG[17514]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag 1996341685 Our tag: as40e96d1a [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 Their Tag 2101063791802876654 Our tag: as3206fd7f [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 10:10:48] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on 'FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192' of Response 2: Match Not Found [Feb 1 10:10:48] DEBUG[17514]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 10:10:48] DEBUG[17514]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 1 10:10:49] DEBUG[14632]: chan_sip.c:1986 __sip_autodestruct: Auto destroying SIP dialog '4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192' [Feb 1 10:10:49] DEBUG[14632]: chan_sip.c:3072 sip_destroy: Destroying SIP dialog 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Really destroying SIP dialog '4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192' Method: REGISTER [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.16.0.192 [Feb 1 10:10:50] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '*' received on SIP/5050-085f5120 [Feb 1 10:10:50] DEBUG[17514]: channel.c:3803 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-085f5120) [Feb 1 10:10:50] DEBUG[17514]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085f5120 and SIP/1000-0859dc78 [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.16.0.192 [Feb 1 10:10:50] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '*' received on SIP/5050-085f5120 [Feb 1 10:10:50] DEBUG[17514]: channel.c:3803 ast_generic_bridge: Got DTMF end on channel (SIP/5050-085f5120) [Feb 1 10:10:50] DEBUG[17514]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085f5120 and SIP/1000-0859dc78 [Feb 1 10:10:50] DEBUG[17514]: res_features.c:1039 ast_feature_interpret: Feature interpret: chan=SIP/5050-085f5120, peer=SIP/1000-0859dc78, sense=1, features=2 [Feb 1 10:10:50] DEBUG[17514]: res_features.c:1499 ast_bridge_call: Set time limit to 5000 [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:10:50] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag 1996341685 Our tag: as40e96d1a [Feb 1 10:10:50] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 Their Tag 2101063791802876654 Our tag: as3206fd7f [Feb 1 10:10:50] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 53A570CC-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 2100667486775245684 Our tag: as2577faa5 [Feb 1 10:10:50] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192 [Feb 1 10:10:50] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '1' received on SIP/5050-085f5120 [Feb 1 10:10:50] DEBUG[17514]: channel.c:3803 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-085f5120) [Feb 1 10:10:50] DEBUG[17514]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085f5120 and SIP/1000-0859dc78 [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192 [Feb 1 10:10:50] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '1' received on SIP/5050-085f5120 [Feb 1 10:10:50] DEBUG[17514]: channel.c:3803 ast_generic_bridge: Got DTMF end on channel (SIP/5050-085f5120) [Feb 1 10:10:50] DEBUG[17514]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085f5120 and SIP/1000-0859dc78 [Feb 1 10:10:50] DEBUG[17514]: res_features.c:1039 ast_feature_interpret: Feature interpret: chan=SIP/5050-085f5120, peer=SIP/1000-0859dc78, sense=1, features=2 [Feb 1 10:10:50] WARNING[17514]: res_musiconhold.c:940 local_ast_moh_start: No class: default [Feb 1 10:10:50] DEBUG[17514]: channel.c:2808 set_format: Set channel SIP/5050-085f5120 to write format slin -- Playing 'pbx-transfer' (language 'pt_BR') [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 10:10:50] DEBUG[17440]: rtp.c:871 ast_rtcp_read: Got RTCP report of 88 bytes [Feb 1 10:10:51] DEBUG[17514]: channel.c:2808 set_format: Set channel SIP/5050-085f5120 to write format ulaw [Feb 1 10:10:51] DEBUG[17514]: channel.c:2808 set_format: Set channel SIP/5050-085f5120 to write format slin [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:51] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:51] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192 [Feb 1 10:10:51] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '5' received on SIP/5050-085f5120 [Feb 1 10:10:51] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '5' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: channel.c:2808 set_format: Set channel SIP/5050-085f5120 to write format ulaw [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '0' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '0' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '5' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '5' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192 [Feb 1 10:10:52] DTMF[17514]: channel.c:2223 __ast_read: DTMF begin '0' received on SIP/5050-085f5120 [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:52] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:53] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:53] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:53] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:53] DEBUG[17514]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Feb 1 10:10:53] DEBUG[17514]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192 [Feb 1 10:10:53] DTMF[17514]: channel.c:2203 __ast_read: DTMF end '0' received on SIP/5050-085f5120 -- Transferring SIP/1000-0859dc78 to '5050' (context extensions) priority 1 [Feb 1 10:10:53] DEBUG[17514]: channel.c:3196 ast_channel_masquerade: Planning to masquerade channel SIP/1000-0859dc78 into the structure of AsyncGoto/SIP/1000-0859dc78 [Feb 1 10:10:53] DEBUG[17514]: channel.c:3209 ast_channel_masquerade: Done planning to masquerade channel SIP/1000-0859dc78 into the structure of AsyncGoto/SIP/1000-0859dc78 [Feb 1 10:10:53] DEBUG[17514]: channel.c:3326 ast_do_masquerade: Actually Masquerading SIP/1000-0859dc78(6) into the structure of AsyncGoto/SIP/1000-0859dc78(6) [Feb 1 10:10:53] DEBUG[17514]: channel.c:3338 ast_do_masquerade: Got clone lock for masquerade on 'SIP/1000-0859dc78' at 0x85e6180 [Feb 1 10:10:53] DEBUG[17514]: channel.c:3533 ast_do_masquerade: Putting channel SIP/1000-0859dc78 in 4/4 formats [Feb 1 10:10:53] DEBUG[17514]: chan_sip.c:3545 sip_fixup: SIP Fixup: New owner for dialogue 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197: SIP/1000-0859dc78 (Old parent: AsyncGoto/SIP/1000-0859dc78) [Feb 1 10:10:53] DEBUG[17514]: channel.c:3568 ast_do_masquerade: Released clone lock on 'AsyncGoto/SIP/1000-0859dc78' [Feb 1 10:10:53] DEBUG[17514]: channel.c:3578 ast_do_masquerade: Done Masquerading SIP/1000-0859dc78 (6) [Feb 1 10:10:53] DEBUG[17514]: channel.c:1686 ast_hangup: Hanging up zombie 'AsyncGoto/SIP/1000-0859dc78' [Feb 1 10:10:53] DEBUG[17514]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel AsyncGoto/SIP/1000-0859dc78 [Feb 1 10:10:53] DEBUG[17514]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 1 10:10:53] DEBUG[17514]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 1 10:10:53] DEBUG[17514]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085f5120' in macro 'dial' [Feb 1 10:10:53] DEBUG[17514]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085f5120' in macro 'dialinexten' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:2364 __ast_pbx_run: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085f5120' == Spawn extension (macro-dial, s, 12) exited non-zero on 'SIP/5050-085f5120' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Caio Begotti" <5050>' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1000' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'extensions' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/5050-085f5120' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/1000-0859dc78' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/1000|45|Tt' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:10:46' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:10:48' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:10:53' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '7' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1170331846.10' [Feb 1 10:10:53] DEBUG[17514]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Entrante' [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for AsyncGoto - SIP/1000 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for AsyncGoto/SIP/1000 - state 4 (Invalid) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [5050@extensions:1] Macro("SIP/1000-0859dc78", "dialinexten|5050") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:1] GotoIf("SIP/1000-0859dc78", "0?callrouting:checkredir") in new stack -- Goto (macro-dialinexten,s,2) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:2] GotoIf("SIP/1000-0859dc78", "0?:checkboss") in new stack -- Goto (macro-dialinexten,s,5) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1000' [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected $end, expecting '-' or '!' or '(' or ''; Input: "" != "" & 1000 != ^ [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:5] GotoIf("SIP/1000-0859dc78", "0?:checkfindme") in new stack -- Goto (macro-dialinexten,s,9) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:9] GotoIf("SIP/1000-0859dc78", "0?:dial") in new stack -- Goto (macro-dialinexten,s,12) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dialinexten:12] Macro("SIP/1000-0859dc78", "dial|SIP/5050|45|Tt|E5050-CAL|E5050-IN|E5050-OUT|5050") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/1000-0859dc78", "Contexto da macro: "macro-dialinexten"") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:2] GotoIf("SIP/1000-0859dc78", "0?outpstn") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:5930 pbx_builtin_gotoif: Not taking any branch [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:3] GotoIf("SIP/1000-0859dc78", "1?inexten") in new stack -- Goto (macro-dial,s,9) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:9] NoOp("SIP/1000-0859dc78", "Chamando o ramal 5050") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1000' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dial:10] Macro("SIP/1000-0859dc78", "monitor|1000|5050") in new stack [Feb 1 10:10:53] DEBUG[17521]: app_queue.c:546 changethread: Device 'AsyncGoto/SIP/1000' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. > cdr_odbc: Query Successful! [Feb 1 10:10:53] DEBUG[17514]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded! [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:1] Set("SIP/1000-0859dc78", "status = ") in new stack [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = outgoing | = both ^ [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:2] GotoIf("SIP/1000-0859dc78", "?3:5") in new stack -- Goto (macro-monitor,s,5) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:5] Set("SIP/1000-0859dc78", "status=") in new stack [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = incoming | = both ^ [Feb 1 10:10:53] WARNING[17520]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:6] GotoIf("SIP/1000-0859dc78", "?7:9") in new stack -- Goto (macro-monitor,s,9) [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-monitor:9] NoOp("SIP/1000-0859dc78", "Checagem de gravacao da chamada finalizada!") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:11] Set("SIP/1000-0859dc78", "CDR(userfield)=Entrante") in new stack [Feb 1 10:10:53] DEBUG[17520]: pbx.c:1768 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:12] Dial("SIP/1000-0859dc78", "SIP/5050|45|Tt") in new stack [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:15155 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3760 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3763 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-12. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-11. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG2. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-9. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-6. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-5. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-2. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status . [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-1. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-9. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG7. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG6. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG5. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG4. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG3. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-12. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-9. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-5. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-2. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-1. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-extensions-5050-1. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable BLINDTRANSFER. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable BRIDGEPEER. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Feb 1 10:10:53] DEBUG[17520]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:2804 sip_call: Outgoing Call for 5050 [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:3040 update_call_counter: Call to peer '5050' is 1 out of 10 [Feb 1 10:10:53] DEBUG[17520]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:10:53] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 6 (Ringing) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:2818 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:6121 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:6139 add_sdp: This call needs video offers, but there's no video support enabled! [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Feb 1 10:10:53] DEBUG[17520]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:53] DEBUG[17520]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) -- Called 5050 [Feb 1 10:10:53] DEBUG[17522]: app_queue.c:546 changethread: Device 'SIP/5050' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 5ae9fa4b5fdd44d8312876e73b7f33a3@172.16.0.197 Their Tag Our tag: as3e681826 [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5ae9fa4b5fdd44d8312876e73b7f33a3@172.16.0.197' Request 102: Found [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 100 to standard invite [Feb 1 10:10:53] DEBUG[17514]: channel.c:1681 ast_hangup: Hanging up channel 'SIP/5050-085f5120' [Feb 1 10:10:53] DEBUG[17514]: chan_sip.c:3270 sip_hangup: Hangup call SIP/5050-085f5120, SIP callid FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192) [Feb 1 10:10:53] DEBUG[17514]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Feb 1 10:10:53] DEBUG[17514]: chan_sip.c:3014 update_call_counter: Call from user '5050' removed from call limit 10 [Feb 1 10:10:53] DEBUG[17514]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085f5120 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:10:53] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 6 (Ringing) [Feb 1 10:10:53] DEBUG[17523]: app_queue.c:546 changethread: Device 'SIP/5050' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 5ae9fa4b5fdd44d8312876e73b7f33a3@172.16.0.197 Their Tag 2101070400842512067 Our tag: as3e681826 [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 39aa0bef70c443fe1d76ab5407219e77@172.16.0.197 Their Tag 1996341685 Our tag: as40e96d1a [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192 Their Tag 2101063791802876654 Our tag: as3206fd7f [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on 'FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192' of Request 102: Match Not Found Really destroying SIP dialog 'FF1D201E-1DD1-11B2-B857-FB5CBDFDDE74@172.16.0.192' Method: ACK [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 5ae9fa4b5fdd44d8312876e73b7f33a3@172.16.0.197 Their Tag 2101070400842512067 Our tag: as3e681826 [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5ae9fa4b5fdd44d8312876e73b7f33a3@172.16.0.197' Request 102: Found [Feb 1 10:10:53] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 180 to standard invite [Feb 1 10:10:53] DEBUG[14632]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085e6698 -- SIP/5050-085e6698 is ringing [Feb 1 10:10:53] DEBUG[17520]: channel.c:2402 ast_indicate_data: Driver for channel 'SIP/1000-0859dc78' does not support indication 3, emulating it [Feb 1 10:10:53] DEBUG[17520]: channel.c:2808 set_format: Set channel SIP/1000-0859dc78 to write format slin [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:10:53] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:10:53] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 6 (Ringing) [Feb 1 10:10:53] DEBUG[17524]: app_queue.c:546 changethread: Device 'SIP/5050' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 10:10:53] DEBUG[17520]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:10:53] DEBUG[17520]: rtp.c:2540 ast_rtp_raw_write: Difference is 24960, ms is 3140