Connected to Asterisk SVN-branch-1.4-r51241M currently running on weon (pid = 14619) Verbosity is at least 37 Core debug was 0 and is now 35 [Feb 1 10:06:22] DEBUG[17468]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 1 10:06:24] DEBUG[17468]: rtp.c:871 ast_rtcp_read: Got RTCP report of 40 bytes [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 21007948931215866208 Our tag: as3916bf2f [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 476c666136ae3bf70ce4a3362f309bfd@172.16.0.197 Their Tag 136768490 Our tag: as7e162b77 [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:1609 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 476c666136ae3bf70ce4a3362f309bfd@172.16.0.197 [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:14079 handle_request_bye: Received bye, issuing owner hangup [Feb 1 10:06:24] DEBUG[17468]: channel.c:3759 ast_generic_bridge: Didn't get a frame from channel: SIP/1000-085f5120 [Feb 1 10:06:24] DEBUG[17468]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085e6698 and SIP/1000-085f5120 [Feb 1 10:06:24] DEBUG[17468]: channel.c:1681 ast_hangup: Hanging up channel 'SIP/1000-085f5120' [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:3270 sip_hangup: Hangup call SIP/1000-085f5120, SIP callid 476c666136ae3bf70ce4a3362f309bfd@172.16.0.197) [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:3014 update_call_counter: Call to peer '1000' removed from call limit 10 [Feb 1 10:06:24] DEBUG[17468]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000 [Feb 1 10:06:24] DEBUG[17468]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000-085f5120 [Feb 1 10:06:24] DEBUG[17468]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 1 10:06:24] DEBUG[17468]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 1 10:06:24] DEBUG[17468]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085e6698' in macro 'dial' [Feb 1 10:06:24] DEBUG[17468]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085e6698' in macro 'dialinexten' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:2364 __ast_pbx_run: Spawn extension (macro-dial,s,12) exited non-zero on 'SIP/5050-085e6698' == Spawn extension (macro-dial, s, 12) exited non-zero on 'SIP/5050-085e6698' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Caio Begotti" <5050>' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1000' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'extensions' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/5050-085e6698' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/1000-085f5120' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/1000|45|Tt' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:06:06' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:06:08' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-01 10:06:24' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '18' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '16' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1170331566.4' [Feb 1 10:06:24] DEBUG[17468]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Entrante' [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:06:24] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 1 (Not in use) [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:06:24] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 1 (Not in use) [Feb 1 10:06:24] DEBUG[17477]: app_queue.c:546 changethread: Device 'SIP/1000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 10:06:24] DEBUG[17478]: app_queue.c:546 changethread: Device 'SIP/1000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. > cdr_odbc: Query Successful! [Feb 1 10:06:24] DEBUG[17468]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded! [Feb 1 10:06:24] DEBUG[17468]: channel.c:1681 ast_hangup: Hanging up channel 'SIP/5050-085e6698' [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:3270 sip_hangup: Hangup call SIP/5050-085e6698, SIP callid 580419CC-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192) [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Feb 1 10:06:24] DEBUG[17468]: chan_sip.c:3014 update_call_counter: Call from user '5050' removed from call limit 10 [Feb 1 10:06:24] DEBUG[17468]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085e6698 [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:06:24] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:06:24] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 1 (Not in use) [Feb 1 10:06:24] DEBUG[17479]: 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:06:24] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 21007948931215866208 Our tag: as3916bf2f [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 476c666136ae3bf70ce4a3362f309bfd@172.16.0.197 Their Tag 136768490 Our tag: as7e162b77 [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 580419CC-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 Their Tag 21007834481330194204 Our tag: as1b50ade5 [Feb 1 10:06:24] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '580419CC-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192' of Request 102: Match Not Found Really destroying SIP dialog '476c666136ae3bf70ce4a3362f309bfd@172.16.0.197' Method: BYE Really destroying SIP dialog '580419CC-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192' Method: ACK [Feb 1 10:06:25] DEBUG[14632]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Feb 1 10:06:25] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 0bffb1b54297c3d3116844c727a9f617@172.16.0.197 Their Tag Our tag: as01485e84 [Feb 1 10:06:25] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '0bffb1b54297c3d3116844c727a9f617@172.16.0.197' of Request 102: Match Not Found Really destroying SIP dialog '0bffb1b54297c3d3116844c727a9f617@172.16.0.197' Method: NOTIFY [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 21007948931215866208 Our tag: as3916bf2f [Feb 1 10:06:27] 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:06:27] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for 649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 - INVITE (With RTP) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 Their Tag 2100804599265262679 Our tag: as1f1ddfa7 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192' of Response 1: Match Not Found [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 Their Tag 2100804599265262679 Our tag: as1f1ddfa7 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:13290 handle_request_invite: Checking SIP call limits for device 5050 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3040 update_call_counter: Call from user '5050' is 1 out of 10 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3760 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:7894 build_route: build_route: Contact hop: [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:13365 handle_request_invite: SIP/5050-085e6698: New call is still down.... Trying... [Feb 1 10:06:27] DEBUG[14632]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085e6698 [Feb 1 10:06:27] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:06:27] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:06:27] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 1 (Not in use) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [1000@extensions:1] Macro("SIP/5050-085e6698", "dialinexten|1000") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:1] GotoIf("SIP/5050-085e6698", "0?callrouting:checkredir") in new stack -- Goto (macro-dialinexten,s,2) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' [Feb 1 10:06:27] DEBUG[17481]: 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. -- Executing [s@macro-dialinexten:2] GotoIf("SIP/5050-085e6698", "0?:checkboss") in new stack -- Goto (macro-dialinexten,s,5) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected $end, expecting '-' or '!' or '(' or ''; Input: "" != "" & 5050 != ^ [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:5] GotoIf("SIP/5050-085e6698", "0?:checkfindme") in new stack -- Goto (macro-dialinexten,s,9) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialinexten:9] GotoIf("SIP/5050-085e6698", "0?:dial") in new stack -- Goto (macro-dialinexten,s,12) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dialinexten:12] Macro("SIP/5050-085e6698", "dial|SIP/1000|45|Tt|E1000-CAL|E1000-IN|E1000-OUT|1000") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/5050-085e6698", "Contexto da macro: "macro-dialinexten"") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:2] GotoIf("SIP/5050-085e6698", "0?outpstn") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:5930 pbx_builtin_gotoif: Not taking any branch [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1689 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:3] GotoIf("SIP/5050-085e6698", "1?inexten") in new stack -- Goto (macro-dial,s,9) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:9] NoOp("SIP/5050-085e6698", "Chamando o ramal 1000") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5050' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dial:10] Macro("SIP/5050-085e6698", "monitor|5050|1000") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:1] Set("SIP/5050-085e6698", "status = ") in new stack [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = outgoing | = both ^ [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:2] GotoIf("SIP/5050-085e6698", "?3:5") in new stack -- Goto (macro-monitor,s,5) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-monitor:5] Set("SIP/5050-085e6698", "status=") in new stack [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected '=', expecting $end; Input: = incoming | = both ^ [Feb 1 10:06:27] WARNING[17480]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-monitor:6] GotoIf("SIP/5050-085e6698", "?7:9") in new stack -- Goto (macro-monitor,s,9) [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-monitor:9] NoOp("SIP/5050-085e6698", "Checagem de gravacao da chamada finalizada!") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:11] Set("SIP/5050-085e6698", "CDR(userfield)=Entrante") in new stack [Feb 1 10:06:27] DEBUG[17480]: pbx.c:1768 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:12] Dial("SIP/5050-085e6698", "SIP/1000|45|Tt") in new stack [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:15155 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3760 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3763 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-12. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-11. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG2. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-9. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-6. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-5. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-2. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable status . [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-1. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-9. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG7. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG6. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG5. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG4. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable ARG3. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-12. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-9. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-5. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-2. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-1. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable STACK-extensions-1000-1. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 1 10:06:27] DEBUG[17480]: channel.c:3262 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:2804 sip_call: Outgoing Call for 1000 [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:3040 update_call_counter: Call to peer '1000' is 1 out of 10 [Feb 1 10:06:27] DEBUG[17480]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000 [Feb 1 10:06:27] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:06:27] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:06:27] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 6 (Ringing) [Feb 1 10:06:27] DEBUG[17482]: 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:06:27] DEBUG[17480]: chan_sip.c:2818 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:6121 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:6139 add_sdp: This call needs video offers, but there's no video support enabled! [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Feb 1 10:06:27] DEBUG[17480]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:06:27] DEBUG[17480]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) -- Called 1000 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 2e1993175e8619e831591ad538fa1134@172.16.0.197 Their Tag Our tag: as4fa6d038 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e1993175e8619e831591ad538fa1134@172.16.0.197' Request 102: Found [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 100 to standard invite [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 2e1993175e8619e831591ad538fa1134@172.16.0.197 Their Tag Our tag: as4fa6d038 [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e1993175e8619e831591ad538fa1134@172.16.0.197' Request 102: Found [Feb 1 10:06:27] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 101 to standard invite [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 2e1993175e8619e831591ad538fa1134@172.16.0.197 Their Tag 954634113 Our tag: as4fa6d038 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:2047 __sip_ack: Acked pending invite 102 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '2e1993175e8619e831591ad538fa1134@172.16.0.197' of Request 102: Match Not Found [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:11539 handle_response_invite: SIP response 200 to standard invite [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel SIP/1000-085f3690 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:5146 process_sdp: We have an owner, now see if we need to change this call [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Feb 1 10:06:28] 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:06:28] DEBUG[14632]: chan_sip.c:7894 build_route: build_route: Contact hop: [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:06:28] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 2 (In use) [Feb 1 10:06:28] DEBUG[17480]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000-085f3690 -- SIP/1000-085f3690 answered SIP/5050-085e6698 [Feb 1 10:06:28] DEBUG[17480]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085e6698 [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:3420 sip_answer: SIP answering channel: SIP/5050-085e6698 [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:6353 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:6121 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Feb 1 10:06:28] DEBUG[17480]: channel.c:2349 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Feb 1 10:06:28] DEBUG[17480]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Feb 1 10:06:28] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 1000 [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 2 (In use) [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5050 [Feb 1 10:06:28] DEBUG[14625]: chan_sip.c:15097 sip_devicestate: Checking device state for peer 5050 [Feb 1 10:06:28] DEBUG[14625]: devicestate.c:287 do_state_change: Changing state for SIP/5050 - state 1 (Not in use) [Feb 1 10:06:28] DEBUG[17483]: 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:06:28] DEBUG[17484]: 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:06:28] DEBUG[17485]: 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:06:28] DEBUG[17480]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 10:06:28] DEBUG[17480]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 2e1993175e8619e831591ad538fa1134@172.16.0.197 Their Tag 954634113 Our tag: as4fa6d038 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:4307 find_call: = Found Their Call ID: 649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 Their Tag 2100804599265262679 Our tag: as4f1a8fd9 [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 10:06:28] DEBUG[14632]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192' of Response 2: Match Not Found [Feb 1 10:06:28] DEBUG[17480]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 10:06:28] DEBUG[17480]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 1 10:06:30] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 2e1993175e8619e831591ad538fa1134@172.16.0.197 Their Tag 954634113 Our tag: as4fa6d038 [Feb 1 10:06:30] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 649F7096-1DD2-11B2-B856-FB5CBDFDDE74@172.16.0.192 Their Tag 2100804599265262679 Our tag: as4f1a8fd9 [Feb 1 10:06:30] DEBUG[14632]: chan_sip.c:4307 find_call: = No match Their Call ID: 4BBB175E-1DD2-11B2-B855-FB5CBDFDDE74@172.16.0.192 Their Tag 21007948931215866208 Our tag: as3916bf2f [Feb 1 10:06:30] 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:06:30] DEBUG[14632]: chan_sip.c:14502 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.16.0.192 [Feb 1 10:06:30] DTMF[17480]: channel.c:2223 __ast_read: DTMF begin '*' received on SIP/5050-085e6698 [Feb 1 10:06:30] DEBUG[17480]: channel.c:3803 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-085e6698) [Feb 1 10:06:30] DEBUG[17480]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085e6698 and SIP/1000-085f3690 [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:871 ast_rtcp_read: Got RTCP report of 88 bytes [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.16.0.192 [Feb 1 10:06:30] DTMF[17480]: channel.c:2203 __ast_read: DTMF end '*' received on SIP/5050-085e6698 [Feb 1 10:06:30] DEBUG[17480]: channel.c:3803 ast_generic_bridge: Got DTMF end on channel (SIP/5050-085e6698) [Feb 1 10:06:30] DEBUG[17480]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085e6698 and SIP/1000-085f3690 [Feb 1 10:06:30] DEBUG[17480]: res_features.c:1039 ast_feature_interpret: Feature interpret: chan=SIP/5050-085e6698, peer=SIP/1000-085f3690, sense=1, features=2 [Feb 1 10:06:30] DEBUG[17480]: res_features.c:1499 ast_bridge_call: Set time limit to 5000 [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at 172.16.0.192 [Feb 1 10:06:30] DTMF[17480]: channel.c:2223 __ast_read: DTMF begin '7' received on SIP/5050-085e6698 [Feb 1 10:06:30] DEBUG[17480]: channel.c:3803 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-085e6698) [Feb 1 10:06:30] DEBUG[17480]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085e6698 and SIP/1000-085f3690 [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:30] DEBUG[17480]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at 172.16.0.192 [Feb 1 10:06:30] DTMF[17480]: channel.c:2203 __ast_read: DTMF end '7' received on SIP/5050-085e6698 [Feb 1 10:06:30] DEBUG[17480]: channel.c:3803 ast_generic_bridge: Got DTMF end on channel (SIP/5050-085e6698) [Feb 1 10:06:30] DEBUG[17480]: channel.c:4063 ast_channel_bridge: Bridge stops bridging channels SIP/5050-085e6698 and SIP/1000-085f3690 [Feb 1 10:06:30] DEBUG[17480]: res_features.c:1039 ast_feature_interpret: Feature interpret: chan=SIP/5050-085e6698, peer=SIP/1000-085f3690, sense=1, features=2 [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 172.16.0.192 [Feb 1 10:06:31] DTMF[17440]: channel.c:2223 __ast_read: DTMF begin '2' received on SIP/5050-085e6698 [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 172.16.0.192 [Feb 1 10:06:31] DTMF[17440]: channel.c:2203 __ast_read: DTMF end '2' received on SIP/5050-085e6698 [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 10:06:31] DEBUG[17440]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)