[Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=1 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.26.1:64373 does not match identify 'voip-t' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: '192.168.26.1:64373' did not match any identify section rules [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Identified by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg ACK/cseq=1 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.26.1:64373 does not match identify 'voip-t' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: '192.168.26.1:64373' did not match any identify section rules [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Identified by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=2 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.26.1:64373 does not match identify 'voip-t' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: '192.168.26.1:64373' did not match any identify section rules [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_endpoint_identifier_user.c: Identified by From username 'bria' domain '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_authenticator_digest.c: Calculated nonce 1486663991/3549a11f5c699f45fbfb12f027f9c306. Actual nonce is 1486663991/3549a11f5c699f45fbfb12f027f9c306 [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=2 (rdata0x7f5a30005238) [Feb 9 13:13:11] VERBOSE[54570] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '192.168.26.66' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f5a5000fd90' [Feb 9 13:13:11] DEBUG[54570] res_rtp_asterisk.c: Allocated port 7470 for RTP instance '0x7f5a5000fd90' [Feb 9 13:13:11] DEBUG[54570] res_rtp_asterisk.c: Creating ICE session [::]:7470 (7470) for RTP instance '0x7f5a5000fd90' [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: RTP instance '0x7f5a5000fd90' is setup and ready to go [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting 'voip-t-13' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host 'voip-t-13' and port ''. [Feb 9 13:13:11] DEBUG[54570] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f5a5000fd90' [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Don't have a default tx payload type 120 format for m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Don't have a default tx payload type 122 format for m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f59fdd21540 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 0 (0x33aead8) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 8 (0x33adfc8) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 9 (0x33ae008) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 18 (0x7f5a500104c8) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 101 (0x7f5a50010618) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 120 (0x7f5a50010718) from 0x7f59fdd21540 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Media stream 'audio' handled by audio [Feb 9 13:13:11] DEBUG[54570] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria()' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8006bb8) [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is INCOMING [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria()' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8006bb8) [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8006bb8 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current transaction state is Proceeding [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is INCOMING [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Method is INVITE [Feb 9 13:13:11] DEBUG[54110] threadpool.c: Increasing threadpool stasis-core's size by 1 [Feb 9 13:13:11] DEBUG[54570] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/bria-000000bb [Feb 9 13:13:11] DEBUG[54593][C-000000bb] pbx_variables.c: Expression result is '"vm-login"' [Feb 9 13:13:11] DEBUG[54593][C-000000bb] pbx.c: Launching 'MSet' [Feb 9 13:13:11] VERBOSE[54593][C-000000bb] pbx.c: Executing [5678@default:1] MSet("PJSIP/bria-000000bb", "FEATURE(xfersound)="vm-login"") in new stack [Feb 9 13:13:11] DEBUG[54593][C-000000bb] pbx.c: Launching 'Answer' [Feb 9 13:13:11] VERBOSE[54593][C-000000bb] pbx.c: Executing [5678@default:2] Answer("PJSIP/bria-000000bb", "1000") in new stack [Feb 9 13:13:11] DEBUG[54121] devicestate.c: No provider found, checking channel drivers for PJSIP - bria [Feb 9 13:13:11] DEBUG[54121] devicestate.c: Changing state for PJSIP/bria - state 2 (In use) [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:11] DEBUG[54570] netsock2.c: Splitting '192.168.26.1' into... [Feb 9 13:13:11] DEBUG[54570] netsock2.c: ...host '192.168.26.1' and port ''. [Feb 9 13:13:11] DEBUG[54570] acl.c: For destination '192.168.26.1', our source address is '192.168.26.66'. [Feb 9 13:13:11] DEBUG[54570] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f5a5000fd90' [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Don't have a default tx payload type 120 format for m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Don't have a default tx payload type 122 format for m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 0 (0x33aead8) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 8 (0x33adfc8) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 9 (0x33ae008) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 18 (0x7f5a50018188) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 101 (0x7f5a50022778) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] rtp_engine.c: Copying payload 120 (0x7f5a50011be8) from 0x7f59fdd20f80 to 0x7f5a5000ff58 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Feb 9 13:13:11] DEBUG[54570] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.26.66:5060 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8006bb8) [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8006bb8) [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8006bb8 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f59e800cb08 for Request msg ACK/cseq=2 (rdata0x7f5a30000918) [Feb 9 13:13:11] DEBUG[54134] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000021 on dialog dlg0x7f59e800cb08 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8006bb8 [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current transaction state is Terminated [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The transaction state change event is USER [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Received request [Feb 9 13:13:11] DEBUG[54570] res_pjsip_session.c: Method is ACK [Feb 9 13:13:11] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: 0x7f5a50018b10 -- Probation learning mode pass with source address 192.168.26.1:52616 [Feb 9 13:13:11] VERBOSE[54593][C-000000bb] res_rtp_asterisk.c: 0x7f5a50018b10 -- Probation passed - setting RTP source address to 192.168.26.1:52616 [Feb 9 13:13:11] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 9 13:13:11] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:12] DEBUG[54593][C-000000bb] channel.c: Didn't receive a media frame from PJSIP/bria-000000bb within 1000 ms of answering. Continuing anyway [Feb 9 13:13:12] DEBUG[54593][C-000000bb] pbx.c: Launching 'MusicOnHold' [Feb 9 13:13:12] VERBOSE[54593][C-000000bb] pbx.c: Executing [5678@default:3] MusicOnHold("PJSIP/bria-000000bb", "") in new stack [Feb 9 13:13:12] VERBOSE[54593][C-000000bb] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/bria-000000bb' [Feb 9 13:13:12] DEBUG[54593][C-000000bb] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 9 13:13:12] DEBUG[54593][C-000000bb] res_musiconhold.c: PJSIP/bria-000000bb Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Feb 9 13:13:12] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Feb 9 13:13:15] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: Got RTCP report of 100 bytes [Feb 9 13:13:15] DEBUG[54593][C-000000bb] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:17] DEBUG[54134] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=102 (rdata0x7f5a30000918) [Feb 9 13:13:17] DEBUG[54134] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002a to use for Request msg INVITE/cseq=102 (rdata0x7f5a30000918) [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.61' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.61' and port ''. [Feb 9 13:13:17] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.26.61:5060 matches identify 'voip-t' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint voip-t [Feb 9 13:13:17] DEBUG[54570] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002a to use for Request msg INVITE/cseq=102 (rdata0x7f5a300032b8) [Feb 9 13:13:17] VERBOSE[54570] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '192.168.26.66' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.61' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.61' and port ''. [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f5a5001ef90' [Feb 9 13:13:17] DEBUG[54570] res_rtp_asterisk.c: Allocated port 13694 for RTP instance '0x7f5a5001ef90' [Feb 9 13:13:17] DEBUG[54570] res_rtp_asterisk.c: Creating ICE session [::]:13694 (13694) for RTP instance '0x7f5a5001ef90' [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: RTP instance '0x7f5a5001ef90' is setup and ready to go [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting 'voip-t-13' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host 'voip-t-13' and port ''. [Feb 9 13:13:17] DEBUG[54570] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f5a5001ef90' [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting 'fe80::20c:29ff:fe62:391d' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host 'fe80::20c:29ff:fe62:391d' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.66' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.66' and port ''. [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f59fdd21540 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f59fdd21540 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Copying payload 0 (0x7f5a50027ca8) from 0x7f59fdd21540 to 0x7f5a5001f158 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Copying payload 101 (0x7f5a50028238) from 0x7f59fdd21540 to 0x7f5a5001f158 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Media stream 'audio' handled by audio [Feb 9 13:13:17] DEBUG[54570] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t()' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8043418) [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is INCOMING [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t()' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8043418) [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8043418 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current transaction state is Proceeding [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is INCOMING [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Method is INVITE [Feb 9 13:13:17] DEBUG[54570] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/voip-t-000000bc [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx_variables.c: Expression result is 'maryland' [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx.c: Launching 'MSet' [Feb 9 13:13:17] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:1] MSet("PJSIP/voip-t-000000bc", "FEATURE(xfersound)=maryland") in new stack [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx_variables.c: Function CHANNELS(bria) result is 'PJSIP/bria-000000bb' [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx_variables.c: Expression result is '"PJSIP/bria-000000bb"' [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx.c: Launching 'MSet' [Feb 9 13:13:17] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:2] MSet("PJSIP/voip-t-000000bc", "briaCHAN="PJSIP/bria-000000bb"") in new stack [Feb 9 13:13:17] DEBUG[54595][C-000000bc] pbx.c: Launching 'Answer' [Feb 9 13:13:17] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:3] Answer("PJSIP/voip-t-000000bc", "1000") in new stack [Feb 9 13:13:17] DEBUG[54121] devicestate.c: No provider found, checking channel drivers for PJSIP - voip-t [Feb 9 13:13:17] DEBUG[54121] devicestate.c: Changing state for PJSIP/voip-t - state 2 (In use) [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:17] DEBUG[54570] netsock2.c: Splitting '192.168.26.61' into... [Feb 9 13:13:17] DEBUG[54570] netsock2.c: ...host '192.168.26.61' and port ''. [Feb 9 13:13:17] DEBUG[54570] acl.c: For destination '192.168.26.61', our source address is '192.168.26.66'. [Feb 9 13:13:17] DEBUG[54570] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f5a5001ef90' [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f59fdd20f80 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Copying payload 0 (0x7f5a50027c68) from 0x7f59fdd20f80 to 0x7f5a5001f158 [Feb 9 13:13:17] DEBUG[54570] rtp_engine.c: Copying payload 101 (0x7f5a5001ca78) from 0x7f59fdd20f80 to 0x7f5a5001f158 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Feb 9 13:13:17] DEBUG[54570] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.26.66:5060 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8043418) [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f59e8043418) [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8043418 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:17] DEBUG[54134] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f59e8006bb8 for Request msg ACK/cseq=102 (rdata0x7f5a30000918) [Feb 9 13:13:17] DEBUG[54134] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002a on dialog dlg0x7f59e8006bb8 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f59e8043418 [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current transaction state is Terminated [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The transaction state change event is USER [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is CONNECTING [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Received request [Feb 9 13:13:17] DEBUG[54570] res_pjsip_session.c: Method is ACK [Feb 9 13:13:17] DEBUG[54595][C-000000bc] res_rtp_asterisk.c: 0x7f5a500249e0 -- Probation learning mode pass with source address 192.168.26.61:13006 [Feb 9 13:13:17] VERBOSE[54595][C-000000bc] res_rtp_asterisk.c: 0x7f5a500249e0 -- Probation passed - setting RTP source address to 192.168.26.61:13006 [Feb 9 13:13:18] DEBUG[54595][C-000000bc] channel.c: Didn't receive a media frame from PJSIP/voip-t-000000bc within 1000 ms of answering. Continuing anyway [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx_variables.c: Result of 'briaCHAN' is 'PJSIP/bria-000000bb' [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx_variables.c: Expression result is '0' [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx.c: Launching 'GotoIf' [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:4] GotoIf("PJSIP/voip-t-000000bc", "0?5:6") in new stack [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] pbx_builtins.c: Goto (default,1234,6) [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx.c: Launching 'NoOp' [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:6] NoOp("PJSIP/voip-t-000000bc", "Finish if_default_7") in new stack [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx_variables.c: Result of 'briaCHAN' is 'PJSIP/bria-000000bb' [Feb 9 13:13:18] DEBUG[54595][C-000000bc] pbx.c: Launching 'Bridge' [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] pbx.c: Executing [1234@default:7] Bridge("PJSIP/voip-t-000000bc", "PJSIP/bria-000000bb,pF") in new stack [Feb 9 13:13:18] DEBUG[54595][C-000000bc] dahdi/bridge_native_dahdi.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: Cannot use native DAHDI. Must have two channels. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge_native_rtp.c: Bridge '4059192a-3319-44d5-9176-edf9c3328648' can not use native RTP bridge as two channels are required [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Chose bridge technology simple_bridge [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling simple_bridge technology constructor [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling simple_bridge technology start [Feb 9 13:13:18] DEBUG[54595][C-000000bc] channel.c: Actually Masquerading PJSIP/bria-000000bb(6) into the structure of Surrogate/PJSIP/bria-000000bb(0) [Feb 9 13:13:18] DEBUG[54595][C-000000bc] channel.c: Putting channel PJSIP/bria-000000bb in ulaw/ulaw formats [Feb 9 13:13:18] DEBUG[54595][C-000000bc] channel.c: Done Masquerading PJSIP/bria-000000bb (6) [Feb 9 13:13:18] VERBOSE[54593][C-000000bb] res_musiconhold.c: Stopped music on hold on Surrogate/PJSIP/bria-000000bb [Feb 9 13:13:18] DEBUG[54593][C-000000bb] channel.c: Channel Surrogate/PJSIP/bria-000000bb setting write format path: ulaw -> ulaw [Feb 9 13:13:18] DEBUG[54593][C-000000bb] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 13:13:18] DEBUG[54593][C-000000bb] pbx.c: Spawn extension (default,5678,3) exited non-zero on 'Surrogate/PJSIP/bria-000000bb' [Feb 9 13:13:18] VERBOSE[54593][C-000000bb] pbx.c: Spawn extension (default, 5678, 3) exited non-zero on 'Surrogate/PJSIP/bria-000000bb' [Feb 9 13:13:18] DEBUG[54593][C-000000bb] channel.c: Soft-Hanging (0x10) up channel 'Surrogate/PJSIP/bria-000000bb' [Feb 9 13:13:18] DEBUG[54593][C-000000bb] channel.c: Hanging up channel 'Surrogate/PJSIP/bria-000000bb' [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00f230(PJSIP/bria-000000bb) is joining [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: pushing 0x7f5a2c00f230(PJSIP/bria-000000bb) [Feb 9 13:13:18] VERBOSE[54596][C-000000bc] bridge_channel.c: Channel PJSIP/bria-000000bb joined 'simple_bridge' basic-bridge <4059192a-3319-44d5-9176-edf9c3328648> [Feb 9 13:13:18] DEBUG[54596][C-000000bc] dahdi/bridge_native_dahdi.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: Cannot use native DAHDI. Must have two channels. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge_native_rtp.c: Bridge '4059192a-3319-44d5-9176-edf9c3328648' can not use native RTP bridge as two channels are required [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Chose bridge technology simple_bridge [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648 is already using the new technology. [Feb 9 13:13:18] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00f230(PJSIP/bria-000000bb) is joining simple_bridge technology [Feb 9 13:13:18] DEBUG[54121] devicestate.c: No provider found, checking channel drivers for Surrogate - PJSIP/bria [Feb 9 13:13:18] DEBUG[54121] devicestate.c: Changing state for Surrogate/PJSIP/bria - state 0 (Unknown) [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) is joining [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: pushing 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) [Feb 9 13:13:18] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 9 13:13:18] VERBOSE[54596][C-000000bc] file.c: Playing 'vm-login.ulaw' (language 'en') [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] bridge_channel.c: Channel PJSIP/voip-t-000000bc joined 'simple_bridge' basic-bridge <4059192a-3319-44d5-9176-edf9c3328648> [Feb 9 13:13:18] DEBUG[54122] cdr.c: Finalized CDR for PJSIP/bria-000000bb - start 1486663991.827386 answer 1486663991.827912 end 1486663998.560913 dispo ANSWERED [Feb 9 13:13:18] DEBUG[54595][C-000000bc] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/bria-000000bb' is not DAHDI. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] dahdi/bridge_native_dahdi.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: Cannot use native DAHDI. Channel 'PJSIP/bria-000000bb' not compatible. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Chose bridge technology native_rtp [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: switching from simple_bridge technology to native_rtp [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling native_rtp technology constructor [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: moving 0x7f5a2c00f230(PJSIP/bria-000000bb) to dummy bridge temporarily [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00f230(PJSIP/bria-000000bb) is leaving simple_bridge technology (dummy) [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling simple_bridge technology stop [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) is joining native_rtp technology [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/voip-t-000000bc' and 'PJSIP/bria-000000bb' in stack [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00f230(PJSIP/bria-000000bb) is joining native_rtp technology [Feb 9 13:13:18] VERBOSE[54595][C-000000bc] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/voip-t-000000bc' and 'PJSIP/bria-000000bb' in stack [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling native_rtp technology start [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling simple_bridge technology destructor [Feb 9 13:13:18] DEBUG[54595][C-000000bc] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/voip-t-000000bc' is not DAHDI. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] dahdi/bridge_native_dahdi.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: Cannot use native DAHDI. Channel 'PJSIP/voip-t-000000bc' not compatible. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Chose bridge technology native_rtp [Feb 9 13:13:18] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648 is already using the new technology. [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The state change pertains to the endpoint 'bria()' [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f59e802afc8 [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The current transaction state is Terminated [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The transaction state change event is TIMER [Feb 9 13:13:18] DEBUG[54134] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 9 13:13:18] DEBUG[54570] res_pjsip_session.c: Destroying SIP session with endpoint bria [Feb 9 13:13:18] DEBUG[54570] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f5a5000b9d0' [Feb 9 13:13:18] DEBUG[54570] rtp_engine.c: Destroyed RTP instance '0x7f5a5000b9d0' [Feb 9 13:13:21] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (320 requested / 320 actual) timer ticks per second [Feb 9 13:13:21] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 13:13:21] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 13:13:21] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 13:13:21] VERBOSE[54596][C-000000bc] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/voip-t-000000bc' and 'PJSIP/bria-000000bb' in stack [Feb 9 13:13:21] DEBUG[54596][C-000000bc] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/voip-t-000000bc' is not DAHDI. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] dahdi/bridge_native_dahdi.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: Cannot use native DAHDI. Channel 'PJSIP/voip-t-000000bc' not compatible. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] bridge.c: Chose bridge technology native_rtp [Feb 9 13:13:21] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648 is already using the new technology. [Feb 9 13:13:21] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 100 bytes [Feb 9 13:13:21] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:22] DEBUG[54595][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 9 13:13:24] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 100 bytes [Feb 9 13:13:24] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:26] DEBUG[54572] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 9 13:13:26] DEBUG[54574] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 9 13:13:26] DEBUG[54573] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 9 13:13:26] DEBUG[54571] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 9 13:13:26] DEBUG[54132] threadpool.c: Destroying worker thread 105 [Feb 9 13:13:26] DEBUG[54132] threadpool.c: Destroying worker thread 104 [Feb 9 13:13:26] DEBUG[54132] threadpool.c: Destroying worker thread 102 [Feb 9 13:13:26] DEBUG[54132] threadpool.c: Destroying worker thread 103 [Feb 9 13:13:26] DEBUG[54134] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=102 (rdata0x7f5a30000918) [Feb 9 13:13:26] DEBUG[54134] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002d to use for Request msg OPTIONS/cseq=102 (rdata0x7f5a30000918) [Feb 9 13:13:26] DEBUG[54570] netsock2.c: Splitting '192.168.26.61' into... [Feb 9 13:13:26] DEBUG[54570] netsock2.c: ...host '192.168.26.61' and port ''. [Feb 9 13:13:26] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.26.61:5060 matches identify 'voip-t' [Feb 9 13:13:26] DEBUG[54570] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint voip-t [Feb 9 13:13:27] DEBUG[54134] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f59e8006bb8 for Request msg BYE/cseq=103 (rdata0x7f5a30000918) [Feb 9 13:13:27] DEBUG[54134] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002a on dialog dlg0x7f59e8006bb8 [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f59e802afc8 [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Received request [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Method is BYE [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'voip-t(PJSIP/voip-t-000000bc)' [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f59e802afc8 [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 9 13:13:27] DEBUG[54570] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge_channel.c: Setting 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) state from:0 to:1 [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: pulling 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) [Feb 9 13:13:27] VERBOSE[54595][C-000000bc] bridge_channel.c: Channel PJSIP/voip-t-000000bc left 'native_rtp' basic-bridge <4059192a-3319-44d5-9176-edf9c3328648> [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00ee50(PJSIP/voip-t-000000bc) is leaving native_rtp technology [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/voip-t-000000bc' and 'PJSIP/bria-000000bb' - media will flow through Asterisk core [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: dissolving bridge with cause 16(Normal Clearing) [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge_channel.c: Setting 0x7f5a2c00f230(PJSIP/bria-000000bb) state from:0 to:2 [Feb 9 13:13:27] DEBUG[54132] threadpool.c: Increasing threadpool SIP's size by 5 [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: queueing action type:13 sub:1001 [Feb 9 13:13:27] DEBUG[54122] cdr.c: Finalized CDR for PJSIP/voip-t-000000bc - start 1486663997.554630 answer 1486663997.555197 end 1486664007.554947 dispo ANSWERED [Feb 9 13:13:27] DEBUG[54595][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648 is dissolved, not performing smart bridge operation. [Feb 9 13:13:27] DEBUG[54595][C-000000bc] pbx.c: Extension 1234, priority 7 returned normally even though call was hung up [Feb 9 13:13:27] DEBUG[54595][C-000000bc] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/voip-t-000000bc' [Feb 9 13:13:27] DEBUG[54595][C-000000bc] channel.c: Hanging up channel 'PJSIP/voip-t-000000bc' [Feb 9 13:13:27] DEBUG[54595][C-000000bc] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: pulling 0x7f5a2c00f230(PJSIP/bria-000000bb) [Feb 9 13:13:27] VERBOSE[54596][C-000000bc] bridge_channel.c: Channel PJSIP/bria-000000bb left 'native_rtp' basic-bridge <4059192a-3319-44d5-9176-edf9c3328648> [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge_channel.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: 0x7f5a2c00f230(PJSIP/bria-000000bb) is leaving native_rtp technology [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648 is dissolved, not performing smart bridge operation. [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: actually destroying basic bridge, nobody wants it anymore [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling basic bridge destructor [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling native_rtp technology stop [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge.c: Bridge 4059192a-3319-44d5-9176-edf9c3328648: calling native_rtp technology destructor [Feb 9 13:13:27] DEBUG[54596][C-000000bc] bridge_after.c: Setup after bridge goto location to default,1234,8. [Feb 9 13:13:27] DEBUG[54596][C-000000bc] pbx.c: Launching 'MusicOnHold' [Feb 9 13:13:27] DEBUG[54121] devicestate.c: No provider found, checking channel drivers for PJSIP - voip-t [Feb 9 13:13:27] VERBOSE[54596][C-000000bc] pbx.c: Executing [1234@default:8] MusicOnHold("PJSIP/bria-000000bb", "") in new stack [Feb 9 13:13:27] DEBUG[54121] devicestate.c: Changing state for PJSIP/voip-t - state 1 (Not in use) [Feb 9 13:13:27] VERBOSE[54596][C-000000bc] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/bria-000000bb' [Feb 9 13:13:27] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 9 13:13:27] DEBUG[54596][C-000000bc] res_musiconhold.c: PJSIP/bria-000000bb Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Feb 9 13:13:27] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Difference is 51648, ms is 6476 [Feb 9 13:13:28] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 100 bytes [Feb 9 13:13:28] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:30] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 100 bytes [Feb 9 13:13:30] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:30] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Got RTCP report of 60 bytes [Feb 9 13:13:30] DEBUG[54596][C-000000bc] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.26.1:52617 [Feb 9 13:13:30] DEBUG[54134] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f59e800cb08 for Request msg BYE/cseq=3 (rdata0x7f5a30000918) [Feb 9 13:13:30] DEBUG[54134] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000021 on dialog dlg0x7f59e800cb08 [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f59e8043418 [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: There is no transaction involved in this state change [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Received request [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Method is BYE [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The state change pertains to the endpoint 'bria(PJSIP/bria-000000bb)' [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f59e8043418 [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The current transaction state is Completed [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 9 13:13:30] DEBUG[54570] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 9 13:13:30] VERBOSE[54596][C-000000bc] res_musiconhold.c: Stopped music on hold on PJSIP/bria-000000bb [Feb 9 13:13:30] DEBUG[54596][C-000000bc] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 13:13:30] DEBUG[54596][C-000000bc] pbx.c: Spawn extension (default,1234,8) exited non-zero on 'PJSIP/bria-000000bb' [Feb 9 13:13:30] VERBOSE[54596][C-000000bc] pbx.c: Spawn extension (default, 1234, 8) exited non-zero on 'PJSIP/bria-000000bb' [Feb 9 13:13:30] DEBUG[54596][C-000000bc] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/bria-000000bb' [Feb 9 13:13:30] DEBUG[54596][C-000000bc] channel.c: Hanging up channel 'PJSIP/bria-000000bb' [Feb 9 13:13:30] DEBUG[54596][C-000000bc] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Feb 9 13:13:30] DEBUG[54122] cdr.c: Finalized CDR for PJSIP/bria-000000bb - start 1486664007.555482 answer 1486664007.555482 end 1486664010.914286 dispo ANSWERED [Feb 9 13:13:30] DEBUG[54121] devicestate.c: No provider found, checking channel drivers for PJSIP - bria [Feb 9 13:13:30] DEBUG[54121] devicestate.c: Changing state for PJSIP/bria - state 1 (Not in use)