[Jun 26 16:27:51] Asterisk 13.4.0 built by root @ newtonr-laptop on a x86_64 running Linux on 2015-06-26 20:41:07 UTC
[Jun 26 16:27:51] DEBUG[21226] config.c: Parsing /etc/asterisk/logger.conf
[Jun 26 16:27:51] VERBOSE[21226] config.c: Parsing '/etc/asterisk/logger.conf': Found
[Jun 26 16:27:51] VERBOSE[21226] logger.c: Asterisk Queue Logger restarted
[Jun 26 16:27:52] DEBUG[21314] threadpool.c: Worker thread idle timeout reached. Dying.
[Jun 26 16:27:52] DEBUG[21228] threadpool.c: Destroying worker thread 18
[Jun 26 16:27:52] DEBUG[21312] threadpool.c: Worker thread idle timeout reached. Dying.
[Jun 26 16:27:52] DEBUG[21228] threadpool.c: Destroying worker thread 17
[Jun 26 16:27:55] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=13732 (rdata0x7f722c002048)
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=13732 (rdata0x7f722c007538)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	      endpoint .Response msg 401/INVITE/cseq=13732 (tdta0x7f7230032e60) created
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port ''.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tdta0x7f723003 .Destroying txdata Response msg 401/INVITE/cseq=13732 (tdta0x7f7230032e60)
[Jun 26 16:27:55] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Request msg ACK/cseq=13732 (rdata0x7f722c002048)
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=13732 (rdata0x7f722c007278)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE
[Jun 26 16:27:55] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=13733 (rdata0x7f722c002048)
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=13733 (rdata0x7f722c007658)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	      endpoint .Response msg 401/INVITE/cseq=13733 (tdta0x7f7230032e60) created
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_authenticator_digest.c: Calculated nonce 1435354075/bc06237900817f06c9e16105d6f340c6. Actual nonce is 1435354075/bc06237900817f06c9e16105d6f340c6
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port ''.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tdta0x7f723003 .Destroying txdata Response msg 401/INVITE/cseq=13733 (tdta0x7f7230032e60)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Transaction created for Request msg INVITE/cseq=13733 (rdata0x7f722c007658)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 .Incoming Request msg INVITE/cseq=13733 (rdata0x7f722c007658) in state Null
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..State changed from Null to Trying, event=RX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ...Transaction tsx0x7f7230023958 state changed to Trying
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 .UAS dialog created
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 .Module mod-invite added as dialog usage, data=0x7f72300008e8
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Session count inc to 2 by mod-invite
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	inv0x7f7230039 .UAS invite session created for dialog dlg0x7f7230039aa8
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 .Module Session Module added as dialog usage, data=(nil)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Session count inc to 2 by Session Module
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port ''.
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f72300062e8'
[Jun 26 16:27:55] DEBUG[21306] res_rtp_asterisk.c: Allocated port 12106 for RTP instance '0x7f72300062e8'
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 ICE session created, comp_cnt=2, role is Unknown agent
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:12106, base=10.24.18.124:12106, prio=0x7effffff (2130706431)
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: RTP instance '0x7f72300062e8' is setup and ready to go
[Jun 26 16:27:55] DEBUG[21306] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f72300062e8'
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:12107, base=10.24.18.124:12107, prio=0x7efffffe (2130706430)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Destroying ICE session 0x7f723000ac58
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stuse0x7f72300 STUN session 0x7f7230018758 destroy request, ref_cnt=4
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stuse0x7f72300 STUN session 0x7f7230018f38 destroy request, ref_cnt=3
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	 ice_session.c ICE session 0x7f723000ac58 destroyed
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stun_session.c STUN session 0x7f7230018758 destroyed
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stun_session.c STUN session 0x7f7230018f38 destroyed
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 111 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 18 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 0 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 58 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 118 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 9 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 8 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 58 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Setting payload 96 (0x7f7230013958) based on m type on 0x7f72a0102680
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 0 (0x7f72300088e8) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 8 (0x7f7230037518) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 9 (0x7f72300089e8) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 18 (0x7f7230008868) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 58 (0x7f7230008968) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 96 (0x7f7230015ae8) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 111 (0x7f723000d258) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Copying payload 118 (0x7f7230015a68) from 0x7f72a0102680 to 0x7f72300064b0
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Media stream 'audio' handled by audio
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	      endpoint .Response msg 100/INVITE/cseq=13733 (tdta0x7f722c001010) created
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 .Initial answer Response msg 100/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	inv0x7f7230039 .Sending Response msg 100/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Sending Response msg 100/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Sending Response msg 100/INVITE/cseq=13733 (tdta0x7f722c001010) in state Trying
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...State changed from Trying to Proceeding, event=TX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ....Transaction tsx0x7f7230023958 state changed to Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is INCOMING
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current transaction state is Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is INCOMING
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 Module NAT added as dialog usage, data=(nil)
[Jun 26 16:27:55] DEBUG[21228] threadpool.c: Increasing threadpool stasis-core's size by 1
[Jun 26 16:27:55] DEBUG[21306] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/ALICE-00000006
[Jun 26 16:27:55] DEBUG[21317][C-00000003] pbx.c: Launching 'Dial'
[Jun 26 16:27:55] VERBOSE[21317][C-00000003] pbx.c: Executing [102@from-internal:1] Dial("PJSIP/ALICE-00000006", "PJSIP/BOB,30,T") in new stack
[Jun 26 16:27:55] DEBUG[21306] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Jun 26 16:27:55] DEBUG[21306] config.c: extract int from [0] in [0, 86400] gives [0](0)
[Jun 26 16:27:55] DEBUG[21306] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 UAC dialog created
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module Outbound Authentica added as dialog usage, data=0x7f723002de80
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module mod-invite added as dialog usage, data=0x7f72300104b8
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 .Session count inc to 2 by mod-invite
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module mod-100rel added as dialog usage, data=0x7f7230010678
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 100rel module attached
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	inv0x7f7230033 UAC invite session created for dialog dlg0x7f7230033f18
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 .Session count inc to 2 by Session Module
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module Session Module added as dialog usage, data=(nil)
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f72300106f8'
[Jun 26 16:27:55] VERBOSE[21317][C-00000003] app_dial.c: Called PJSIP/BOB
[Jun 26 16:27:55] DEBUG[21306] res_rtp_asterisk.c: Allocated port 11582 for RTP instance '0x7f72300106f8'
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 ICE session created, comp_cnt=2, role is Unknown agent
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:11582, base=10.24.18.124:11582, prio=0x7effffff (2130706431)
[Jun 26 16:27:55] DEBUG[21306] rtp_engine.c: RTP instance '0x7f72300106f8' is setup and ready to go
[Jun 26 16:27:55] DEBUG[21306] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f72300106f8'
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.124' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.124' and port ''.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:11583, base=10.24.18.124:11583, prio=0x7efffffe (2130706430)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	icess0x7f72300 Destroying ICE session 0x7f7230030278
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stuse0x7f72300 STUN session 0x7f723001f5f8 destroy request, ref_cnt=4
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stuse0x7f72300 STUN session 0x7f72300205f8 destroy request, ref_cnt=3
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	 ice_session.c ICE session 0x7f7230030278 destroyed
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stun_session.c STUN session 0x7f723001f5f8 destroyed
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	stun_session.c STUN session 0x7f72300205f8 destroyed
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	      endpoint Request msg INVITE/cseq=22658 (tdta0x7f7230032e60) created.
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module WebSocket Transport Module added as dialog usage, data=(nil)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 Module NAT added as dialog usage, data=(nil)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	inv0x7f7230033 .Sending Request msg INVITE/cseq=22658 (tdta0x7f7230032e60)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ..Sending Request msg INVITE/cseq=22658 (tdta0x7f7230032e60)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 ...Transaction created for Request msg INVITE/cseq=22657 (tdta0x7f7230032e60)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..Sending Request msg INVITE/cseq=22657 (tdta0x7f7230032e60) in state Null
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	 sip_resolve.c ...Target '10.24.18.138:5060' type=Unspecified resolved to '10.24.18.138:5060' type=UDP (UDP transport)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 ...State changed from Null to Calling, event=TX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ....Transaction tsx0x7f7230032518 state changed to Calling
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is CALLING
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending request
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current transaction state is Calling
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is CALLING
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending request
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE
[Jun 26 16:27:55] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=22657 (rdata0x7f722c002048)
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=22657 (rdata0x7f722c0062d8)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 .Incoming Response msg 100/INVITE/cseq=22657 (rdata0x7f722c0062d8) in state Calling
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..State changed from Calling to Proceeding, event=RX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Received Response msg 100/INVITE/cseq=22657 (rdata0x7f722c0062d8)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Transaction tsx0x7f7230032518 state changed to Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current transaction state is Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is CALLING
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Response is 100 Trying
[Jun 26 16:27:55] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=22657 (rdata0x7f722c002048)
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=22657 (rdata0x7f722c0063b8)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 .Incoming Response msg 180/INVITE/cseq=22657 (rdata0x7f722c0063b8) in state Proceeding
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..State changed from Proceeding to Proceeding, event=RX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Received Response msg 180/INVITE/cseq=22657 (rdata0x7f722c0063b8)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ....Route-set updated
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Transaction tsx0x7f7230032518 state changed to Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is EARLY
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Response is 180 ringing
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current transaction state is Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is EARLY
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Response is 180 ringing
[Jun 26 16:27:55] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB
[Jun 26 16:27:55] VERBOSE[21317][C-00000003] app_dial.c: PJSIP/BOB-00000007 is ringing
[Jun 26 16:27:55] DEBUG[21240] devicestate.c: Changing state for PJSIP/BOB - state 6 (Ringing)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
[Jun 26 16:27:55] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	inv0x7f7230039 .Sending Response msg 180/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:55] DEBUG[21297] app_queue.c: Device 'PJSIP/BOB' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Sending Response msg 180/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:55] DEBUG[21240] devicestate.c: Changing state for PJSIP/ALICE - state 2 (In use)
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Sending Response msg 180/INVITE/cseq=13733 (tdta0x7f722c001010) in state Proceeding
[Jun 26 16:27:55] DEBUG[21297] app_queue.c: Device 'PJSIP/ALICE' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:55] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...State changed from Proceeding to Proceeding, event=TX_MSG
[Jun 26 16:27:55] DEBUG[21306] pjsip: 	dlg0x7f7230039 ....Transaction tsx0x7f7230023958 state changed to Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is EARLY
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current transaction state is Proceeding
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: The current inv state is EARLY
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:55] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
[Jun 26 16:27:56] DEBUG[21311] threadpool.c: Worker thread idle timeout reached. Dying.
[Jun 26 16:27:56] DEBUG[21227] threadpool.c: Destroying worker thread 16
[Jun 26 16:27:57] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=22657 (rdata0x7f722c002048)
[Jun 26 16:27:57] DEBUG[21256] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:27:57] DEBUG[21256] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:27:57] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:57] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=22657 (rdata0x7f722c0070e8)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	tsx0x7f7230032 .Incoming Response msg 200/INVITE/cseq=22657 (rdata0x7f722c0070e8) in state Proceeding
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..State changed from Proceeding to Terminated, event=RX_MSG
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Received Response msg 200/INVITE/cseq=22657 (rdata0x7f722c0070e8)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230033 ....Route-set updated
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230033 ....Route-set frozen
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230033 ...Transaction tsx0x7f7230032518 state changed to Terminated
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current inv state is CONNECTING
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Response is 200 OK
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	inv0x7f7230033 ....Got SDP answer in Response msg 200/INVITE/cseq=22657 (rdata0x7f722c0070e8)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	inv0x7f7230033 ....SDP negotiation done, status=0
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '10.24.18.138' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '10.24.18.138' and port ''.
[Jun 26 16:27:57] DEBUG[21306] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f72300106f8'
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Setting payload 0 (0x7f723000e3f8) based on m type on 0x7f72a0101e90
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Setting payload 101 (0x7f723000e3f8) based on m type on 0x7f72a0101e90
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Copying payload 0 (0x7f723002ed48) from 0x7f72a0101e90 to 0x7f72300108c0
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Copying payload 101 (0x7f7230010a48) from 0x7f72a0101e90 to 0x7f72300108c0
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	inv0x7f7230033 ....Received Response msg 200/INVITE/cseq=22657 (rdata0x7f722c0070e8), sending ACK
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	      endpoint ....Request msg ACK/cseq=22657 (tdta0x7f7230003c00) created.
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230033 .....Sending Request msg ACK/cseq=22657 (tdta0x7f7230003c00)
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: 0x7f723001c760 -- Probation learning mode pass with source address 10.24.18.138:4022
[Jun 26 16:27:57] VERBOSE[21317][C-00000003] res_rtp_asterisk.c: 0x7f723001c760 -- Probation passed - setting RTP source address to 10.24.18.138:4022
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	 sip_resolve.c .....Target '10.24.18.138:5060' type=Unspecified resolved to '10.24.18.138:5060' type=UDP (UDP transport)
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: No remote address on RTP instance '0x7f72300062e8' so dropping frame
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: No remote address on RTP instance '0x7f72300062e8' so dropping frame
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: No remote address on RTP instance '0x7f72300062e8' so dropping frame
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230032518)
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current inv state is CONFIRMED
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Sending request
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Method is ACK
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current transaction state is Terminated
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current inv state is CONFIRMED
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Response is 200 OK
[Jun 26 16:27:57] VERBOSE[21317][C-00000003] app_dial.c: PJSIP/BOB-00000007 answered PJSIP/ALICE-00000006
[Jun 26 16:27:57] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB
[Jun 26 16:27:57] DEBUG[21240] devicestate.c: Changing state for PJSIP/BOB - state 2 (In use)
[Jun 26 16:27:57] DEBUG[21297] app_queue.c: Device 'PJSIP/BOB' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 26 16:27:57] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE
[Jun 26 16:27:57] DEBUG[21240] devicestate.c: Changing state for PJSIP/ALICE - state 2 (In use)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	inv0x7f7230039 .SDP negotiation done, status=0
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '10.24.18.16' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port ''.
[Jun 26 16:27:57] DEBUG[21306] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f72300062e8'
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Setting payload 0 (0x7f723000e3f8) based on m type on 0x7f72a0102070
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Setting payload 96 (0x7f723000e3f8) based on m type on 0x7f72a0102070
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Copying payload 0 (0x7f723000c378) from 0x7f72a0102070 to 0x7f72300064b0
[Jun 26 16:27:57] DEBUG[21306] rtp_engine.c: Copying payload 96 (0x7f723002f9c8) from 0x7f72a0102070 to 0x7f72300064b0
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	inv0x7f7230039 .Sending Response msg 200/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Sending Response msg 200/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Sending Response msg 200/INVITE/cseq=13733 (tdta0x7f722c001010) in state Proceeding
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:57] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...State changed from Proceeding to Completed, event=TX_MSG
[Jun 26 16:27:57] DEBUG[21306] pjsip: 	dlg0x7f7230039 ....Transaction tsx0x7f7230023958 state changed to Completed
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current inv state is CONNECTING
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f7230023958)
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current transaction state is Completed
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: The current inv state is CONNECTING
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:27:57] DEBUG[21306] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge_native_rtp.c: Bridge '446cda5b-6f3a-4c26-950c-6450ee8808ca' can not use native RTP bridge as two channels are required
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: calling simple_bridge technology constructor
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: calling simple_bridge technology start
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006128(PJSIP/ALICE-00000006) is joining
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006e18(PJSIP/BOB-00000007) is joining
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: pushing 0x7f7284006128(PJSIP/ALICE-00000006)
[Jun 26 16:27:57] VERBOSE[21317][C-00000003] bridge_channel.c: Channel PJSIP/ALICE-00000006 joined 'simple_bridge' basic-bridge <446cda5b-6f3a-4c26-950c-6450ee8808ca>
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge_native_rtp.c: Bridge '446cda5b-6f3a-4c26-950c-6450ee8808ca' can not use native RTP bridge as two channels are required
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca is already using the new technology.
[Jun 26 16:27:57] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006128(PJSIP/ALICE-00000006) is joining simple_bridge technology
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: pushing 0x7f7284006e18(PJSIP/BOB-00000007)
[Jun 26 16:27:57] VERBOSE[21318][C-00000003] bridge_channel.c: Channel PJSIP/BOB-00000007 joined 'simple_bridge' basic-bridge <446cda5b-6f3a-4c26-950c-6450ee8808ca>
[Jun 26 16:27:57] DEBUG[21241] cdr.c: Finalized CDR for PJSIP/BOB-00000007 - start 1435354075.391267 answer 1435354077.845215 end 1435354077.848240 dispo ANSWERED
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge_native_rtp.c: Bridge '446cda5b-6f3a-4c26-950c-6450ee8808ca' can not use native RTP bridge as channel 'PJSIP/ALICE-00000006' has DTMF hooks
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca is already using the new technology.
[Jun 26 16:27:57] DEBUG[21318][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006e18(PJSIP/BOB-00000007) is joining simple_bridge technology
[Jun 26 16:27:57] DEBUG[21256] pjsip: 	tsx0x7f7230032 Timeout timer event
[Jun 26 16:27:57] DEBUG[21256] pjsip: 	tsx0x7f7230032 .State changed from Terminated to Destroyed, event=TIMER
[Jun 26 16:27:57] DEBUG[21256] pjsip: 	tsx0x7f7230032 Transaction destroyed!
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: Ooh, format changed from none to ulaw
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f72300062e8'
[Jun 26 16:27:57] DEBUG[21317][C-00000003] res_rtp_asterisk.c: 0x7f7230034680 -- Probation learning mode pass with source address 10.24.18.16:4000
[Jun 26 16:27:57] VERBOSE[21317][C-00000003] res_rtp_asterisk.c: 0x7f7230034680 -- Probation passed - setting RTP source address to 10.24.18.16:4000
[Jun 26 16:27:57] DEBUG[21318][C-00000003] res_rtp_asterisk.c: Ooh, format changed from none to ulaw
[Jun 26 16:27:58] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Request msg ACK/cseq=13733 (rdata0x7f722c002048)
[Jun 26 16:27:58] DEBUG[21256] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:27:58] DEBUG[21256] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:27:58] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:27:58] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:27:58] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=13733 (rdata0x7f722c0062f8)
[Jun 26 16:27:58] DEBUG[21306] pjsip: 	dlg0x7f7230039 .Received Request msg ACK/cseq=13733 (rdata0x7f722c0062f8)
[Jun 26 16:27:58] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Request to terminate transaction
[Jun 26 16:27:58] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...State changed from Completed to Terminated, event=USER
[Jun 26 16:27:58] DEBUG[21306] pjsip: 	dlg0x7f7230039 ....Transaction tsx0x7f7230023958 state changed to Terminated
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The current transaction state is Terminated
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The transaction state change event is USER
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The current inv state is CONNECTING
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: The current inv state is CONFIRMED
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: Received request
[Jun 26 16:27:58] DEBUG[21306] res_pjsip_session.c: Method is ACK
[Jun 26 16:27:58] DEBUG[21256] pjsip: 	tsx0x7f7230023 Timeout timer event
[Jun 26 16:27:58] DEBUG[21256] pjsip: 	tsx0x7f7230023 .State changed from Terminated to Destroyed, event=TIMER
[Jun 26 16:27:58] DEBUG[21256] pjsip: 	tdta0x7f722c00 ..Destroying txdata Response msg 200/INVITE/cseq=13733 (tdta0x7f722c001010)
[Jun 26 16:27:58] DEBUG[21256] pjsip: 	tsx0x7f7230023 Transaction destroyed!
[Jun 26 16:28:00] DEBUG[21317][C-00000003] res_rtp_asterisk.c: Got RTCP report of 64 bytes
[Jun 26 16:28:00] DEBUG[21317][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21317][C-00000003] netsock2.c: Splitting 'newtonr-laptop' into...
[Jun 26 16:28:00] DEBUG[21317][C-00000003] netsock2.c: ...host 'newtonr-laptop' and port ''.
[Jun 26 16:28:00] DEBUG[21317][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21317][C-00000003] acl.c: Attached to given IP address
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '10.24.18.16:4001' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '10.24.18.16' and port '4001'.
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '127.0.1.1:0' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '127.0.1.1' and port '0'.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] res_rtp_asterisk.c: Got RTCP report of 64 bytes
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] netsock2.c: Splitting 'newtonr-laptop' into...
[Jun 26 16:28:00] DEBUG[21318][C-00000003] netsock2.c: ...host 'newtonr-laptop' and port ''.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Attached to given IP address
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '10.24.18.138:4023' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '10.24.18.138' and port '4023'.
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '127.0.1.1:0' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '127.0.1.1' and port '0'.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] res_rtp_asterisk.c: Got RTCP report of 72 bytes
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] netsock2.c: Splitting 'newtonr-laptop' into...
[Jun 26 16:28:00] DEBUG[21318][C-00000003] netsock2.c: ...host 'newtonr-laptop' and port ''.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 26 16:28:00] DEBUG[21318][C-00000003] acl.c: Attached to given IP address
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '10.24.18.138:4023' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '10.24.18.138' and port '4023'.
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: Splitting '127.0.1.1:0' into...
[Jun 26 16:28:00] DEBUG[21287] netsock2.c: ...host '127.0.1.1' and port '0'.
[Jun 26 16:28:00] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Request msg BYE/cseq=32124 (rdata0x7f722c002048)
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=32124 (rdata0x7f722c0072c8)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 .Received Request msg BYE/cseq=32124 (rdata0x7f722c0072c8)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...Transaction created for Request msg BYE/cseq=32124 (rdata0x7f722c0072c8)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230023 ..Incoming Request msg BYE/cseq=32124 (rdata0x7f722c0072c8) in state Null
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230023 ...State changed from Null to Trying, event=RX_MSG
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 ....Transaction tsx0x7f7230023958 state changed to Trying
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	      endpoint .....Response msg 200/BYE/cseq=32124 (tdta0x7f723000ec70) created
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 ......Sending Response msg 200/BYE/cseq=32124 (tdta0x7f723000ec70)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230023 ......Sending Response msg 200/BYE/cseq=32124 (tdta0x7f723000ec70) in state Trying
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: Splitting '10.24.18.138:5060' into...
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: ...host '10.24.18.138' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230023 .......State changed from Trying to Completed, event=TX_MSG
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 ........Transaction tsx0x7f7230023958 state changed to Completed
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current transaction state is Completed
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is CONFIRMED
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Sending response
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Method is BYE, Response is 200 OK
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000007)'
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Received request
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Method is BYE
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tdta0x7f723000 .....Destroying txdata Request msg ACK/cseq=22657 (tdta0x7f7230003c00)
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge_channel.c: Setting 0x7f7284006e18(PJSIP/BOB-00000007) state from:0 to:1
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: pulling 0x7f7284006e18(PJSIP/BOB-00000007)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tdta0x7f723003 .....Destroying txdata Request msg INVITE/cseq=22657 (tdta0x7f7230032e60)
[Jun 26 16:28:00] VERBOSE[21318][C-00000003] bridge_channel.c: Channel PJSIP/BOB-00000007 left 'simple_bridge' basic-bridge <446cda5b-6f3a-4c26-950c-6450ee8808ca>
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006e18(PJSIP/BOB-00000007) is leaving simple_bridge technology
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 ......Session count dec to 4 by mod-invite
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: dissolving bridge with cause 16(Normal Clearing)
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: inv_session 0x7f72300104b8 has no ast session
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f7230023958
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge_channel.c: Setting 0x7f7284006128(PJSIP/ALICE-00000006) state from:0 to:2
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current transaction state is Completed
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: queueing action type:13 sub:1001
[Jun 26 16:28:00] DEBUG[21318][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca is dissolved, not performing smart bridge operation.
[Jun 26 16:28:00] DEBUG[21241] cdr.c: Finalized CDR for PJSIP/ALICE-00000006 - start 1435354075.389910 answer 1435354077.846067 end 1435354080.755576 dispo ANSWERED
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: pulling 0x7f7284006128(PJSIP/ALICE-00000006)
[Jun 26 16:28:00] VERBOSE[21317][C-00000003] bridge_channel.c: Channel PJSIP/ALICE-00000006 left 'simple_bridge' basic-bridge <446cda5b-6f3a-4c26-950c-6450ee8808ca>
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge_channel.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: 0x7f7284006128(PJSIP/ALICE-00000006) is leaving simple_bridge technology
[Jun 26 16:28:00] DEBUG[21318][C-00000003] channel.c: Hanging up channel 'PJSIP/BOB-00000007'
[Jun 26 16:28:00] DEBUG[21318][C-00000003] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca is dissolved, not performing smart bridge operation.
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Destroying SIP session with endpoint BOB
[Jun 26 16:28:00] DEBUG[21306] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f72300106f8'
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: actually destroying basic bridge, nobody wants it anymore
[Jun 26 16:28:00] DEBUG[21306] rtp_engine.c: Destroyed RTP instance '0x7f72300106f8'
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: calling basic bridge destructor
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230033 .Session count dec to 0 by Session Module
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: calling simple_bridge technology stop
[Jun 26 16:28:00] DEBUG[21317][C-00000003] bridge.c: Bridge 446cda5b-6f3a-4c26-950c-6450ee8808ca: calling simple_bridge technology destructor
[Jun 26 16:28:00] DEBUG[21241] cdr.c: CDR for PJSIP/BOB-00000007 is dialed and has no Party B; discarding
[Jun 26 16:28:00] DEBUG[21306] taskprocessor.c: destroying taskprocessor 'd0c19424-e813-41ae-ab76-292e236d4061'
[Jun 26 16:28:00] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB
[Jun 26 16:28:00] DEBUG[21240] devicestate.c: Changing state for PJSIP/BOB - state 1 (Not in use)
[Jun 26 16:28:00] DEBUG[21228] threadpool.c: Increasing threadpool stasis-core's size by 1
[Jun 26 16:28:00] DEBUG[21317][C-00000003] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jun 26 16:28:00] DEBUG[21317][C-00000003] pbx.c: Spawn extension (from-internal,102,1) exited non-zero on 'PJSIP/ALICE-00000006'
[Jun 26 16:28:00] DEBUG[21228] threadpool.c: Increasing threadpool stasis-core's size by 1
[Jun 26 16:28:00] DEBUG[21297] app_queue.c: Device 'PJSIP/BOB' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 26 16:28:00] VERBOSE[21317][C-00000003] pbx.c: Spawn extension (from-internal, 102, 1) exited non-zero on 'PJSIP/ALICE-00000006'
[Jun 26 16:28:00] DEBUG[21317][C-00000003] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/ALICE-00000006'
[Jun 26 16:28:00] DEBUG[21317][C-00000003] channel.c: Hanging up channel 'PJSIP/ALICE-00000006'
[Jun 26 16:28:00] DEBUG[21317][C-00000003] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	      endpoint .Request msg BYE/cseq=12260 (tdta0x7f722c001010) created.
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Method is BYE
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	inv0x7f7230039 .Sending Request msg BYE/cseq=12260 (tdta0x7f722c001010)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 ..Sending Request msg BYE/cseq=12260 (tdta0x7f722c001010)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230032 ...Transaction created for Request msg BYE/cseq=12259 (tdta0x7f722c001010)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..Sending Request msg BYE/cseq=12259 (tdta0x7f722c001010) in state Null
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	 sip_resolve.c ...Target '10.24.18.16:5060' type=Unspecified resolved to '10.24.18.16:5060' type=UDP (UDP transport)
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:28:00] DEBUG[21306] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230032 ...State changed from Null to Calling, event=TX_MSG
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 ....Transaction tsx0x7f7230032518 state changed to Calling
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000006)'
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current transaction state is Calling
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is CONFIRMED
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Sending request
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Method is BYE
[Jun 26 16:28:00] DEBUG[21240] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE
[Jun 26 16:28:00] DEBUG[21240] devicestate.c: Changing state for PJSIP/ALICE - state 1 (Not in use)
[Jun 26 16:28:00] DEBUG[21297] app_queue.c: Device 'PJSIP/ALICE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 26 16:28:00] DEBUG[21256] pjsip: 	sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=12259 (rdata0x7f722c002048)
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: Splitting '10.24.18.16:5060' into...
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: ...host '10.24.18.16' and port '5060'.
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: Splitting '0.0.0.0:5060' into...
[Jun 26 16:28:00] DEBUG[21256] netsock2.c: ...host '0.0.0.0' and port '5060'.
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=12259 (rdata0x7f722c006e88)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230032 .Incoming Response msg 200/BYE/cseq=12259 (rdata0x7f722c006e88) in state Calling
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	tsx0x7f7230032 ..State changed from Calling to Completed, event=RX_MSG
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 ...Received Response msg 200/BYE/cseq=12259 (rdata0x7f722c006e88)
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 ...Transaction tsx0x7f7230032518 state changed to Completed
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()'
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: There is no transaction involved in this state change
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Received response
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Response is 200 OK
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Destroying SIP session with endpoint ALICE
[Jun 26 16:28:00] DEBUG[21306] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f72300062e8'
[Jun 26 16:28:00] DEBUG[21306] rtp_engine.c: Destroyed RTP instance '0x7f72300062e8'
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 .....Session count dec to 2 by Session Module
[Jun 26 16:28:00] DEBUG[21306] pjsip: 	dlg0x7f7230039 .....Session count dec to 1 by mod-invite
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: inv_session 0x7f72300008e8 has no ast session
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current transaction state is Completed
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jun 26 16:28:00] DEBUG[21306] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:00] DEBUG[21306] taskprocessor.c: destroying taskprocessor '60424d2a-9b9c-4a82-a671-4983d9b97b46'
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tsx0x7f723000f Timeout timer event
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tsx0x7f723000f .State changed from Completed to Terminated, event=TIMER
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	dlg0x7f7230022 ..Transaction tsx0x7f723000fd28 state changed to Terminated
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: inv_session 0x7f7230016438 has no ast session
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f723000fd28
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: The current transaction state is Terminated
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: The transaction state change event is TIMER
[Jun 26 16:28:04] DEBUG[21256] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	dlg0x7f7230022 ...Dialog destroyed
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tsx0x7f723000f Timeout timer event
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tsx0x7f723000f .State changed from Terminated to Destroyed, event=TIMER
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tdta0x7f722c00 ..Destroying txdata Response msg 200/BYE/cseq=28891 (tdta0x7f722c003f70)
[Jun 26 16:28:04] DEBUG[21256] pjsip: 	tsx0x7f723000f Transaction destroyed!
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tsx0x7f7230032 Timeout timer event
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tsx0x7f7230032 .State changed from Completed to Terminated, event=TIMER
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	dlg0x7f7230039 ..Transaction tsx0x7f7230032518 state changed to Terminated
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: inv_session 0x7f72300008e8 has no ast session
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f7230032518
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: The current transaction state is Terminated
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: The transaction state change event is TIMER
[Jun 26 16:28:05] DEBUG[21256] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	dlg0x7f7230039 ...Dialog destroyed
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tsx0x7f7230032 Timeout timer event
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tsx0x7f7230032 .State changed from Terminated to Destroyed, event=TIMER
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tdta0x7f722c00 ..Destroying txdata Request msg BYE/cseq=12259 (tdta0x7f722c001010)
[Jun 26 16:28:05] DEBUG[21256] pjsip: 	tsx0x7f7230032 Transaction destroyed!
[Jun 26 16:28:10] DEBUG[21226] cdr.c: CDR Engine termination request received; waiting on messages...
[Jun 26 16:28:10] DEBUG[21226] taskprocessor.c: destroying taskprocessor 'ast_msg_queue'
[Jun 26 16:28:10] VERBOSE[21226] asterisk.c: Beginning asterisk shutdown....
[Jun 26 16:28:10] VERBOSE[21226] asterisk.c: Asterisk cleanly ending (0).
[Jun 26 16:28:10] VERBOSE[21226] asterisk.c: Executing last minute cleanups
[Jun 26 16:28:10] VERBOSE[21226] res_musiconhold.c: Destroying musiconhold processes
[Jun 26 16:28:10] DEBUG[21226] res_musiconhold.c: Destroying MOH class 'default'
[Jun 26 16:28:10] DEBUG[21226] taskprocessor.c: destroying taskprocessor 'e5562378-6ac8-4919-aa64-c25327e1d41b'
[Jun 26 16:28:10] VERBOSE[21226] manager.c: Manager unregistered action DBGet
[Jun 26 16:28:10] VERBOSE[21226] manager.c: Manager unregistered action DBPut
[Jun 26 16:28:10] VERBOSE[21226] manager.c: Manager unregistered action DBDel
[Jun 26 16:28:10] VERBOSE[21226] manager.c: Manager unregistered action DBDelTree
[Jun 26 16:28:10] DEBUG[21226] asterisk.c: Asterisk ending (0).