[Jun 25 16:32:24] Asterisk 11.4.0 built by root @ ubuntu on a x86_64 running Linux on 2013-06-25 21:26:18 UTC [Jun 25 16:32:24] DEBUG[8153] config.c: Parsing /etc/asterisk/logger.conf [Jun 25 16:32:24] VERBOSE[8153] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Jun 25 16:32:24] VERBOSE[8153] logger.c: Asterisk Queue Logger restarted [Jun 25 16:32:27] DEBUG[8133] chan_sip.c: = Looking for Call ID: cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 (Checking From) --From tag rJOUkTbjdN72FyIfEqvOrWZ1G4IxszH- --To-tag [Jun 25 16:32:27] DEBUG[8133] acl.c: For destination '10.24.18.16', our source address is '10.24.18.124'. [Jun 25 16:32:27] DEBUG[8133] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.24.18.124:5060 [Jun 25 16:32:27] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:27] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:27] DEBUG[8133] chan_sip.c: Allocating new SIP dialog for cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 - INVITE (No RTP) [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Found SIP option: -100rel- [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Matched SIP option: 100rel [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Found SIP option: -timer- [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Matched SIP option: timer [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jun 25 16:32:27] DEBUG[8133][C-00000000] sip/reqresp_parser.c: Matched SIP option: norefersub [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:27] DEBUG[8133] chan_sip.c: = Looking for Call ID: cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 (Checking From) --From tag rJOUkTbjdN72FyIfEqvOrWZ1G4IxszH- --To-tag as3105cc50 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Stopping retransmission on 'cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3' of Response 8409: Match Found [Jun 25 16:32:27] DEBUG[8133] chan_sip.c: = Looking for Call ID: cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 (Checking From) --From tag rJOUkTbjdN72FyIfEqvOrWZ1G4IxszH- --To-tag [Jun 25 16:32:27] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffe84038518' [Jun 25 16:32:27] DEBUG[8133][C-00000000] res_rtp_asterisk.c: Allocated port 11712 for RTP instance '0x7ffe84038518' [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: RTP instance '0x7ffe84038518' is setup and ready to go [Jun 25 16:32:27] DEBUG[8133][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffe84038518' [Jun 25 16:32:27] VERBOSE[8133][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP o=- 67567238 67567238 IN IP4 10.24.18.16... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.16' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.16' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.18.16... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 9 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 111 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 18 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 58 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 118 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 58 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Setting payload 96 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4019 IN IP4 10.24.18.16... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Jun 25 16:32:27] DEBUG[8133][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffe84038518' [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 0 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 8 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 9 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 18 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 58 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 96 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 111 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] rtp_engine.c: Copying payload 118 from 0x7ffec00e2fa0 to 0x7ffe840386e0 [Jun 25 16:32:27] DEBUG[8133][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffe84038518' [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Checking SIP call limits for device 6001 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Updating call counter for incoming call [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:27] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: This channel will not be able to handle video. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: build_route: Contact hop: "RustyONE" [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Incoming INVITE with 'timer' option supported [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: INVITE also has "Session-Expires" header. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Session-Expires: 1800 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: INVITE also has "Min-SE" header. [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Received Min-SE: 90 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Session timer started: 20 - cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: SIP/6001-00000000: New call is still down.... Trying... [Jun 25 16:32:27] DEBUG[8133][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:27] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jun 25 16:32:27] DEBUG[8125] chan_sip.c: Checking device state for peer 6001 [Jun 25 16:32:27] DEBUG[8125] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jun 25 16:32:27] DEBUG[8125] devicestate.c: device 'SIP/6001' state '1' [Jun 25 16:32:27] DEBUG[8176][C-00000000] pbx.c: Launching 'Goto' [Jun 25 16:32:27] VERBOSE[8176][C-00000000] pbx.c: -- Executing [600@internal:1] Goto("SIP/6001-00000000", "conferences,1000,1") in new stack [Jun 25 16:32:27] VERBOSE[8176][C-00000000] pbx.c: -- Goto (conferences,1000,1) [Jun 25 16:32:27] DEBUG[8176][C-00000000] pbx.c: Launching 'Answer' [Jun 25 16:32:27] VERBOSE[8176][C-00000000] pbx.c: -- Executing [1000@conferences:1] Answer("SIP/6001-00000000", "") in new stack [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: SIP answering channel: SIP/6001-00000000 [Jun 25 16:32:27] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 25 16:32:27] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jun 25 16:32:27] DEBUG[8125] chan_sip.c: Checking device state for peer 6001 [Jun 25 16:32:27] DEBUG[8125] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jun 25 16:32:27] DEBUG[8125] devicestate.c: device 'SIP/6001' state '1' [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: Setting framing from config on incoming call [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jun 25 16:32:27] DEBUG[8176][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:28] DEBUG[8176][C-00000000] res_rtp_asterisk.c: 0x7ffe8403ca60 -- Probation learning mode pass with source address 10.24.18.16:4018 [Jun 25 16:32:28] DEBUG[8176][C-00000000] pbx.c: Launching 'Playback' [Jun 25 16:32:28] VERBOSE[8176][C-00000000] pbx.c: -- Executing [1000@conferences:2] Playback("SIP/6001-00000000", "digits/0") in new stack [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format gsm [Jun 25 16:32:28] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jun 25 16:32:28] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:28] VERBOSE[8176][C-00000000] file.c: -- Playing 'digits/0.gsm' (language 'en') [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: = Looking for Call ID: cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 (Checking From) --From tag rJOUkTbjdN72FyIfEqvOrWZ1G4IxszH- --To-tag as51adf436 [Jun 25 16:32:28] DEBUG[8133][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 16:32:28] DEBUG[8133][C-00000000] chan_sip.c: Stopping retransmission on 'cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3' of Response 8410: Match Found [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: = Looking for Call ID: ZWiWe6NlLoD-FHbBo.6jipAUG9e7Cthi (Checking From) --From tag vyRlUVBE61D7U7YvBexMM.XANCYEv4GF --To-tag [Jun 25 16:32:28] DEBUG[8133] acl.c: For destination '10.24.18.16', our source address is '10.24.18.124'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.24.18.124:5060 [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Allocating new SIP dialog for ZWiWe6NlLoD-FHbBo.6jipAUG9e7Cthi - REGISTER (No RTP) [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: = Looking for Call ID: ZWiWe6NlLoD-FHbBo.6jipAUG9e7Cthi (Checking From) --From tag vyRlUVBE61D7U7YvBexMM.XANCYEv4GF --To-tag [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Store REGISTER's Contact header for call routing. [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:28] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jun 25 16:32:28] DEBUG[8125] chan_sip.c: Checking device state for peer 6001 [Jun 25 16:32:28] DEBUG[8125] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jun 25 16:32:28] DEBUG[8125] devicestate.c: device 'SIP/6001' state '1' [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: = Looking for Call ID: Pui7jhqx5yBBBuEe1pNbX-nMr0iKJdyM (Checking From) --From tag t-Ht2WHXWmivIauOVg1n4u6gMT8.PDS4 --To-tag [Jun 25 16:32:28] DEBUG[8133] acl.c: For destination '10.24.18.16', our source address is '10.24.18.124'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.24.18.124:5060 [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Allocating new SIP dialog for Pui7jhqx5yBBBuEe1pNbX-nMr0iKJdyM - SUBSCRIBE (No RTP) [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: build_route: Contact hop: "RustyONE" [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: = Looking for Call ID: Pui7jhqx5yBBBuEe1pNbX-nMr0iKJdyM (Checking From) --From tag t-Ht2WHXWmivIauOVg1n4u6gMT8.PDS4 --To-tag [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: build_route: Retaining previous route: [Jun 25 16:32:28] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:28] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:28] NOTICE[8133] chan_sip.c: Received SIP subscribe for peer without mailbox: 6001 [Jun 25 16:32:28] DEBUG[8133] chan_sip.c: Destroying SIP dialog Pui7jhqx5yBBBuEe1pNbX-nMr0iKJdyM [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format ulaw [Jun 25 16:32:28] DEBUG[8176][C-00000000] pbx.c: Launching 'Set' [Jun 25 16:32:28] VERBOSE[8176][C-00000000] pbx.c: -- Executing [1000@conferences:3] Set("SIP/6001-00000000", "CONFBRIDGE(user,admin)=yes") in new stack [Jun 25 16:32:28] DEBUG[8176][C-00000000] pbx.c: Launching 'Set' [Jun 25 16:32:28] VERBOSE[8176][C-00000000] pbx.c: -- Executing [1000@conferences:4] Set("SIP/6001-00000000", "CONFBRIDGE(user,marked)=yes") in new stack [Jun 25 16:32:28] DEBUG[8176][C-00000000] pbx.c: Launching 'ConfBridge' [Jun 25 16:32:28] VERBOSE[8176][C-00000000] pbx.c: -- Executing [1000@conferences:5] ConfBridge("SIP/6001-00000000", "1000") in new stack [Jun 25 16:32:28] DEBUG[8176][C-00000000] app_confbridge.c: Trying to find conference bridge '1000' [Jun 25 16:32:28] DEBUG[8176][C-00000000] bridging.c: Bridge technology simple_bridge does not have the capabilities we need. [Jun 25 16:32:28] DEBUG[8176][C-00000000] bridging.c: Bridge technology multiplexed_bridge does not have the capabilities we need. [Jun 25 16:32:28] DEBUG[8176][C-00000000] bridging.c: Chose bridge technology softmix [Jun 25 16:32:28] DEBUG[8176][C-00000000] bridging.c: Giving bridge technology softmix the bridge structure 0x7ffe3c0051d8 to setup [Jun 25 16:32:28] DEBUG[8176][C-00000000] app_confbridge.c: Created conference '1000' and linked to container. [Jun 25 16:32:28] DEBUG[8176][C-00000000] devicestate.c: device 'confbridge:1000' state '2' [Jun 25 16:32:28] DEBUG[8176][C-00000000] confbridge/conf_state.c: Changing conference '1000' state from EMPTY to SINGLE_MARKED [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format gsm [Jun 25 16:32:28] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:28] VERBOSE[8176][C-00000000] file.c: -- Playing 'conf-placeintoconf.gsm' (language 'en') [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: = Looking for Call ID: et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS (Checking From) --From tag GLD8tZS65IP8CnK8o-izjQNivnliUtZy --To-tag [Jun 25 16:32:31] DEBUG[8133] acl.c: For destination '10.24.18.138', our source address is '10.24.18.124'. [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.24.18.124:5060 [Jun 25 16:32:31] DEBUG[8133] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 25 16:32:31] DEBUG[8133] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: Allocating new SIP dialog for et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS - INVITE (No RTP) [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Found SIP option: -100rel- [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Matched SIP option: 100rel [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jun 25 16:32:31] DEBUG[8133][C-00000001] sip/reqresp_parser.c: Matched SIP option: norefersub [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.138:5060 [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: = Looking for Call ID: et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS (Checking From) --From tag GLD8tZS65IP8CnK8o-izjQNivnliUtZy --To-tag as3ed5a696 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Stopping retransmission on 'et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS' of Response 28884: Match Found [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: = Looking for Call ID: et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS (Checking From) --From tag GLD8tZS65IP8CnK8o-izjQNivnliUtZy --To-tag [Jun 25 16:32:31] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffe8405eae8' [Jun 25 16:32:31] DEBUG[8133][C-00000001] res_rtp_asterisk.c: Allocated port 12938 for RTP instance '0x7ffe8405eae8' [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: RTP instance '0x7ffe8405eae8' is setup and ready to go [Jun 25 16:32:31] DEBUG[8133][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffe8405eae8' [Jun 25 16:32:31] VERBOSE[8133][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP o=- 67567241 67567241 IN IP4 10.24.18.138... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.138' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.138' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.18.138... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 8 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 9 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 111 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 18 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 58 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 118 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 58 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Setting payload 96 based on m type on 0x7ffec00e2fa0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4055 IN IP4 10.24.18.138... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Jun 25 16:32:31] DEBUG[8133][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffe8405eae8' [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 0 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 8 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 9 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 18 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 58 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 96 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 111 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] rtp_engine.c: Copying payload 118 from 0x7ffec00e2fa0 to 0x7ffe8405ecb0 [Jun 25 16:32:31] DEBUG[8133][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffe8405eae8' [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Checking SIP call limits for device 6002 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Updating call counter for incoming call [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: Splitting '10.24.18.124' into... [Jun 25 16:32:31] DEBUG[8133][C-00000001] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: build_route: Contact hop: "RustyTWO" [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: INVITE also has "Session-Expires" header. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Session-Expires: 1800 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: INVITE also has "Min-SE" header. [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Received Min-SE: 90 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Session timer started: 30 - et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: SIP/6002-00000001: New call is still down.... Trying... [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.18.138:5060 [Jun 25 16:32:31] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jun 25 16:32:31] DEBUG[8125] chan_sip.c: Checking device state for peer 6002 [Jun 25 16:32:31] DEBUG[8125] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jun 25 16:32:31] DEBUG[8125] devicestate.c: device 'SIP/6002' state '1' [Jun 25 16:32:31] DEBUG[8177][C-00000001] pbx.c: Launching 'Goto' [Jun 25 16:32:31] VERBOSE[8177][C-00000001] pbx.c: -- Executing [601@internal:1] Goto("SIP/6002-00000001", "conferences,1001,1") in new stack [Jun 25 16:32:31] VERBOSE[8177][C-00000001] pbx.c: -- Goto (conferences,1001,1) [Jun 25 16:32:31] DEBUG[8177][C-00000001] pbx.c: Launching 'Playback' [Jun 25 16:32:31] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:1] Playback("SIP/6002-00000001", "digits/1") in new stack [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: SIP answering channel: SIP/6002-00000001 [Jun 25 16:32:31] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 25 16:32:31] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jun 25 16:32:31] DEBUG[8125] chan_sip.c: Checking device state for peer 6002 [Jun 25 16:32:31] DEBUG[8125] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jun 25 16:32:31] DEBUG[8125] devicestate.c: device 'SIP/6002' state '1' [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: Setting framing from config on incoming call [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jun 25 16:32:31] DEBUG[8177][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.138:5060 [Jun 25 16:32:31] DEBUG[8177][C-00000001] res_rtp_asterisk.c: 0x7ffe84063cf0 -- Probation learning mode pass with source address 10.24.18.138:4054 [Jun 25 16:32:31] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format gsm [Jun 25 16:32:31] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jun 25 16:32:31] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jun 25 16:32:31] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:31] VERBOSE[8177][C-00000001] file.c: -- Playing 'digits/1.gsm' (language 'en') [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format ulaw [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format gsm [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:31] VERBOSE[8176][C-00000000] file.c: -- Playing 'confbridge-join.gsm' (language 'en') [Jun 25 16:32:31] DEBUG[8133] chan_sip.c: = Looking for Call ID: et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS (Checking From) --From tag GLD8tZS65IP8CnK8o-izjQNivnliUtZy --To-tag as5f297974 [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 16:32:31] DEBUG[8133][C-00000001] chan_sip.c: Stopping retransmission on 'et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS' of Response 28885: Match Found [Jun 25 16:32:31] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format ulaw [Jun 25 16:32:31] DEBUG[8176][C-00000000] app_confbridge.c: Created a playback channel to conference bridge '1000' [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Joining bridge channel 0x7ffe3c005038 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Added channel Bridge/0x7ffe3c004f18-output(0x7ffe3c00d078) to bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has read format slin [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has write format slin [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c005038 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format gsm [Jun 25 16:32:31] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:31] VERBOSE[8176][C-00000000] file.c: -- Playing 'confbridge-join.gsm' (language 'en') [Jun 25 16:32:31] DEBUG[8179][C-00000000] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:31] DEBUG[8179][C-00000000] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:31] DEBUG[8179][C-00000000] bridging.c: Starting a bridge thread for bridge 0x7ffe3c0051d8 [Jun 25 16:32:31] DEBUG[8180][C-00000000] bridging.c: Started bridge thread for 0x7ffe3c0051d8 [Jun 25 16:32:31] DEBUG[8180][C-00000000] bridging.c: Launching bridge thread function 0x7ffe97a88659 for bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format ulaw [Jun 25 16:32:32] DEBUG[8177][C-00000001] pbx.c: Launching 'Set' [Jun 25 16:32:32] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:2] Set("SIP/6002-00000001", "CONFBRIDGE(user,marked)=no") in new stack [Jun 25 16:32:32] DEBUG[8177][C-00000001] pbx.c: Launching 'Set' [Jun 25 16:32:32] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:3] Set("SIP/6002-00000001", "CONFBRIDGE(user,end_marked)=yes") in new stack [Jun 25 16:32:32] DEBUG[8177][C-00000001] pbx.c: Launching 'Set' [Jun 25 16:32:32] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:4] Set("SIP/6002-00000001", "CONFBRIDGE(user,wait_marked)=yes") in new stack [Jun 25 16:32:32] DEBUG[8177][C-00000001] pbx.c: Launching 'ConfBridge' [Jun 25 16:32:32] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:5] ConfBridge("SIP/6002-00000001", "1000") in new stack [Jun 25 16:32:32] DEBUG[8177][C-00000001] app_confbridge.c: Trying to find conference bridge '1000' [Jun 25 16:32:32] DEBUG[8177][C-00000001] confbridge/conf_state.c: Changing conference '1000' state from SINGLE_MARKED to MULTI_MARKED [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format gsm [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:32] VERBOSE[8177][C-00000001] file.c: -- Playing 'confbridge-join.gsm' (language 'en') [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format slin [Jun 25 16:32:32] DEBUG[8176][C-00000000] app_confbridge.c: Departing underlying channel 'Bridge/0x7ffe3c004f18-output' from bridge '0x7ffe3c0051d8' [Jun 25 16:32:32] DEBUG[8179][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c005038 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8179][C-00000000] bridging.c: Removed channel 0x7ffe3c00d078 from bridge array on 0x7ffe3c0051d8, new count is 0 [Jun 25 16:32:32] DEBUG[8180][C-00000000] bridging.c: Ending bridge thread for 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Joining bridge channel 0x7ffe3c004fd8 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Added channel SIP/6001-00000000(0x7ffe8403f698) to bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Bridge technology softmix wants to read any of formats (slin) but channel has ulaw [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to read format slin [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 put channel SIP/6001-00000000 into read format slin [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Bridge technology softmix wants to write any of formats (slin) but channel has ulaw [Jun 25 16:32:32] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format slin [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 put channel SIP/6001-00000000 into write format slin [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c004fd8 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8176][C-00000000] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:32] DEBUG[8176][C-00000000] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:32] DEBUG[8176][C-00000000] bridging.c: Starting a bridge thread for bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8181][C-00000000] bridging.c: Started bridge thread for 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8181][C-00000000] bridging.c: Launching bridge thread function 0x7ffe97a88659 for bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Difference is 3072, ms is 404 [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format ulaw [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Joining bridge channel 0x7ffe48001098 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Added channel Bridge/0x7ffe3c004f18-output(0x7ffe3c00d078) to bridge array on 0x7ffe3c0051d8, new count is 2 [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has read format slin [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has write format slin [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001098 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format gsm [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:32] VERBOSE[8177][C-00000001] file.c: -- Playing 'confbridge-join.gsm' (language 'en') [Jun 25 16:32:32] DEBUG[8182][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:32] DEBUG[8182][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format slin [Jun 25 16:32:32] DEBUG[8177][C-00000001] app_confbridge.c: Departing underlying channel 'Bridge/0x7ffe3c004f18-output' from bridge '0x7ffe3c0051d8' [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001098 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8182][C-00000001] bridging.c: Removed channel 0x7ffe3c00d078 from bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Joining bridge channel 0x7ffe48001098 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Added channel SIP/6002-00000001(0x7ffe840670e8) to bridge array on 0x7ffe3c0051d8, new count is 2 [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Bridge technology softmix wants to read any of formats (slin) but channel has ulaw [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to read format slin [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 put channel SIP/6002-00000001 into read format slin [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Bridge technology softmix wants to write any of formats (slin) but channel has ulaw [Jun 25 16:32:32] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format slin [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 put channel SIP/6002-00000001 into write format slin [Jun 25 16:32:32] DEBUG[8177][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001098 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:32] DEBUG[8177][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:32] DEBUG[8177][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:32] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Difference is 3176, ms is 417 [Jun 25 16:32:33] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 25 16:32:36] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 25 16:32:37] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jun 25 16:32:37] DEBUG[8133] chan_sip.c: = Looking for Call ID: cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 (Checking From) --From tag rJOUkTbjdN72FyIfEqvOrWZ1G4IxszH- --To-tag as51adf436 [Jun 25 16:32:37] DEBUG[8133][C-00000000] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 25 16:32:37] DEBUG[8133][C-00000000] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 25 16:32:37] DEBUG[8133][C-00000000] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 25 16:32:37] DEBUG[8133][C-00000000] chan_sip.c: Setting SIP_ALREADYGONE on dialog cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 [Jun 25 16:32:37] DEBUG[8133][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffe84038518' [Jun 25 16:32:37] DEBUG[8133][C-00000000] chan_sip.c: Session timer stopped: 20 - cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 [Jun 25 16:32:37] DEBUG[8133][C-00000000] chan_sip.c: Received bye, issuing owner hangup [Jun 25 16:32:37] DEBUG[8133][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.16:5060 [Jun 25 16:32:37] DEBUG[8176][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c004fd8 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:37] DEBUG[8176][C-00000000] bridging.c: Removed channel 0x7ffe8403f698 from bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:37] DEBUG[8176][C-00000000] bridging.c: Bridge is returning 0x7ffe3c004fd8 to read format ulaw(100003) [Jun 25 16:32:37] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to read format ulaw [Jun 25 16:32:37] DEBUG[8176][C-00000000] bridging.c: Bridge is returning 0x7ffe3c004fd8 to write format ulaw(100003) [Jun 25 16:32:37] DEBUG[8176][C-00000000] channel.c: Set channel SIP/6001-00000000 to write format ulaw [Jun 25 16:32:37] DEBUG[8183][C-00000000] bridging.c: Joining bridge channel 0x7ffe3c014508 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:37] DEBUG[8183][C-00000000] bridging.c: Added channel Bridge/0x7ffe3c004f18-output(0x7ffe3c00d078) to bridge array on 0x7ffe3c0051d8, new count is 2 [Jun 25 16:32:37] DEBUG[8183][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has read format slin [Jun 25 16:32:37] DEBUG[8183][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has write format slin [Jun 25 16:32:37] DEBUG[8183][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c014508 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:37] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format gsm [Jun 25 16:32:37] DEBUG[8183][C-00000000] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:37] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:37] VERBOSE[8176][C-00000000] file.c: -- Playing 'confbridge-leave.gsm' (language 'en') [Jun 25 16:32:37] DEBUG[8183][C-00000000] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format slin [Jun 25 16:32:38] DEBUG[8176][C-00000000] app_confbridge.c: Departing underlying channel 'Bridge/0x7ffe3c004f18-output' from bridge '0x7ffe3c0051d8' [Jun 25 16:32:38] DEBUG[8183][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c014508 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:38] DEBUG[8183][C-00000000] bridging.c: Removed channel 0x7ffe3c00d078 from bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:38] DEBUG[8184][C-00000000] bridging.c: Joining bridge channel 0x7ffe3c014ff8 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:38] DEBUG[8184][C-00000000] bridging.c: Added channel Bridge/0x7ffe3c004f18-output(0x7ffe3c00d078) to bridge array on 0x7ffe3c0051d8, new count is 2 [Jun 25 16:32:38] DEBUG[8184][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has read format slin [Jun 25 16:32:38] DEBUG[8184][C-00000000] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has write format slin [Jun 25 16:32:38] DEBUG[8184][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c014ff8 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format gsm [Jun 25 16:32:38] DEBUG[8184][C-00000000] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:38] DEBUG[8184][C-00000000] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:38] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:38] VERBOSE[8176][C-00000000] file.c: -- Playing 'conf-leaderhasleft.gsm' (language 'en') [Jun 25 16:32:38] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format slin [Jun 25 16:32:40] DEBUG[8176][C-00000000] app_confbridge.c: Departing underlying channel 'Bridge/0x7ffe3c004f18-output' from bridge '0x7ffe3c0051d8' [Jun 25 16:32:40] DEBUG[8184][C-00000000] bridging.c: Giving bridge technology softmix notification that 0x7ffe3c014ff8 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:40] DEBUG[8184][C-00000000] bridging.c: Removed channel 0x7ffe3c00d078 from bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:40] DEBUG[8176][C-00000000] confbridge/conf_state.c: Changing conference '1000' state from MULTI_MARKED to SINGLE [Jun 25 16:32:40] DEBUG[8176][C-00000000] pbx.c: Extension 1000, priority 5 returned normally even though call was hung up [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Soft-Hanging up channel 'SIP/6001-00000000' [Jun 25 16:32:40] DEBUG[8177][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001098 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:40] DEBUG[8177][C-00000001] bridging.c: Removed channel 0x7ffe840670e8 from bridge array on 0x7ffe3c0051d8, new count is 0 [Jun 25 16:32:40] DEBUG[8177][C-00000001] bridging.c: Bridge is returning 0x7ffe48001098 to read format ulaw(100003) [Jun 25 16:32:40] DEBUG[8176][C-00000000] channel.c: Hanging up channel 'SIP/6001-00000000' [Jun 25 16:32:40] DEBUG[8176][C-00000000] chan_sip.c: Hangup call SIP/6001-00000000, SIP callid cbaRjiZl1j6woNLT.iYS.bBEiJqCJ-O3 [Jun 25 16:32:40] DEBUG[8176][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffe84038518' [Jun 25 16:32:40] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to read format ulaw [Jun 25 16:32:40] DEBUG[8177][C-00000001] bridging.c: Bridge is returning 0x7ffe48001098 to write format ulaw(100003) [Jun 25 16:32:40] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jun 25 16:32:40] DEBUG[8125] chan_sip.c: Checking device state for peer 6001 [Jun 25 16:32:40] DEBUG[8125] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jun 25 16:32:40] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format ulaw [Jun 25 16:32:40] DEBUG[8125] devicestate.c: device 'SIP/6001' state '1' [Jun 25 16:32:40] DEBUG[8185][C-00000001] bridging.c: Joining bridge channel 0x7ffe48001a08 to bridge 0x7ffe3c0051d8 [Jun 25 16:32:40] DEBUG[8185][C-00000001] bridging.c: Added channel Bridge/0x7ffe3c004f18-output(0x7ffe3c00d078) to bridge array on 0x7ffe3c0051d8, new count is 1 [Jun 25 16:32:40] DEBUG[8185][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has read format slin [Jun 25 16:32:40] DEBUG[8185][C-00000001] bridging.c: Bridge 0x7ffe3c0051d8 is happy that channel Bridge/0x7ffe3c004f18-output already has write format slin [Jun 25 16:32:40] DEBUG[8185][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001a08 is joining bridge 0x7ffe3c0051d8 [Jun 25 16:32:40] DEBUG[8177][C-00000001] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format gsm [Jun 25 16:32:40] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:40] VERBOSE[8177][C-00000001] file.c: -- Playing 'confbridge-leave.gsm' (language 'en') [Jun 25 16:32:40] DEBUG[8185][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jun 25 16:32:40] DEBUG[8185][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Set channel Bridge/0x7ffe3c004f18-input to write format slin [Jun 25 16:32:41] DEBUG[8177][C-00000001] app_confbridge.c: Departing underlying channel 'Bridge/0x7ffe3c004f18-output' from bridge '0x7ffe3c0051d8' [Jun 25 16:32:41] DEBUG[8185][C-00000001] bridging.c: Giving bridge technology softmix notification that 0x7ffe48001a08 is leaving bridge 0x7ffe3c0051d8 [Jun 25 16:32:41] DEBUG[8185][C-00000001] bridging.c: Removed channel 0x7ffe3c00d078 from bridge array on 0x7ffe3c0051d8, new count is 0 [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format gsm [Jun 25 16:32:41] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Difference is 2992, ms is 394 [Jun 25 16:32:41] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 25 16:32:41] VERBOSE[8177][C-00000001] file.c: -- Playing 'conf-kicked.gsm' (language 'en') [Jun 25 16:32:41] DEBUG[8181][C-00000000] bridging.c: Ending bridge thread for 0x7ffe3c0051d8 [Jun 25 16:32:43] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Set channel SIP/6002-00000001 to write format ulaw [Jun 25 16:32:43] DEBUG[8177][C-00000001] pbx.c: Launching 'Hangup' [Jun 25 16:32:43] VERBOSE[8177][C-00000001] pbx.c: -- Executing [1001@conferences:6] Hangup("SIP/6002-00000001", "") in new stack [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Soft-Hanging up channel 'SIP/6002-00000001' [Jun 25 16:32:43] DEBUG[8177][C-00000001] pbx.c: Spawn extension (conferences,1001,6) exited non-zero on 'SIP/6002-00000001' [Jun 25 16:32:43] VERBOSE[8177][C-00000001] pbx.c: == Spawn extension (conferences, 1001, 6) exited non-zero on 'SIP/6002-00000001' [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Soft-Hanging up channel 'SIP/6002-00000001' [Jun 25 16:32:43] DEBUG[8177][C-00000001] channel.c: Hanging up channel 'SIP/6002-00000001' [Jun 25 16:32:43] DEBUG[8177][C-00000001] chan_sip.c: Hangup call SIP/6002-00000001, SIP callid et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS [Jun 25 16:32:43] DEBUG[8177][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffe8405eae8' [Jun 25 16:32:43] DEBUG[8177][C-00000001] chan_sip.c: Session timer stopped: 30 - et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS [Jun 25 16:32:43] DEBUG[8177][C-00000001] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 25 16:32:43] DEBUG[8177][C-00000001] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 25 16:32:43] DEBUG[8177][C-00000001] chan_sip.c: Trying to put 'BYE sip:600' onto UDP socket destined for 10.24.18.138:5060 [Jun 25 16:32:43] DEBUG[8125] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jun 25 16:32:43] DEBUG[8125] chan_sip.c: Checking device state for peer 6002 [Jun 25 16:32:43] DEBUG[8125] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jun 25 16:32:43] DEBUG[8125] devicestate.c: device 'SIP/6002' state '1' [Jun 25 16:32:43] DEBUG[8133] chan_sip.c: = Looking for Call ID: et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS (Checking To) --From tag as5f297974 --To-tag GLD8tZS65IP8CnK8o-izjQNivnliUtZy [Jun 25 16:32:43] DEBUG[8133][C-00000001] chan_sip.c: Stopping retransmission on 'et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS' of Request 102: Match Found [Jun 25 16:32:43] DEBUG[8133] chan_sip.c: Destroying SIP dialog et7rJ66ECh0ivZpqvCwk2kfYRUrOQXqS [Jun 25 16:32:43] DEBUG[8133] rtp_engine.c: Destroyed RTP instance '0x7ffe8405eae8' [Jun 25 16:32:44] DEBUG[8133] chan_sip.c: = Looking for Call ID: 12c3731b4f6373ec3ffcfbf653082355@0:0:0:0:0:0:0:0 (Checking From) --From tag 70408ac --To-tag [Jun 25 16:32:44] DEBUG[8133] acl.c: For destination '127.0.0.1', our source address is '127.0.0.1'. [Jun 25 16:32:44] DEBUG[8133] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 127.0.0.1:5060 [Jun 25 16:32:44] DEBUG[8133] netsock2.c: Splitting '127.0.0.1:27816' into... [Jun 25 16:32:44] DEBUG[8133] netsock2.c: ...host '127.0.0.1' and port '27816'. [Jun 25 16:32:44] DEBUG[8133] chan_sip.c: Allocating new SIP dialog for 12c3731b4f6373ec3ffcfbf653082355@0:0:0:0:0:0:0:0 - OPTIONS (No RTP) [Jun 25 16:32:44] DEBUG[8133] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 25 16:32:44] DEBUG[8133] netsock2.c: Splitting '127.0.0.1' into... [Jun 25 16:32:44] DEBUG[8133] netsock2.c: ...host '127.0.0.1' and port ''. [Jun 25 16:32:44] DEBUG[8133] netsock2.c: Splitting '127.0.0.1' into... [Jun 25 16:32:44] DEBUG[8133] netsock2.c: ...host '127.0.0.1' and port ''. [Jun 25 16:32:44] DEBUG[8133] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 127.0.0.1:27816 [Jun 25 16:32:48] DEBUG[8133] chan_sip.c: Auto destroying SIP dialog 'FDmObRYTNlx04Dzob9ynzfFL7G3I9XHh' [Jun 25 16:32:48] DEBUG[8133] chan_sip.c: Destroying SIP dialog FDmObRYTNlx04Dzob9ynzfFL7G3I9XHh [Jun 25 16:32:51] DEBUG[8133] chan_sip.c: Auto destroying SIP dialog '98abc62ca1f45030f83f6577e4d89301@0:0:0:0:0:0:0:0' [Jun 25 16:32:51] DEBUG[8133] chan_sip.c: Destroying SIP dialog 98abc62ca1f45030f83f6577e4d89301@0:0:0:0:0:0:0:0 [Jun 25 16:32:51] DEBUG[8133] chan_sip.c: Auto destroying SIP dialog 'f73b82472967c88e85619b2cbe76fdd4@0:0:0:0:0:0:0:0' [Jun 25 16:32:51] DEBUG[8133] chan_sip.c: Destroying SIP dialog f73b82472967c88e85619b2cbe76fdd4@0:0:0:0:0:0:0:0