[Oct 14 13:17:30] Asterisk SVN-trunk-r400855M built by root @ on a i686 running Linux on 2013-09-12 17:44:53 UTC [Oct 14 13:17:30] VERBOSE[32301] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Oct 14 13:17:30] VERBOSE[32301] logger.c: Asterisk Queue Logger restarted [Oct 14 13:17:36] Asterisk SVN-trunk-r400855M built by root @ on a i686 running Linux on 2013-09-12 17:44:53 UTC [Oct 14 13:17:36] DEBUG[32301] config.c: Parsing /etc/asterisk/logger.conf [Oct 14 13:17:36] VERBOSE[32301] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Oct 14 13:17:36] VERBOSE[32301] logger.c: Asterisk Queue Logger restarted [Oct 14 13:17:47] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe - REGISTER (No RTP) [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: build_path: do not use Path headers [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:17:47] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_A [Oct 14 13:17:47] DEBUG[32162] chan_sip.c: Checking device state for peer phone_A [Oct 14 13:17:47] DEBUG[32162] devicestate.c: Changing state for SIP/phone_A - state 1 (Not in use) [Oct 14 13:17:47] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_A' [Oct 14 13:17:47] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_A' [Oct 14 13:17:47] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_A' [Oct 14 13:17:47] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_A' has changed to 'Not in use' [Oct 14 13:17:47] DEBUG[32274] app_queue.c: Device 'SIP/phone_A' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 14 13:17:47] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for SdydP3MU7MoXRE3ybc8hACM50mkJwL.k - SUBSCRIBE (No RTP) [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_A" [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:17:47] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_A [Oct 14 13:17:47] DEBUG[32212] chan_sip.c: Destroying SIP dialog SdydP3MU7MoXRE3ybc8hACM50mkJwL.k [Oct 14 13:18:03] DEBUG[32310] http.c: HTTP Request URI is /ari/events?app=Bridge&api_key=admin%3Asecret [Oct 14 13:18:03] DEBUG[32310] http.c: match request [ari/events] with handler [httpstatus] len 10 [Oct 14 13:18:03] DEBUG[32310] http.c: match request [ari/events] with handler [phoneprov] len 9 [Oct 14 13:18:03] DEBUG[32310] http.c: match request [ari/events] with handler [static] len 6 [Oct 14 13:18:03] DEBUG[32310] http.c: match request [ari/events] with handler [ari] len 3 [Oct 14 13:18:03] DEBUG[32310] http.c: Match made with [ari] [Oct 14 13:18:03] DEBUG[32310] res_ari.c: Finding handler for events [Oct 14 13:18:03] DEBUG[32310] res_ari.c: Checking endpoints [Oct 14 13:18:03] DEBUG[32310] res_ari.c: Checking channels [Oct 14 13:18:03] DEBUG[32310] res_ari.c: Checking events [Oct 14 13:18:03] DEBUG[32310] res_ari.c: Got it! [Oct 14 13:18:03] VERBOSE[32310] res_http_websocket.c: == WebSocket connection from '127.0.0.1:38130' for protocol '' accepted using version '13' [Oct 14 13:18:03] DEBUG[32310] ari/resource_events.c: /events WebSocket connection [Oct 14 13:18:03] VERBOSE[32310] stasis/app.c: Creating Stasis app 'Bridge' [Oct 14 13:18:07] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa - REGISTER (No RTP) [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: build_path: do not use Path headers [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:18:07] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_B [Oct 14 13:18:07] DEBUG[32162] chan_sip.c: Checking device state for peer phone_B [Oct 14 13:18:07] DEBUG[32162] devicestate.c: Changing state for SIP/phone_B - state 1 (Not in use) [Oct 14 13:18:07] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_B' [Oct 14 13:18:07] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:07] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:07] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_B' has changed to 'Not in use' [Oct 14 13:18:07] DEBUG[32274] app_queue.c: Device 'SIP/phone_B' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 14 13:18:07] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for KInNq-OjcA8edaEt61Hs.U.u.HHdOOh0 - SUBSCRIBE (No RTP) [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_B" [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:18:07] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_B [Oct 14 13:18:07] DEBUG[32212] chan_sip.c: Destroying SIP dialog KInNq-OjcA8edaEt61Hs.U.u.HHdOOh0 [Oct 14 13:18:15] DEBUG[32212] logger.c: CALL_ID [C-00000000] created by thread. [Oct 14 13:18:15] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:18:15] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:18:15] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for af8sfPbTwlfrPaVDz7G5NYV4hISmNAyX - INVITE (No RTP) [Oct 14 13:18:15] DEBUG[32212][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Found SIP option: -timer- [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Matched SIP option: timer [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Found SIP option: -norefersub- [Oct 14 13:18:15] DEBUG[32212][C-00000000] sip/reqresp_parser.c: Matched SIP option: norefersub [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb2d50b74' [Oct 14 13:18:15] DEBUG[32212][C-00000000] res_rtp_asterisk.c: Allocated port 11618 for RTP instance '0xb2d50b74' [Oct 14 13:18:15] DEBUG[32212][C-00000000] pjsip: icess0xb2d57a2 ICE session created, comp_cnt=2, role is Unknown agent [Oct 14 13:18:15] DEBUG[32212][C-00000000] pjsip: icess0xb2d57a2 Candidate 0 added: comp_id=1, type=host, foundation=Ha1812a1, addr=10.24.18.161:11618, base=10.24.18.161:11618, prio=0x7effffff (2130706431) [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: RTP instance '0xb2d50b74' is setup and ready to go [Oct 14 13:18:15] DEBUG[32212][C-00000000] pjsip: icess0xb2d57a2 Destroying ICE session 0xb2d57a2c [Oct 14 13:18:15] DEBUG[32212][C-00000000] pjsip: ice_session.c ICE session 0xb2d57a2c destroyed [Oct 14 13:18:15] DEBUG[32212][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb2d50b74' [Oct 14 13:18:15] VERBOSE[32212][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP o=- 77145985 77145985 IN IP4 10.24.19.97... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.19.97... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 111 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 18 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 58 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 118 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 9 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 58 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Setting payload 96 based on m type on 0xb3146c78 [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4057 IN IP4 10.24.19.97... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Oct 14 13:18:15] DEBUG[32212][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb2d50b74' [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 0 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 8 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 9 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 18 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 58 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 96 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 111 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] rtp_engine.c: Copying payload 118 from 0xb3146c78 to 0xb2d50c9c [Oct 14 13:18:15] DEBUG[32212][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb2d50b74' [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Checking SIP call limits for device phone_A [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Updating call counter for incoming call [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: This channel will not be able to handle video. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: build_route: Contact hop: "phone_A" [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Incoming INVITE with 'timer' option supported [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: INVITE also has "Session-Expires" header. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Session-Expires: 1800 [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: INVITE also has "Min-SE" header. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Received Min-SE: 90 [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Session timer started: 11 - af8sfPbTwlfrPaVDz7G5NYV4hISmNAyX 900000ms [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: SIP/phone_A-00000000: New call is still down.... Trying... [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:18:15] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_A [Oct 14 13:18:15] DEBUG[32162] chan_sip.c: Checking device state for peer phone_A [Oct 14 13:18:15] DEBUG[32162] devicestate.c: Changing state for SIP/phone_A - state 1 (Not in use) [Oct 14 13:18:15] DEBUG[32212][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread. [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32316][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_A' has not changed from 'Not in use' [Oct 14 13:18:15] DEBUG[32316][C-00000000] pbx.c: Launching 'NoOp' [Oct 14 13:18:15] VERBOSE[32316][C-00000000] pbx.c: -- Executing [201@internal:1] NoOp("SIP/phone_A-00000000", "") in new stack [Oct 14 13:18:15] DEBUG[32316][C-00000000] pbx.c: Launching 'Answer' [Oct 14 13:18:15] VERBOSE[32316][C-00000000] pbx.c: -- Executing [201@internal:2] Answer("SIP/phone_A-00000000", "") in new stack [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: SIP answering channel: SIP/phone_A-00000000 [Oct 14 13:18:15] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_A [Oct 14 13:18:15] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 14 13:18:15] DEBUG[32162] chan_sip.c: Checking device state for peer phone_A [Oct 14 13:18:15] DEBUG[32162] devicestate.c: Changing state for SIP/phone_A - state 1 (Not in use) [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: Setting framing from config on incoming call [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_A' [Oct 14 13:18:15] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_A' has not changed from 'Not in use' [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 14 13:18:15] DEBUG[32316][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:18:15] DEBUG[32316][C-00000000] res_rtp_asterisk.c: 0xb2d55090 -- Probation learning mode pass with source address 10.24.19.97:4056 [Oct 14 13:18:15] DEBUG[32316][C-00000000] pbx.c: Launching 'Stasis' [Oct 14 13:18:15] VERBOSE[32316][C-00000000] pbx.c: -- Executing [201@internal:3] Stasis("SIP/phone_A-00000000", "Bridge") in new stack [Oct 14 13:18:15] DEBUG[32212][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 14 13:18:15] DEBUG[32212][C-00000000] chan_sip.c: Stopping retransmission on 'af8sfPbTwlfrPaVDz7G5NYV4hISmNAyX' of Response 9140: Match Found [Oct 14 13:18:15] DEBUG[32212][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread. [Oct 14 13:18:18] DEBUG[32212] logger.c: CALL_ID [C-00000001] created by thread. [Oct 14 13:18:18] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:18:18] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:18:18] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for .bvBPVmXunZ8T48yGtHjKayxdKrK1S1X - INVITE (No RTP) [Oct 14 13:18:18] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Found SIP option: -norefersub- [Oct 14 13:18:18] DEBUG[32212][C-00000001] sip/reqresp_parser.c: Matched SIP option: norefersub [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x965bddc' [Oct 14 13:18:18] DEBUG[32212][C-00000001] res_rtp_asterisk.c: Allocated port 17816 for RTP instance '0x965bddc' [Oct 14 13:18:18] DEBUG[32212][C-00000001] pjsip: icess0x9631e8c ICE session created, comp_cnt=2, role is Unknown agent [Oct 14 13:18:18] DEBUG[32212][C-00000001] pjsip: icess0x9631e8c Candidate 0 added: comp_id=1, type=host, foundation=Ha1812a1, addr=10.24.18.161:17816, base=10.24.18.161:17816, prio=0x7effffff (2130706431) [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: RTP instance '0x965bddc' is setup and ready to go [Oct 14 13:18:18] DEBUG[32212][C-00000001] pjsip: icess0x9631e8c Destroying ICE session 0x9631e8c [Oct 14 13:18:18] DEBUG[32212][C-00000001] pjsip: ice_session.c ICE session 0x9631e8c destroyed [Oct 14 13:18:18] DEBUG[32212][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x965bddc' [Oct 14 13:18:18] VERBOSE[32212][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP o=- 77145988 77145988 IN IP4 10.24.18.165... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.18.165... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 8 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 9 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 111 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 18 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 58 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 118 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 58 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Setting payload 96 based on m type on 0xb3146c78 [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4039 IN IP4 10.24.18.165... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Oct 14 13:18:18] DEBUG[32212][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x965bddc' [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 0 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 8 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 9 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 18 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 58 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 96 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 111 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] rtp_engine.c: Copying payload 118 from 0xb3146c78 to 0x965bf04 [Oct 14 13:18:18] DEBUG[32212][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x965bddc' [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Checking SIP call limits for device phone_B [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Updating call counter for incoming call [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: This channel will not be able to handle video. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: build_route: Contact hop: "phone_B" [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: INVITE also has "Session-Expires" header. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Session-Expires: 1800 [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: INVITE also has "Min-SE" header. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Received Min-SE: 90 [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Session timer started: 15 - .bvBPVmXunZ8T48yGtHjKayxdKrK1S1X 900000ms [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: SIP/phone_B-00000001: New call is still down.... Trying... [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:18:18] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] being removed from thread. [Oct 14 13:18:18] DEBUG[32317][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:18:18] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_B [Oct 14 13:18:18] DEBUG[32317][C-00000001] pbx.c: Launching 'NoOp' [Oct 14 13:18:18] DEBUG[32162] chan_sip.c: Checking device state for peer phone_B [Oct 14 13:18:18] DEBUG[32162] devicestate.c: Changing state for SIP/phone_B - state 1 (Not in use) [Oct 14 13:18:18] VERBOSE[32317][C-00000001] pbx.c: -- Executing [201@internal:1] NoOp("SIP/phone_B-00000001", "") in new stack [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32317][C-00000001] pbx.c: Launching 'Answer' [Oct 14 13:18:18] VERBOSE[32317][C-00000001] pbx.c: -- Executing [201@internal:2] Answer("SIP/phone_B-00000001", "") in new stack [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_B' has not changed from 'Not in use' [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: SIP answering channel: SIP/phone_B-00000001 [Oct 14 13:18:18] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 14 13:18:18] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_B [Oct 14 13:18:18] DEBUG[32162] chan_sip.c: Checking device state for peer phone_B [Oct 14 13:18:18] DEBUG[32162] devicestate.c: Changing state for SIP/phone_B - state 1 (Not in use) [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: Setting framing from config on incoming call [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_B' [Oct 14 13:18:18] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_B' has not changed from 'Not in use' [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 14 13:18:18] DEBUG[32317][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:18:18] DEBUG[32317][C-00000001] res_rtp_asterisk.c: 0x971bed8 -- Probation learning mode pass with source address 10.24.18.165:4038 [Oct 14 13:18:18] DEBUG[32317][C-00000001] pbx.c: Launching 'Stasis' [Oct 14 13:18:18] VERBOSE[32317][C-00000001] pbx.c: -- Executing [201@internal:3] Stasis("SIP/phone_B-00000001", "Bridge") in new stack [Oct 14 13:18:18] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 14 13:18:18] DEBUG[32212][C-00000001] chan_sip.c: Stopping retransmission on '.bvBPVmXunZ8T48yGtHjKayxdKrK1S1X' of Response 5443: Match Found [Oct 14 13:18:18] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] being removed from thread. [Oct 14 13:18:19] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:19] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:19] DEBUG[32212] chan_sip.c: Auto destroying SIP dialog 'wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe' [Oct 14 13:18:19] DEBUG[32212] chan_sip.c: Destroying SIP dialog wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe [Oct 14 13:18:24] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:24] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:26] DEBUG[32175] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:26] DEBUG[32176] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:26] DEBUG[32177] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:26] DEBUG[32178] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:26] DEBUG[32172] threadpool.c: Destroying worker thread 1 [Oct 14 13:18:26] DEBUG[32172] threadpool.c: Destroying worker thread 2 [Oct 14 13:18:26] DEBUG[32172] threadpool.c: Destroying worker thread 3 [Oct 14 13:18:26] DEBUG[32172] threadpool.c: Destroying worker thread 4 [Oct 14 13:18:26] DEBUG[32179] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:26] DEBUG[32153] threadpool.c: Destroying worker thread 5 [Oct 14 13:18:27] DEBUG[32174] threadpool.c: Worker thread idle timeout reached. Dying. [Oct 14 13:18:27] DEBUG[32172] threadpool.c: Destroying worker thread 0 [Oct 14 13:18:29] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:29] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:34] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:34] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:39] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:39] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:39] DEBUG[32212] chan_sip.c: Auto destroying SIP dialog 'NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa' [Oct 14 13:18:39] DEBUG[32212] chan_sip.c: Destroying SIP dialog NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa [Oct 14 13:18:44] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:44] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:49] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:49] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:52] DEBUG[32320] http.c: HTTP Request URI is /ari/channels?api_key=admin%3Asecret [Oct 14 13:18:52] DEBUG[32320] http.c: match request [ari/channels] with handler [httpstatus] len 10 [Oct 14 13:18:52] DEBUG[32320] http.c: match request [ari/channels] with handler [phoneprov] len 9 [Oct 14 13:18:52] DEBUG[32320] http.c: match request [ari/channels] with handler [static] len 6 [Oct 14 13:18:52] DEBUG[32320] http.c: match request [ari/channels] with handler [ari] len 3 [Oct 14 13:18:52] DEBUG[32320] http.c: Match made with [ari] [Oct 14 13:18:52] DEBUG[32320] res_ari.c: Finding handler for channels [Oct 14 13:18:52] DEBUG[32320] res_ari.c: Checking endpoints [Oct 14 13:18:52] DEBUG[32320] res_ari.c: Checking channels [Oct 14 13:18:52] DEBUG[32320] res_ari.c: Got it! [Oct 14 13:18:52] DEBUG[32322] http.c: HTTP Request URI is /ari/channels?api_key=admin%3Asecret [Oct 14 13:18:52] DEBUG[32322] http.c: match request [ari/channels] with handler [httpstatus] len 10 [Oct 14 13:18:52] DEBUG[32322] http.c: match request [ari/channels] with handler [phoneprov] len 9 [Oct 14 13:18:52] DEBUG[32322] http.c: match request [ari/channels] with handler [static] len 6 [Oct 14 13:18:52] DEBUG[32322] http.c: match request [ari/channels] with handler [ari] len 3 [Oct 14 13:18:52] DEBUG[32322] http.c: Match made with [ari] [Oct 14 13:18:52] DEBUG[32322] res_ari.c: Finding handler for channels [Oct 14 13:18:52] DEBUG[32322] res_ari.c: Checking endpoints [Oct 14 13:18:52] DEBUG[32322] res_ari.c: Checking channels [Oct 14 13:18:52] DEBUG[32322] res_ari.c: Got it! [Oct 14 13:18:54] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:54] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:59] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:18:59] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:04] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:04] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:09] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for Z0LujM83oRc6BlBeJE9zf2DesacLn4NM - SUBSCRIBE (No RTP) [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_B" [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:19:09] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_B [Oct 14 13:19:09] DEBUG[32212] chan_sip.c: Destroying SIP dialog Z0LujM83oRc6BlBeJE9zf2DesacLn4NM [Oct 14 13:19:09] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:09] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:13] DEBUG[32324] http.c: HTTP Request URI is /ari/bridges?type=mixing&api_key=admin%3Asecret [Oct 14 13:19:13] DEBUG[32324] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [Oct 14 13:19:13] DEBUG[32324] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [Oct 14 13:19:13] DEBUG[32324] http.c: match request [ari/bridges] with handler [static] len 6 [Oct 14 13:19:13] DEBUG[32324] http.c: match request [ari/bridges] with handler [ari] len 3 [Oct 14 13:19:13] DEBUG[32324] http.c: Match made with [ari] [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Finding handler for bridges [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking endpoints [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking channels [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking events [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking recordings [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking playback [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking applications [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Checking bridges [Oct 14 13:19:13] DEBUG[32324] res_ari.c: Got it! [Oct 14 13:19:13] DEBUG[32325] http.c: HTTP Request URI is /ari/bridges?type=mixing&api_key=admin%3Asecret [Oct 14 13:19:13] DEBUG[32325] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [Oct 14 13:19:13] DEBUG[32325] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [Oct 14 13:19:13] DEBUG[32325] http.c: match request [ari/bridges] with handler [static] len 6 [Oct 14 13:19:13] DEBUG[32325] http.c: match request [ari/bridges] with handler [ari] len 3 [Oct 14 13:19:13] DEBUG[32325] http.c: Match made with [ari] [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Finding handler for bridges [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking endpoints [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking channels [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking events [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking recordings [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking playback [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking applications [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Checking bridges [Oct 14 13:19:13] DEBUG[32325] res_ari.c: Got it! [Oct 14 13:19:13] DEBUG[32325] dahdi/bridge_native_dahdi.c: Bridge b19969be-14f3-457f-8424-415147006c79: Cannot use native DAHDI. Must have two channels. [Oct 14 13:19:13] DEBUG[32325] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Oct 14 13:19:13] DEBUG[32325] bridge_native_rtp.c: Bridge 'b19969be-14f3-457f-8424-415147006c79' can not use native RTP bridge as two channels are required [Oct 14 13:19:13] DEBUG[32325] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Oct 14 13:19:13] DEBUG[32325] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:19:13] DEBUG[32325] bridge.c: Chose bridge technology simple_bridge [Oct 14 13:19:13] DEBUG[32325] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology constructor [Oct 14 13:19:13] DEBUG[32325] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology start [Oct 14 13:19:14] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:14] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:19] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:19] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:24] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:24] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:29] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:29] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:34] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:34] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:34] DEBUG[32328] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774698.1&api_key=admin%3Asecret [Oct 14 13:19:34] DEBUG[32328] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:19:34] DEBUG[32328] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:19:34] DEBUG[32328] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:19:34] DEBUG[32328] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:19:34] DEBUG[32328] http.c: Match made with [ari] [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Finding handler for bridges [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking endpoints [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking channels [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking events [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking recordings [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking playback [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking applications [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking bridges [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking bridgeId [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Finding handler for addChannel [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Checking addChannel [Oct 14 13:19:34] DEBUG[32328] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32329] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774698.1&api_key=admin%3Asecret [Oct 14 13:19:34] DEBUG[32329] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:19:34] DEBUG[32329] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:19:34] DEBUG[32329] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:19:34] DEBUG[32329] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:19:34] DEBUG[32329] http.c: Match made with [ari] [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Finding handler for bridges [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking endpoints [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking channels [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking events [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking recordings [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking playback [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking applications [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking bridges [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking bridgeId [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Finding handler for addChannel [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Checking addChannel [Oct 14 13:19:34] DEBUG[32329] res_ari.c: Got it! [Oct 14 13:19:34] DEBUG[32329] bridge_roles.c: Roles did not exist on channel SIP/phone_B-00000001 [Oct 14 13:19:34] DEBUG[32329] stasis/control.c: 1381774698.1: Sending channel add_to_bridge command [Oct 14 13:19:34] DEBUG[32317][C-00000001] stasis/control.c: 1381774698.1: Adding to bridge b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:19:34] DEBUG[32330][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is joining [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: pushing 0xb6e85a8c(SIP/phone_B-00000001) [Oct 14 13:19:34] VERBOSE[32330][C-00000001] bridge_channel.c: -- Channel SIP/phone_B-00000001 joined 'simple_bridge' base-bridge [Oct 14 13:19:34] DEBUG[32330][C-00000001] dahdi/bridge_native_dahdi.c: Bridge b19969be-14f3-457f-8424-415147006c79: Cannot use native DAHDI. Must have two channels. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge_native_rtp.c: Bridge 'b19969be-14f3-457f-8424-415147006c79' can not use native RTP bridge as two channels are required [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Chose bridge technology simple_bridge [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is already using the new technology. [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has read format ulaw [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has write format ulaw [Oct 14 13:19:34] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is joining simple_bridge technology [Oct 14 13:19:34] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 14 13:19:39] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:39] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:44] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:44] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:49] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:49] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:54] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:54] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:59] DEBUG[32316][C-00000000] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:19:59] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Oct 14 13:20:01] DEBUG[32331] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774695.0&api_key=admin%3Asecret [Oct 14 13:20:01] DEBUG[32331] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:20:01] DEBUG[32331] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:20:01] DEBUG[32331] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:20:01] DEBUG[32331] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:20:01] DEBUG[32331] http.c: Match made with [ari] [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Finding handler for bridges [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking endpoints [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking channels [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking events [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking recordings [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking playback [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking applications [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking bridges [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking bridgeId [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Finding handler for addChannel [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Checking addChannel [Oct 14 13:20:01] DEBUG[32331] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32332] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774695.0&api_key=admin%3Asecret [Oct 14 13:20:01] DEBUG[32332] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:20:01] DEBUG[32332] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:20:01] DEBUG[32332] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:20:01] DEBUG[32332] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:20:01] DEBUG[32332] http.c: Match made with [ari] [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Finding handler for bridges [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking endpoints [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking channels [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking events [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking recordings [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking playback [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking applications [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking bridges [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking bridgeId [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Finding handler for addChannel [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Checking addChannel [Oct 14 13:20:01] DEBUG[32332] res_ari.c: Got it! [Oct 14 13:20:01] DEBUG[32332] bridge_roles.c: Roles did not exist on channel SIP/phone_A-00000000 [Oct 14 13:20:01] DEBUG[32332] stasis/control.c: 1381774695.0: Sending channel add_to_bridge command [Oct 14 13:20:01] DEBUG[32316][C-00000000] stasis/control.c: 1381774695.0: Adding to bridge b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:20:01] DEBUG[32333][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is joining [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: pushing 0xb3009844(SIP/phone_A-00000000) [Oct 14 13:20:01] VERBOSE[32333][C-00000000] bridge_channel.c: -- Channel SIP/phone_A-00000000 joined 'simple_bridge' base-bridge [Oct 14 13:20:01] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_B-00000001 - start 1381774698.124146 answer 1381774698.124971 end 1381774801.227279 dispo ANSWERED [Oct 14 13:20:01] DEBUG[32333][C-00000000] dahdi/bridge_native_dahdi.c: Channel 'SIP/phone_B-00000001' is not DAHDI. [Oct 14 13:20:01] DEBUG[32333][C-00000000] dahdi/bridge_native_dahdi.c: Bridge b19969be-14f3-457f-8424-415147006c79: Cannot use native DAHDI. Channel 'SIP/phone_B-00000001' not compatible. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Chose bridge technology native_rtp [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology constructor [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology stop [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is leaving simple_bridge technology (dummy) [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has read format ulaw [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has write format ulaw [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is joining native_rtp technology [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge_native_rtp.c: Locally RTP bridged 'SIP/phone_B-00000001' and 'SIP/phone_A-00000000' in stack [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has read format ulaw [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has write format ulaw [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is joining native_rtp technology [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge_native_rtp.c: Locally RTP bridged 'SIP/phone_B-00000001' and 'SIP/phone_A-00000000' in stack [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology start [Oct 14 13:20:01] DEBUG[32333][C-00000000] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology destructor [Oct 14 13:20:01] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 14 13:20:03] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for w7hkt9CUeDdnCM81gfaR-SrMFeYJ7sb. - SUBSCRIBE (No RTP) [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_A" [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:20:03] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_A [Oct 14 13:20:03] DEBUG[32212] chan_sip.c: Destroying SIP dialog w7hkt9CUeDdnCM81gfaR-SrMFeYJ7sb. [Oct 14 13:20:04] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:04] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:09] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:09] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:14] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:14] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:17] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe - REGISTER (No RTP) [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: build_path: do not use Path headers [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:20:17] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_A [Oct 14 13:20:17] DEBUG[32162] chan_sip.c: Checking device state for peer phone_A [Oct 14 13:20:17] DEBUG[32162] devicestate.c: Changing state for SIP/phone_A - state 1 (Not in use) [Oct 14 13:20:17] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_A' [Oct 14 13:20:17] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_A' [Oct 14 13:20:17] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_A' [Oct 14 13:20:17] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_A' has not changed from 'Not in use' [Oct 14 13:20:17] DEBUG[32212] acl.c: For destination '10.24.19.97', our source address is '10.24.18.161'. [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for 3BoOOapMwV6fgOEeNnCktdYVDoFBJehD - SUBSCRIBE (No RTP) [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_A" [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.19.97:5060 [Oct 14 13:20:17] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_A [Oct 14 13:20:17] DEBUG[32212] chan_sip.c: Destroying SIP dialog 3BoOOapMwV6fgOEeNnCktdYVDoFBJehD [Oct 14 13:20:19] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:19] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:24] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:24] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:29] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:29] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:34] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:34] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:34] DEBUG[32212] logger.c: CALL_ID [C-00000002] created by thread. [Oct 14 13:20:34] DEBUG[32212] acl.c: For destination '10.24.17.17', our source address is '10.24.18.161'. [Oct 14 13:20:34] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:34] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for 525c35f05de4-k4a6lk03f5ep - INVITE (No RTP) [Oct 14 13:20:34] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Found SIP option: -timer- [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Matched SIP option: timer [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Found SIP option: -from-change- [Oct 14 13:20:34] DEBUG[32212][C-00000002] sip/reqresp_parser.c: Matched SIP option: from-change [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb2bf1184' [Oct 14 13:20:34] DEBUG[32212][C-00000002] res_rtp_asterisk.c: Allocated port 18110 for RTP instance '0xb2bf1184' [Oct 14 13:20:34] DEBUG[32212][C-00000002] pjsip: icess0xb2df8f5 ICE session created, comp_cnt=2, role is Unknown agent [Oct 14 13:20:34] DEBUG[32212][C-00000002] pjsip: icess0xb2df8f5 Candidate 0 added: comp_id=1, type=host, foundation=Ha1812a1, addr=10.24.18.161:18110, base=10.24.18.161:18110, prio=0x7effffff (2130706431) [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: RTP instance '0xb2bf1184' is setup and ready to go [Oct 14 13:20:34] DEBUG[32212][C-00000002] pjsip: icess0xb2df8f5 Destroying ICE session 0xb2df8f5c [Oct 14 13:20:34] DEBUG[32212][C-00000002] pjsip: ice_session.c ICE session 0xb2df8f5c destroyed [Oct 14 13:20:34] DEBUG[32212][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb2bf1184' [Oct 14 13:20:34] VERBOSE[32212][C-00000002] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Setting NAT on RTP to Off [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing session-level SDP o=root 437293363 437293363 IN IP4 10.24.17.17... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing session-level SDP s=call... UNSUPPORTED OR FAILED. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.17.17... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 9 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 0 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 8 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 3 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 99 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 108 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 18 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Setting payload 101 based on m type on 0xb3146c78 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:99 G726-32/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:108 AAL2-G726-32/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 14 13:20:34] DEBUG[32212][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb2bf1184' [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 0 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 3 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 8 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 9 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 18 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 99 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 101 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] rtp_engine.c: Copying payload 108 from 0xb3146c78 to 0xb2bf12ac [Oct 14 13:20:34] DEBUG[32212][C-00000002] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb2bf1184' [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: We're settling with these formats: (ulaw|g722) [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Checking SIP call limits for device phone_C [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Updating call counter for incoming call [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: *** Our native formats are (g722) [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: *** Joint capabilities are (ulaw|g722) [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: *** Our capabilities are (ulaw|g722) [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: *** AST_CODEC_CHOOSE formats are g722 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: This channel will not be able to handle video. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: build_route: Contact hop: ;reg-id=1 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Incoming INVITE with 'timer' option supported [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: INVITE also has "Session-Expires" header. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Session-Expires: 3600 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Refresher: UAS [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: INVITE also has "Min-SE" header. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Received Min-SE: 90 [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Session timer started: 21 - 525c35f05de4-k4a6lk03f5ep 900000ms [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: SIP/phone_C-00000002: New call is still down.... Trying... [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.17.17:5060 [Oct 14 13:20:34] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_C [Oct 14 13:20:34] DEBUG[32162] chan_sip.c: Checking device state for peer phone_C [Oct 14 13:20:34] DEBUG[32162] devicestate.c: Changing state for SIP/phone_C - state 1 (Not in use) [Oct 14 13:20:34] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] being removed from thread. [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_C' [Oct 14 13:20:34] DEBUG[32337][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_C' [Oct 14 13:20:34] DEBUG[32337][C-00000002] pbx.c: Launching 'NoOp' [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_C' [Oct 14 13:20:34] VERBOSE[32337][C-00000002] pbx.c: -- Executing [201@internal:1] NoOp("SIP/phone_C-00000002", "") in new stack [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_C' has changed to 'Not in use' [Oct 14 13:20:34] DEBUG[32274] app_queue.c: Device 'SIP/phone_C' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 14 13:20:34] DEBUG[32337][C-00000002] pbx.c: Launching 'Answer' [Oct 14 13:20:34] VERBOSE[32337][C-00000002] pbx.c: -- Executing [201@internal:2] Answer("SIP/phone_C-00000002", "") in new stack [Oct 14 13:20:34] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_C [Oct 14 13:20:34] DEBUG[32162] chan_sip.c: Checking device state for peer phone_C [Oct 14 13:20:34] DEBUG[32162] devicestate.c: Changing state for SIP/phone_C - state 1 (Not in use) [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: SIP answering channel: SIP/phone_C-00000002 [Oct 14 13:20:34] DEBUG[32337][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: Setting framing from config on incoming call [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_C' [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_C' [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: ** Our capability: (ulaw|g722) Video flag: True Text flag: True [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_C' [Oct 14 13:20:34] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_C' has not changed from 'Not in use' [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: ** Our prefcodec: (nothing) [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: -- Done with adding codecs to SDP [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722) [Oct 14 13:20:34] DEBUG[32337][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.17.17:5060 [Oct 14 13:20:34] DEBUG[32212] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #23)) [Oct 14 13:20:34] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.17.17:5060 [Oct 14 13:20:34] DEBUG[32337][C-00000002] channel.c: Didn't receive a media frame from SIP/phone_C-00000002 within 500 ms of answering. Continuing anyway [Oct 14 13:20:34] DEBUG[32337][C-00000002] pbx.c: Launching 'Stasis' [Oct 14 13:20:34] VERBOSE[32337][C-00000002] pbx.c: -- Executing [201@internal:3] Stasis("SIP/phone_C-00000002", "Bridge") in new stack [Oct 14 13:20:34] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 14 13:20:34] DEBUG[32212][C-00000002] chan_sip.c: Stopping retransmission on '525c35f05de4-k4a6lk03f5ep' of Response 1: Match Found [Oct 14 13:20:34] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] being removed from thread. [Oct 14 13:20:35] DEBUG[32337][C-00000002] res_rtp_asterisk.c: 0xb2df65c0 -- Probation learning mode pass with source address 10.24.17.17:65420 [Oct 14 13:20:35] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:20:35] DEBUG[32212][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 14 13:20:35] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] being removed from thread. [Oct 14 13:20:37] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa - REGISTER (No RTP) [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: build_path: do not use Path headers [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:20:37] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_B [Oct 14 13:20:37] DEBUG[32162] chan_sip.c: Checking device state for peer phone_B [Oct 14 13:20:37] DEBUG[32162] devicestate.c: Changing state for SIP/phone_B - state 1 (Not in use) [Oct 14 13:20:37] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_B' [Oct 14 13:20:37] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_B' [Oct 14 13:20:37] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_B' [Oct 14 13:20:37] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_B' has not changed from 'Not in use' [Oct 14 13:20:37] DEBUG[32212] acl.c: For destination '10.24.18.165', our source address is '10.24.18.161'. [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.161:5061 [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Allocating new SIP dialog for 89QaCjSr9zGK-DWEKGC4it.SzD0swirW - SUBSCRIBE (No RTP) [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: build_route: Contact hop: "phone_B" [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:20:37] NOTICE[32212] chan_sip.c: Received SIP subscribe for peer without mailbox: phone_B [Oct 14 13:20:37] DEBUG[32212] chan_sip.c: Destroying SIP dialog 89QaCjSr9zGK-DWEKGC4it.SzD0swirW [Oct 14 13:20:39] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:39] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:40] DEBUG[32338] http.c: HTTP Request URI is /ari/channels?api_key=admin%3Asecret [Oct 14 13:20:40] DEBUG[32338] http.c: match request [ari/channels] with handler [httpstatus] len 10 [Oct 14 13:20:40] DEBUG[32338] http.c: match request [ari/channels] with handler [phoneprov] len 9 [Oct 14 13:20:40] DEBUG[32338] http.c: match request [ari/channels] with handler [static] len 6 [Oct 14 13:20:40] DEBUG[32338] http.c: match request [ari/channels] with handler [ari] len 3 [Oct 14 13:20:40] DEBUG[32338] http.c: Match made with [ari] [Oct 14 13:20:40] DEBUG[32338] res_ari.c: Finding handler for channels [Oct 14 13:20:40] DEBUG[32338] res_ari.c: Checking endpoints [Oct 14 13:20:40] DEBUG[32338] res_ari.c: Checking channels [Oct 14 13:20:40] DEBUG[32338] res_ari.c: Got it! [Oct 14 13:20:40] DEBUG[32339] http.c: HTTP Request URI is /ari/channels?api_key=admin%3Asecret [Oct 14 13:20:40] DEBUG[32339] http.c: match request [ari/channels] with handler [httpstatus] len 10 [Oct 14 13:20:40] DEBUG[32339] http.c: match request [ari/channels] with handler [phoneprov] len 9 [Oct 14 13:20:40] DEBUG[32339] http.c: match request [ari/channels] with handler [static] len 6 [Oct 14 13:20:40] DEBUG[32339] http.c: match request [ari/channels] with handler [ari] len 3 [Oct 14 13:20:40] DEBUG[32339] http.c: Match made with [ari] [Oct 14 13:20:40] DEBUG[32339] res_ari.c: Finding handler for channels [Oct 14 13:20:40] DEBUG[32339] res_ari.c: Checking endpoints [Oct 14 13:20:40] DEBUG[32339] res_ari.c: Checking channels [Oct 14 13:20:40] DEBUG[32339] res_ari.c: Got it! [Oct 14 13:20:44] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:44] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:49] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:49] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:49] DEBUG[32212] chan_sip.c: Auto destroying SIP dialog 'wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe' [Oct 14 13:20:49] DEBUG[32212] chan_sip.c: Destroying SIP dialog wZzOV.PhANaLnS96XPQ0FLmTh.GwVZXe [Oct 14 13:20:54] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:54] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:59] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:20:59] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:04] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:04] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:09] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:09] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:09] DEBUG[32212] chan_sip.c: Auto destroying SIP dialog 'NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa' [Oct 14 13:21:09] DEBUG[32212] chan_sip.c: Destroying SIP dialog NacarXYZ4RwMe780LH7Fe8NkbxZ0vkZa [Oct 14 13:21:10] DEBUG[32341] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774834.2&api_key=admin%3Asecret [Oct 14 13:21:10] DEBUG[32341] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:21:10] DEBUG[32341] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:21:10] DEBUG[32341] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:21:10] DEBUG[32341] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:21:10] DEBUG[32341] http.c: Match made with [ari] [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Finding handler for bridges [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking endpoints [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking channels [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking events [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking recordings [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking playback [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking applications [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking bridges [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking bridgeId [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Finding handler for addChannel [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Checking addChannel [Oct 14 13:21:10] DEBUG[32341] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32342] http.c: HTTP Request URI is /ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel?channel=1381774834.2&api_key=admin%3Asecret [Oct 14 13:21:10] DEBUG[32342] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [httpstatus] len 10 [Oct 14 13:21:10] DEBUG[32342] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [phoneprov] len 9 [Oct 14 13:21:10] DEBUG[32342] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [static] len 6 [Oct 14 13:21:10] DEBUG[32342] http.c: match request [ari/bridges/b19969be-14f3-457f-8424-415147006c79/addChannel] with handler [ari] len 3 [Oct 14 13:21:10] DEBUG[32342] http.c: Match made with [ari] [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Finding handler for bridges [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking endpoints [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking channels [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking events [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking recordings [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking playback [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking applications [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking bridges [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Finding handler for b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking bridgeId [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Finding handler for addChannel [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Checking addChannel [Oct 14 13:21:10] DEBUG[32342] res_ari.c: Got it! [Oct 14 13:21:10] DEBUG[32342] bridge_roles.c: Roles did not exist on channel SIP/phone_C-00000002 [Oct 14 13:21:10] DEBUG[32342] stasis/control.c: 1381774834.2: Sending channel add_to_bridge command [Oct 14 13:21:10] DEBUG[32337][C-00000002] stasis/control.c: 1381774834.2: Adding to bridge b19969be-14f3-457f-8424-415147006c79 [Oct 14 13:21:10] DEBUG[32343][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb300be9c(SIP/phone_C-00000002) is joining [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: pushing 0xb300be9c(SIP/phone_C-00000002) [Oct 14 13:21:10] VERBOSE[32343][C-00000002] bridge_channel.c: -- Channel SIP/phone_C-00000002 joined 'native_rtp' base-bridge [Oct 14 13:21:10] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_C-00000002 - start 1381774834.439775 answer 1381774834.441071 end 1381774870.050481 dispo ANSWERED [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Chose bridge technology softmix [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling softmix technology constructor [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology stop [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is leaving native_rtp technology (dummy) [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to read any of formats (slin) but channel has ulaw [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_B-00000001 to read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_B-00000001 into read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to write any of formats (slin) but channel has ulaw [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_B-00000001 to write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_B-00000001 into write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is joining softmix technology [Oct 14 13:21:10] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is leaving native_rtp technology (dummy) [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to read any of formats (slin) but channel has ulaw [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_A-00000000 to read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_A-00000000 into read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to write any of formats (slin) but channel has ulaw [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_A-00000000 to write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_A-00000000 into write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is joining softmix technology [Oct 14 13:21:10] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to read any of formats (slin) but channel has g722 [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_C-00000002 to read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_C-00000002 into read format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix wants to write any of formats (slin) but channel has g722 [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_C-00000002 to write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 put channel SIP/phone_C-00000002 into write format slin [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb300be9c(SIP/phone_C-00000002) is joining softmix technology [Oct 14 13:21:10] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_C-00000002 to read format slin16 [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=320, hits_required=21 [Oct 14 13:21:10] DEBUG[32343][C-00000002] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=320, hits_required=116 [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling softmix technology start [Oct 14 13:21:10] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology destructor [Oct 14 13:21:10] DEBUG[32343][C-00000002] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 14 13:21:10] DEBUG[32344][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:21:10] DEBUG[32344][C-00000001] bridge_softmix.c: Bridge b19969be-14f3-457f-8424-415147006c79: starting mixing thread [Oct 14 13:21:10] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 14 13:21:10] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 14 13:21:10] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 14 13:21:10] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 14 13:21:10] DEBUG[32343][C-00000002] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Oct 14 13:21:10] DEBUG[32343][C-00000002] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Oct 14 13:21:14] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:14] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:19] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:19] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:24] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:24] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:29] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:29] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:34] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:34] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:39] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:39] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:44] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:44] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:47] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] bound to thread. [Oct 14 13:21:47] DEBUG[32212][C-00000002] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Oct 14 13:21:47] DEBUG[32212][C-00000002] chan_sip.c: Setting SIP_ALREADYGONE on dialog 525c35f05de4-k4a6lk03f5ep [Oct 14 13:21:47] DEBUG[32212][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb2bf1184' [Oct 14 13:21:47] DEBUG[32212][C-00000002] chan_sip.c: Session timer stopped: 21 - 525c35f05de4-k4a6lk03f5ep [Oct 14 13:21:47] DEBUG[32212][C-00000002] chan_sip.c: Received bye, issuing owner hangup [Oct 14 13:21:47] DEBUG[32212][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.17.17:5060 [Oct 14 13:21:47] DEBUG[32212][C-00000002] logger.c: CALL_ID [C-00000002] being removed from thread. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_channel.c: Setting 0xb300be9c(SIP/phone_C-00000002) state from:0 to:1 [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: pulling 0xb300be9c(SIP/phone_C-00000002) [Oct 14 13:21:47] VERBOSE[32343][C-00000002] bridge_channel.c: -- Channel SIP/phone_C-00000002 left 'softmix' base-bridge [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb300be9c(SIP/phone_C-00000002) is leaving softmix technology [Oct 14 13:21:47] DEBUG[32343][C-00000002] dahdi/bridge_native_dahdi.c: Channel 'SIP/phone_B-00000001' is not DAHDI. [Oct 14 13:21:47] DEBUG[32343][C-00000002] dahdi/bridge_native_dahdi.c: Bridge b19969be-14f3-457f-8424-415147006c79: Cannot use native DAHDI. Channel 'SIP/phone_B-00000001' not compatible. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Chose bridge technology native_rtp [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology constructor [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling softmix technology stop [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is leaving softmix technology (dummy) [Oct 14 13:21:47] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Changing ssrc from 1032416830 to 1775496035 due to a source change [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has read format slin [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_B-00000001 already has write format slin [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is joining native_rtp technology [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_native_rtp.c: Locally RTP bridged 'SIP/phone_B-00000001' and 'SIP/phone_A-00000000' in stack [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is leaving softmix technology (dummy) [Oct 14 13:21:47] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Changing ssrc from 1337073065 to 611442929 due to a source change [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has read format slin [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has write format slin [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is joining native_rtp technology [Oct 14 13:21:47] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_B-00000001 - start 1381774698.124146 answer 1381774698.124971 end 1381774907.745052 dispo ANSWERED [Oct 14 13:21:47] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_A-00000000 - start 1381774870.050516 answer 1381774870.050516 end 1381774907.745069 dispo ANSWERED [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_native_rtp.c: Locally RTP bridged 'SIP/phone_B-00000001' and 'SIP/phone_A-00000000' in stack [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology start [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: deferring softmix technology destructor [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: queueing action type:13 sub:1000 [Oct 14 13:21:47] DEBUG[32333][C-00000000] channel.c: SIP/phone_A-00000000: Dropping redundant connected line update "Phone B" <1002>. [Oct 14 13:21:47] DEBUG[32330][C-00000001] channel.c: SIP/phone_B-00000001: Dropping redundant connected line update "Phone A" <1001>. [Oct 14 13:21:47] DEBUG[32160][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:21:47] DEBUG[32160][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling softmix technology destructor (deferred, dummy) [Oct 14 13:21:47] DEBUG[32160][C-00000001] bridge_softmix.c: Bridge b19969be-14f3-457f-8424-415147006c79: Waiting for mixing thread to die. [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_channel.c: Bridge is returning 0xb300be9c(SIP/phone_C-00000002) to read format g722 [Oct 14 13:21:47] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_C-00000002 to read format g722 [Oct 14 13:21:47] DEBUG[32343][C-00000002] bridge_channel.c: Bridge is returning 0xb300be9c(SIP/phone_C-00000002) to write format g722 [Oct 14 13:21:47] DEBUG[32343][C-00000002] channel.c: Set channel SIP/phone_C-00000002 to write format g722 [Oct 14 13:21:47] DEBUG[32343][C-00000002] stasis/control.c: 1381774834.2, b19969be-14f3-457f-8424-415147006c79: Channel leaving bridge [Oct 14 13:21:47] DEBUG[32337][C-00000002] pbx.c: Extension 201, priority 3 returned normally even though call was hung up [Oct 14 13:21:47] DEBUG[32337][C-00000002] channel.c: Soft-Hanging up channel 'SIP/phone_C-00000002' [Oct 14 13:21:47] DEBUG[32337][C-00000002] channel.c: Soft-Hanging up channel 'SIP/phone_C-00000002' [Oct 14 13:21:47] DEBUG[32337][C-00000002] pbx.c: Launching 'NoOp' [Oct 14 13:21:47] VERBOSE[32337][C-00000002] pbx.c: -- Executing [h@internal:1] NoOp("SIP/phone_C-00000002", "=== Hang up handler ===") in new stack [Oct 14 13:21:47] DEBUG[32337][C-00000002] pbx.c: Launching 'NoOp' [Oct 14 13:21:47] VERBOSE[32337][C-00000002] pbx.c: -- Executing [h@internal:2] NoOp("SIP/phone_C-00000002", "=== AGENT STATUS: ===") in new stack [Oct 14 13:21:47] DEBUG[32337][C-00000002] channel.c: Hanging up channel 'SIP/phone_C-00000002' [Oct 14 13:21:47] DEBUG[32337][C-00000002] chan_sip.c: Hangup call SIP/phone_C-00000002, SIP callid 525c35f05de4-k4a6lk03f5ep [Oct 14 13:21:47] DEBUG[32337][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb2bf1184' [Oct 14 13:21:47] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_C-00000002 - start 1381774907.746679 answer 1381774907.746679 end 1381774907.746719 dispo ANSWERED [Oct 14 13:21:47] DEBUG[32161] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Oct 14 13:21:47] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_C [Oct 14 13:21:47] DEBUG[32162] chan_sip.c: Checking device state for peer phone_C [Oct 14 13:21:47] DEBUG[32162] devicestate.c: Changing state for SIP/phone_C - state 1 (Not in use) [Oct 14 13:21:47] DEBUG[32161] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Oct 14 13:21:47] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_C' [Oct 14 13:21:47] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_C' [Oct 14 13:21:47] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_C' [Oct 14 13:21:47] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_C' has not changed from 'Not in use' [Oct 14 13:21:47] DEBUG[32161] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Phone C" <1003>','1003','201','internal','SIP/phone_C-00000002','Stasis','Bridge','2013-10-14 13:20:34','2013-10-14 13:20:34','2013-10-14 13:21:10','35','35','ANSWERED','DOCUMENTATION','1381774834.2') [Oct 14 13:21:47] DEBUG[32343][C-00000002] stasis/control.c: reason: Channel was departed from bridge [Oct 14 13:21:47] DEBUG[32344][C-00000001] bridge_softmix.c: Bridge b19969be-14f3-457f-8424-415147006c79: stopping mixing thread [Oct 14 13:21:47] DEBUG[32161] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Oct 14 13:21:47] DEBUG[32161] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Phone C" <1003>','1003','h','internal','SIP/phone_C-00000002','NoOp','=== AGENT STATUS: ===','2013-10-14 13:21:47','2013-10-14 13:21:47','2013-10-14 13:21:47','0','0','ANSWERED','DOCUMENTATION','1381774834.2') [Oct 14 13:21:49] DEBUG[32333][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:49] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 14 13:21:52] DEBUG[32330][C-00000001] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Oct 14 13:21:52] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Oct 14 13:21:52] DEBUG[32212][C-00000001] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Oct 14 13:21:52] DEBUG[32212][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog .bvBPVmXunZ8T48yGtHjKayxdKrK1S1X [Oct 14 13:21:52] DEBUG[32212][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x965bddc' [Oct 14 13:21:52] DEBUG[32212][C-00000001] chan_sip.c: Session timer stopped: 15 - .bvBPVmXunZ8T48yGtHjKayxdKrK1S1X [Oct 14 13:21:52] DEBUG[32212][C-00000001] chan_sip.c: Received bye, issuing owner hangup [Oct 14 13:21:52] DEBUG[32212][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.165:5060 [Oct 14 13:21:52] DEBUG[32212][C-00000001] logger.c: CALL_ID [C-00000001] being removed from thread. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_channel.c: Setting 0xb6e85a8c(SIP/phone_B-00000001) state from:0 to:1 [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: pulling 0xb6e85a8c(SIP/phone_B-00000001) [Oct 14 13:21:52] VERBOSE[32330][C-00000001] bridge_channel.c: -- Channel SIP/phone_B-00000001 left 'native_rtp' base-bridge [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_channel.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb6e85a8c(SIP/phone_B-00000001) is leaving native_rtp technology [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/phone_B-00000001' and 'SIP/phone_A-00000000' - media will flow through Asterisk core [Oct 14 13:21:52] DEBUG[32330][C-00000001] dahdi/bridge_native_dahdi.c: Bridge b19969be-14f3-457f-8424-415147006c79: Cannot use native DAHDI. Must have two channels. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_native_rtp.c: Bridge 'b19969be-14f3-457f-8424-415147006c79' can not use native RTP bridge as two channels are required [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Chose bridge technology simple_bridge [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology constructor [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology stop [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is leaving native_rtp technology (dummy) [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has read format slin [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79 is happy that channel SIP/phone_A-00000000 already has write format slin [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: 0xb3009844(SIP/phone_A-00000000) is joining simple_bridge technology [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling simple_bridge technology start [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge.c: Bridge b19969be-14f3-457f-8424-415147006c79: calling native_rtp technology destructor [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_channel.c: Bridge is returning 0xb6e85a8c(SIP/phone_B-00000001) to read format ulaw [Oct 14 13:21:52] DEBUG[32330][C-00000001] channel.c: Set channel SIP/phone_B-00000001 to read format ulaw [Oct 14 13:21:52] DEBUG[32330][C-00000001] bridge_channel.c: Bridge is returning 0xb6e85a8c(SIP/phone_B-00000001) to write format ulaw [Oct 14 13:21:52] DEBUG[32330][C-00000001] channel.c: Set channel SIP/phone_B-00000001 to write format ulaw [Oct 14 13:21:52] DEBUG[32330][C-00000001] stasis/control.c: 1381774698.1, b19969be-14f3-457f-8424-415147006c79: Channel leaving bridge [Oct 14 13:21:52] DEBUG[32317][C-00000001] pbx.c: Extension 201, priority 3 returned normally even though call was hung up [Oct 14 13:21:52] DEBUG[32317][C-00000001] channel.c: Soft-Hanging up channel 'SIP/phone_B-00000001' [Oct 14 13:21:52] DEBUG[32317][C-00000001] channel.c: Soft-Hanging up channel 'SIP/phone_B-00000001' [Oct 14 13:21:52] DEBUG[32317][C-00000001] pbx.c: Launching 'NoOp' [Oct 14 13:21:52] VERBOSE[32317][C-00000001] pbx.c: -- Executing [h@internal:1] NoOp("SIP/phone_B-00000001", "=== Hang up handler ===") in new stack [Oct 14 13:21:52] DEBUG[32317][C-00000001] pbx.c: Launching 'NoOp' [Oct 14 13:21:52] VERBOSE[32317][C-00000001] pbx.c: -- Executing [h@internal:2] NoOp("SIP/phone_B-00000001", "=== AGENT STATUS: ===") in new stack [Oct 14 13:21:52] DEBUG[32317][C-00000001] channel.c: Hanging up channel 'SIP/phone_B-00000001' [Oct 14 13:21:52] DEBUG[32317][C-00000001] chan_sip.c: Hangup call SIP/phone_B-00000001, SIP callid .bvBPVmXunZ8T48yGtHjKayxdKrK1S1X [Oct 14 13:21:52] DEBUG[32317][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x965bddc' [Oct 14 13:21:52] DEBUG[32162] devicestate.c: No provider found, checking channel drivers for SIP - phone_B [Oct 14 13:21:52] DEBUG[32162] chan_sip.c: Checking device state for peer phone_B [Oct 14 13:21:52] DEBUG[32162] devicestate.c: Changing state for SIP/phone_B - state 1 (Not in use) [Oct 14 13:21:52] DEBUG[32156] devicestate.c: Processing device state change for 'SIP/phone_B' [Oct 14 13:21:52] DEBUG[32156] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_B' [Oct 14 13:21:52] DEBUG[32156] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_B' [Oct 14 13:21:52] DEBUG[32156] devicestate.c: Aggregate state for device 'SIP/phone_B' has not changed from 'Not in use' [Oct 14 13:21:52] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_B-00000001 - start 1381774912.576671 answer 1381774912.576671 end 1381774912.576707 dispo ANSWERED [Oct 14 13:21:52] DEBUG[32161] cdr.c: Finalized CDR for SIP/phone_A-00000000 - start 1381774695.559994 answer 1381774695.561048 end 1381774912.576725 dispo ANSWERED [Oct 14 13:21:52] DEBUG[32161] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Oct 14 13:21:52] DEBUG[32161] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Phone B" <1002>','1002','201','internal','SIP/phone_B-00000001','SIP/phone_C-00000002','Stasis','Bridge','2013-10-14 13:18:18','2013-10-14 13:18:18','2013-10-14 13:21:47','209','209','ANSWERED','DOCUMENTATION','1381774698.1') [Oct 14 13:21:52] DEBUG[32330][C-00000001] stasis/control.c: reason: Channel was departed from bridge