[Jun 26 16:21:29] Asterisk 13.3.2 built by root @ newtonr-laptop on a x86_64 running Linux on 2015-06-26 20:58:16 UTC [Jun 26 16:21:29] DEBUG[20354] config.c: Parsing /etc/asterisk/logger.conf [Jun 26 16:21:29] VERBOSE[20354] config.c: Parsing '/etc/asterisk/logger.conf': Found [Jun 26 16:21:29] VERBOSE[20354] logger.c: Asterisk Queue Logger restarted [Jun 26 16:21:34] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=4273 (rdata0x7fba8433cc38) [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=4273 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jun 26 16:21:34] DEBUG[20379] pjsip: endpoint .Response msg 401/INVITE/cseq=4273 (tdta0x7fba74004c40) created [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port ''. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: tdta0x7fba7400 .Destroying txdata Response msg 401/INVITE/cseq=4273 (tdta0x7fba74004c40) [Jun 26 16:21:34] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=4273 (rdata0x7fba8433cc38) [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=4273 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jun 26 16:21:34] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=4274 (rdata0x7fba8433cc38) [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=4274 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Jun 26 16:21:34] DEBUG[20379] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jun 26 16:21:34] DEBUG[20379] pjsip: endpoint .Response msg 401/INVITE/cseq=4274 (tdta0x7fba74004c40) created [Jun 26 16:21:34] DEBUG[20379] res_pjsip_authenticator_digest.c: Calculated nonce 1435353694/6ec39d9e50c673734803f2edfdcebc32. Actual nonce is 1435353694/6ec39d9e50c673734803f2edfdcebc32 [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port ''. [Jun 26 16:21:34] DEBUG[20379] pjsip: tdta0x7fba7400 .Destroying txdata Response msg 401/INVITE/cseq=4274 (tdta0x7fba74004c40) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ..Transaction created for Request msg INVITE/cseq=4274 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 .Incoming Request msg INVITE/cseq=4274 (rdata0x7fba8408b558) in state Null [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ..State changed from Null to Trying, event=RX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ...Transaction tsx0x7fba74009de8 state changed to Trying [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 .UAS dialog created [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 .Module mod-invite added as dialog usage, data=0x7fba7400c5e8 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ..Session count inc to 2 by mod-invite [Jun 26 16:21:34] DEBUG[20379] pjsip: inv0x7fba74023 .UAS invite session created for dialog dlg0x7fba74023dd8 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 .Module Session Module added as dialog usage, data=(nil) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ..Session count inc to 2 by Session Module [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port ''. [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fba7401b228' [Jun 26 16:21:34] DEBUG[20379] res_rtp_asterisk.c: Allocated port 10162 for RTP instance '0x7fba7401b228' [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:10162, base=10.24.18.124:10162, prio=0x7effffff (2130706431) [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: RTP instance '0x7fba7401b228' is setup and ready to go [Jun 26 16:21:34] DEBUG[20379] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fba7401b228' [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:10163, base=10.24.18.124:10163, prio=0x7efffffe (2130706430) [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Destroying ICE session 0x7fba74024d78 [Jun 26 16:21:34] DEBUG[20379] pjsip: stuse0x7fba740 STUN session 0x7fba74019ec8 destroy request, ref_cnt=4 [Jun 26 16:21:34] DEBUG[20379] pjsip: stuse0x7fba740 STUN session 0x7fba740290f8 destroy request, ref_cnt=3 [Jun 26 16:21:34] DEBUG[20379] pjsip: ice_session.c ICE session 0x7fba74024d78 destroyed [Jun 26 16:21:34] DEBUG[20379] pjsip: stun_session.c STUN session 0x7fba74019ec8 destroyed [Jun 26 16:21:34] DEBUG[20379] pjsip: stun_session.c STUN session 0x7fba740290f8 destroyed [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 111 (0x7fba7401adc8) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 18 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 0 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 58 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 118 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 9 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 8 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 58 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Setting payload 96 (0x7fba7401b188) based on m type on 0x7fbae40b7680 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 0 (0x7fba7400c218) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 8 (0x7fba74029fb8) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 9 (0x7fba74029f38) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 18 (0x7fba7401adc8) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 58 (0x7fba7400c298) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 96 (0x7fba7402a038) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 111 (0x7fba7401b108) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Copying payload 118 (0x7fba74029eb8) from 0x7fbae40b7680 to 0x7fba7401b3f0 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Media stream 'audio' handled by audio [Jun 26 16:21:34] DEBUG[20379] pjsip: endpoint .Response msg 100/INVITE/cseq=4274 (tdta0x7fba74003c30) created [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 .Initial answer Response msg 100/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 26 16:21:34] DEBUG[20379] pjsip: inv0x7fba74023 .Sending Response msg 100/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ..Sending Response msg 100/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ..Sending Response msg 100/INVITE/cseq=4274 (tdta0x7fba74003c30) in state Trying [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ...State changed from Trying to Proceeding, event=TX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ....Transaction tsx0x7fba74009de8 state changed to Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is INCOMING [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current transaction state is Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is INCOMING [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 Module NAT added as dialog usage, data=(nil) [Jun 26 16:21:34] DEBUG[20379] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/ALICE-00000002 [Jun 26 16:21:34] DEBUG[20432][C-00000001] pbx.c: Launching 'Dial' [Jun 26 16:21:34] VERBOSE[20432][C-00000001] pbx.c: Executing [102@from-internal:1] Dial("PJSIP/ALICE-00000002", "PJSIP/BOB,30,T") in new stack [Jun 26 16:21:34] DEBUG[20379] config.c: extract int from [0] in [0, 86400] gives [0](0) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f UAC dialog created [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module Outbound Authentica added as dialog usage, data=0x7fba74028220 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module mod-invite added as dialog usage, data=0x7fba7401e068 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f .Session count inc to 2 by mod-invite [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module mod-100rel added as dialog usage, data=0x7fba7401e228 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f 100rel module attached [Jun 26 16:21:34] DEBUG[20379] pjsip: inv0x7fba7401f UAC invite session created for dialog dlg0x7fba7401fdc8 [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f .Session count inc to 2 by Session Module [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module Session Module added as dialog usage, data=(nil) [Jun 26 16:21:34] VERBOSE[20432][C-00000001] app_dial.c: Called PJSIP/BOB [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fba7401e2a8' [Jun 26 16:21:34] DEBUG[20379] res_rtp_asterisk.c: Allocated port 15570 for RTP instance '0x7fba7401e2a8' [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:15570, base=10.24.18.124:15570, prio=0x7effffff (2130706431) [Jun 26 16:21:34] DEBUG[20379] rtp_engine.c: RTP instance '0x7fba7401e2a8' is setup and ready to go [Jun 26 16:21:34] DEBUG[20379] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fba7401e2a8' [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.124' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.124' and port ''. [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:15571, base=10.24.18.124:15571, prio=0x7efffffe (2130706430) [Jun 26 16:21:34] DEBUG[20379] pjsip: icess0x7fba740 Destroying ICE session 0x7fba74012238 [Jun 26 16:21:34] DEBUG[20379] pjsip: stuse0x7fba740 STUN session 0x7fba74014a78 destroy request, ref_cnt=4 [Jun 26 16:21:34] DEBUG[20379] pjsip: stuse0x7fba740 STUN session 0x7fba740081a8 destroy request, ref_cnt=3 [Jun 26 16:21:34] DEBUG[20379] pjsip: ice_session.c ICE session 0x7fba74012238 destroyed [Jun 26 16:21:34] DEBUG[20379] pjsip: stun_session.c STUN session 0x7fba74014a78 destroyed [Jun 26 16:21:34] DEBUG[20379] pjsip: stun_session.c STUN session 0x7fba740081a8 destroyed [Jun 26 16:21:34] DEBUG[20379] pjsip: endpoint Request msg INVITE/cseq=7227 (tdta0x7fba74004c40) created. [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module WebSocket Transport Module added as dialog usage, data=(nil) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f Module NAT added as dialog usage, data=(nil) [Jun 26 16:21:34] DEBUG[20379] pjsip: inv0x7fba7401f .Sending Request msg INVITE/cseq=7227 (tdta0x7fba74004c40) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ..Sending Request msg INVITE/cseq=7227 (tdta0x7fba74004c40) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c ...Transaction created for Request msg INVITE/cseq=7226 (tdta0x7fba74004c40) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c ..Sending Request msg INVITE/cseq=7226 (tdta0x7fba74004c40) in state Null [Jun 26 16:21:34] DEBUG[20379] 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:21:34] DEBUG[20379] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060 [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c ...State changed from Null to Calling, event=TX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ....Transaction tsx0x7fba7402c738 state changed to Calling [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is CALLING [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending request [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current transaction state is Calling [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is CALLING [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending request [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE [Jun 26 16:21:34] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=7226 (rdata0x7fba8433cc38) [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c .Incoming Response msg 100/INVITE/cseq=7226 (rdata0x7fba8408b558) in state Calling [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c ..State changed from Calling to Proceeding, event=RX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ...Received Response msg 100/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ...Transaction tsx0x7fba7402c738 state changed to Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current transaction state is Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is CALLING [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Response is 100 Trying [Jun 26 16:21:34] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=7226 (rdata0x7fba8433cc38) [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:34] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c .Incoming Response msg 180/INVITE/cseq=7226 (rdata0x7fba8408b558) in state Proceeding [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba7402c ..State changed from Proceeding to Proceeding, event=RX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ...Received Response msg 180/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ....Route-set updated [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba7401f ...Transaction tsx0x7fba7402c738 state changed to Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is EARLY [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Response is 180 ringing [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current transaction state is Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is EARLY [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Response is 180 ringing [Jun 26 16:21:34] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB [Jun 26 16:21:34] VERBOSE[20432][C-00000001] app_dial.c: PJSIP/BOB-00000003 is ringing [Jun 26 16:21:34] DEBUG[20368] devicestate.c: Changing state for PJSIP/BOB - state 6 (Ringing) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Jun 26 16:21:34] DEBUG[20379] pjsip: inv0x7fba74023 .Sending Response msg 180/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ..Sending Response msg 180/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:34] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ..Sending Response msg 180/INVITE/cseq=4274 (tdta0x7fba74003c30) in state Proceeding [Jun 26 16:21:34] DEBUG[20370] devicestate.c: No provider found, checking channel drivers for pjsip - BOB [Jun 26 16:21:34] DEBUG[20368] devicestate.c: Changing state for PJSIP/ALICE - state 2 (In use) [Jun 26 16:21:34] DEBUG[20370] app_queue.c: Extension '102@from-internal' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 26 16:21:34] DEBUG[20379] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060 [Jun 26 16:21:34] DEBUG[20370] devicestate.c: No provider found, checking channel drivers for pjsip - ALICE [Jun 26 16:21:34] DEBUG[20425] 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:21:34] DEBUG[20425] 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:21:34] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:34] DEBUG[20370] app_queue.c: Extension '101@from-internal' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:34] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:34] DEBUG[20379] pjsip: tsx0x7fba74009 ...State changed from Proceeding to Proceeding, event=TX_MSG [Jun 26 16:21:34] DEBUG[20379] pjsip: dlg0x7fba74023 ....Transaction tsx0x7fba74009de8 state changed to Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is EARLY [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current transaction state is Proceeding [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: The current inv state is EARLY [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:34] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Jun 26 16:21:38] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=7226 (rdata0x7fba8433cc38) [Jun 26 16:21:38] DEBUG[20384] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:38] DEBUG[20384] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:38] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:38] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba7402c .Incoming Response msg 200/INVITE/cseq=7226 (rdata0x7fba8408b558) in state Proceeding [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba7402c ..State changed from Proceeding to Terminated, event=RX_MSG [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba7401f ...Received Response msg 200/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba7401f ....Route-set updated [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba7401f ....Route-set frozen [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba7401f ...Transaction tsx0x7fba7402c738 state changed to Terminated [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONNECTING [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Response is 200 OK [Jun 26 16:21:38] DEBUG[20379] pjsip: inv0x7fba7401f ....Got SDP answer in Response msg 200/INVITE/cseq=7226 (rdata0x7fba8408b558) [Jun 26 16:21:38] DEBUG[20379] pjsip: inv0x7fba7401f ....SDP negotiation done, status=0 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '10.24.18.138' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '10.24.18.138' and port ''. [Jun 26 16:21:38] DEBUG[20379] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fba7401e2a8' [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Setting payload 0 (0x7fba7402f358) based on m type on 0x7fbae40b6e90 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Setting payload 101 (0x7fba7402f358) based on m type on 0x7fbae40b6e90 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Copying payload 0 (0x7fba7402f3d8) from 0x7fbae40b6e90 to 0x7fba7401e470 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Copying payload 101 (0x7fba7402f568) from 0x7fbae40b6e90 to 0x7fba7401e470 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jun 26 16:21:38] DEBUG[20379] pjsip: inv0x7fba7401f ....Received Response msg 200/INVITE/cseq=7226 (rdata0x7fba8408b558), sending ACK [Jun 26 16:21:38] DEBUG[20379] pjsip: endpoint ....Request msg ACK/cseq=7226 (tdta0x7fba740306d0) created. [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba7401f .....Sending Request msg ACK/cseq=7226 (tdta0x7fba740306d0) [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: 0x7fba7400f7b0 -- Probation learning mode pass with source address 10.24.18.138:4014 [Jun 26 16:21:38] VERBOSE[20432][C-00000001] res_rtp_asterisk.c: 0x7fba7400f7b0 -- Probation passed - setting RTP source address to 10.24.18.138:4014 [Jun 26 16:21:38] DEBUG[20379] 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:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: No remote address on RTP instance '0x7fba7401b228' so dropping frame [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: No remote address on RTP instance '0x7fba7401b228' so dropping frame [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: No remote address on RTP instance '0x7fba7401b228' so dropping frame [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba7402c738) [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Sending request [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Method is ACK [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current transaction state is Terminated [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Response is 200 OK [Jun 26 16:21:38] VERBOSE[20432][C-00000001] app_dial.c: PJSIP/BOB-00000003 answered PJSIP/ALICE-00000002 [Jun 26 16:21:38] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB [Jun 26 16:21:38] DEBUG[20368] devicestate.c: Changing state for PJSIP/BOB - state 2 (In use) [Jun 26 16:21:38] DEBUG[20370] devicestate.c: No provider found, checking channel drivers for pjsip - BOB [Jun 26 16:21:38] DEBUG[20370] app_queue.c: Extension '102@from-internal' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 26 16:21:38] DEBUG[20425] 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:21:38] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE [Jun 26 16:21:38] DEBUG[20368] devicestate.c: Changing state for PJSIP/ALICE - state 2 (In use) [Jun 26 16:21:38] DEBUG[20379] pjsip: inv0x7fba74023 .SDP negotiation done, status=0 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '10.24.18.16' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port ''. [Jun 26 16:21:38] DEBUG[20379] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fba7401b228' [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Setting payload 0 (0x7fba74031d58) based on m type on 0x7fbae40b7070 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Setting payload 96 (0x7fba74031d58) based on m type on 0x7fbae40b7070 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Copying payload 0 (0x7fba74031dd8) from 0x7fbae40b7070 to 0x7fba7401b3f0 [Jun 26 16:21:38] DEBUG[20379] rtp_engine.c: Copying payload 96 (0x7fba7402c418) from 0x7fbae40b7070 to 0x7fba7401b3f0 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 26 16:21:38] DEBUG[20379] pjsip: inv0x7fba74023 .Sending Response msg 200/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba74023 ..Sending Response msg 200/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba74009 ..Sending Response msg 200/INVITE/cseq=4274 (tdta0x7fba74003c30) in state Proceeding [Jun 26 16:21:38] DEBUG[20379] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.24.18.124:5060 [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:38] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba74009 ...State changed from Proceeding to Completed, event=TX_MSG [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba74023 ....Transaction tsx0x7fba74009de8 state changed to Completed [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONNECTING [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fba74009de8) [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current transaction state is Completed [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONNECTING [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 26 16:21:38] DEBUG[20432][C-00000001] features.c: Removing dialed interfaces datastore on PJSIP/BOB-00000003 since we're bridging [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge_native_rtp.c: Bridge 'd7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee' can not use native RTP bridge as two channels are required [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: calling simple_bridge technology constructor [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: calling simple_bridge technology start [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003aa8(PJSIP/ALICE-00000002) is joining [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003938(PJSIP/BOB-00000003) is joining [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: pushing 0x7fba68003aa8(PJSIP/ALICE-00000002) [Jun 26 16:21:38] VERBOSE[20432][C-00000001] bridge_channel.c: Channel PJSIP/ALICE-00000002 joined 'simple_bridge' basic-bridge [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge_native_rtp.c: Bridge 'd7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee' can not use native RTP bridge as two channels are required [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is already using the new technology. [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is happy that channel PJSIP/ALICE-00000002 already has read format ulaw [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is happy that channel PJSIP/ALICE-00000002 already has write format ulaw [Jun 26 16:21:38] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003aa8(PJSIP/ALICE-00000002) is joining simple_bridge technology [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: pushing 0x7fba68003938(PJSIP/BOB-00000003) [Jun 26 16:21:38] VERBOSE[20433][C-00000001] bridge_channel.c: Channel PJSIP/BOB-00000003 joined 'simple_bridge' basic-bridge [Jun 26 16:21:38] DEBUG[20369] cdr.c: Finalized CDR for PJSIP/BOB-00000003 - start 1435353694.456000 answer 1435353698.735430 end 1435353698.737579 dispo ANSWERED [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge_native_rtp.c: Bridge 'd7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee' can not use native RTP bridge as channel 'PJSIP/ALICE-00000002' has DTMF hooks [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is already using the new technology. [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is happy that channel PJSIP/BOB-00000003 already has read format ulaw [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is happy that channel PJSIP/BOB-00000003 already has write format ulaw [Jun 26 16:21:38] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003938(PJSIP/BOB-00000003) is joining simple_bridge technology [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fba7401b228' [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba7402c Timeout timer event [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba7402c .State changed from Terminated to Destroyed, event=TIMER [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba7402c Transaction destroyed! [Jun 26 16:21:38] DEBUG[20432][C-00000001] res_rtp_asterisk.c: 0x7fba74017350 -- Probation learning mode pass with source address 10.24.18.16:4056 [Jun 26 16:21:38] VERBOSE[20432][C-00000001] res_rtp_asterisk.c: 0x7fba74017350 -- Probation passed - setting RTP source address to 10.24.18.16:4056 [Jun 26 16:21:38] DEBUG[20433][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Jun 26 16:21:38] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=4274 (rdata0x7fba8433cc38) [Jun 26 16:21:38] DEBUG[20384] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:38] DEBUG[20384] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:38] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:38] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:38] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=4274 (rdata0x7fba8408b558) [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba74023 .Received Request msg ACK/cseq=4274 (rdata0x7fba8408b558) [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba74009 ..Request to terminate transaction [Jun 26 16:21:38] DEBUG[20379] pjsip: tsx0x7fba74009 ...State changed from Completed to Terminated, event=USER [Jun 26 16:21:38] DEBUG[20379] pjsip: dlg0x7fba74023 ....Transaction tsx0x7fba74009de8 state changed to Terminated [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current transaction state is Terminated [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The transaction state change event is USER [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONNECTING [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Received request [Jun 26 16:21:38] DEBUG[20379] res_pjsip_session.c: Method is ACK [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba74009 Timeout timer event [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba74009 .State changed from Terminated to Destroyed, event=TIMER [Jun 26 16:21:38] DEBUG[20384] pjsip: tdta0x7fba7400 ..Destroying txdata Response msg 200/INVITE/cseq=4274 (tdta0x7fba74003c30) [Jun 26 16:21:38] DEBUG[20384] pjsip: tsx0x7fba74009 Transaction destroyed! [Jun 26 16:21:41] DEBUG[20433][C-00000001] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jun 26 16:21:41] DEBUG[20433][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 26 16:21:41] DEBUG[20433][C-00000001] netsock2.c: Splitting 'newtonr-laptop' into... [Jun 26 16:21:41] DEBUG[20433][C-00000001] netsock2.c: ...host 'newtonr-laptop' and port ''. [Jun 26 16:21:41] DEBUG[20433][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 26 16:21:41] DEBUG[20433][C-00000001] acl.c: Attached to given IP address [Jun 26 16:21:41] DEBUG[20415] netsock2.c: Splitting '10.24.18.138:4015' into... [Jun 26 16:21:41] DEBUG[20415] netsock2.c: ...host '10.24.18.138' and port '4015'. [Jun 26 16:21:41] DEBUG[20415] netsock2.c: Splitting '127.0.1.1:0' into... [Jun 26 16:21:41] DEBUG[20415] netsock2.c: ...host '127.0.1.1' and port '0'. [Jun 26 16:21:41] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=7474 (rdata0x7fba8433cc38) [Jun 26 16:21:41] DEBUG[20384] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:41] DEBUG[20384] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:41] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:41] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=7474 (rdata0x7fba8408b558) [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f .Received Request msg BYE/cseq=7474 (rdata0x7fba8408b558) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba74009 ...Transaction created for Request msg BYE/cseq=7474 (rdata0x7fba8408b558) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba74009 ..Incoming Request msg BYE/cseq=7474 (rdata0x7fba8408b558) in state Null [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba74009 ...State changed from Null to Trying, event=RX_MSG [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f ....Transaction tsx0x7fba74009de8 state changed to Trying [Jun 26 16:21:41] DEBUG[20379] pjsip: endpoint .....Response msg 200/BYE/cseq=7474 (tdta0x7fba7402b100) created [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f ......Sending Response msg 200/BYE/cseq=7474 (tdta0x7fba7402b100) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba74009 ......Sending Response msg 200/BYE/cseq=7474 (tdta0x7fba7402b100) in state Trying [Jun 26 16:21:41] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:41] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] netsock2.c: Splitting '10.24.18.138:5060' into... [Jun 26 16:21:41] DEBUG[20379] netsock2.c: ...host '10.24.18.138' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba74009 .......State changed from Trying to Completed, event=TX_MSG [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f ........Transaction tsx0x7fba74009de8 state changed to Completed [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current transaction state is Completed [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Sending response [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Method is BYE, Response is 200 OK [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'BOB(PJSIP/BOB-00000003)' [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Received request [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Method is BYE [Jun 26 16:21:41] DEBUG[20379] pjsip: tdta0x7fba7403 .....Destroying txdata Request msg ACK/cseq=7226 (tdta0x7fba740306d0) [Jun 26 16:21:41] DEBUG[20379] pjsip: tdta0x7fba7400 .....Destroying txdata Request msg INVITE/cseq=7226 (tdta0x7fba74004c40) [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f ......Session count dec to 4 by mod-invite [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: inv_session 0x7fba7401e068 has no ast session [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fba74009de8 [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current transaction state is Completed [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge_channel.c: Setting 0x7fba68003938(PJSIP/BOB-00000003) state from:0 to:1 [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: pulling 0x7fba68003938(PJSIP/BOB-00000003) [Jun 26 16:21:41] VERBOSE[20433][C-00000001] bridge_channel.c: Channel PJSIP/BOB-00000003 left 'simple_bridge' basic-bridge [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003938(PJSIP/BOB-00000003) is leaving simple_bridge technology [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: dissolving bridge with cause 16(Normal Clearing) [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge_channel.c: Setting 0x7fba68003aa8(PJSIP/ALICE-00000002) state from:0 to:2 [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: queueing action type:13 sub:1001 [Jun 26 16:21:41] DEBUG[20369] cdr.c: Finalized CDR for PJSIP/ALICE-00000002 - start 1435353694.454234 answer 1435353698.735924 end 1435353701.985639 dispo ANSWERED [Jun 26 16:21:41] DEBUG[20433][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is dissolved, not performing smart bridge operation. [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: pulling 0x7fba68003aa8(PJSIP/ALICE-00000002) [Jun 26 16:21:41] VERBOSE[20432][C-00000001] bridge_channel.c: Channel PJSIP/ALICE-00000002 left 'simple_bridge' basic-bridge [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge_channel.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: 0x7fba68003aa8(PJSIP/ALICE-00000002) is leaving simple_bridge technology [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee is dissolved, not performing smart bridge operation. [Jun 26 16:21:41] DEBUG[20433][C-00000001] channel.c: Hanging up channel 'PJSIP/BOB-00000003' [Jun 26 16:21:41] DEBUG[20433][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Destroying SIP session with endpoint BOB [Jun 26 16:21:41] DEBUG[20379] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fba7401e2a8' [Jun 26 16:21:41] DEBUG[20379] rtp_engine.c: Destroyed RTP instance '0x7fba7401e2a8' [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba7401f .Session count dec to 0 by Session Module [Jun 26 16:21:41] DEBUG[20369] cdr.c: CDR for PJSIP/BOB-00000003 is dialed and has no Party B; discarding [Jun 26 16:21:41] DEBUG[20379] taskprocessor.c: destroying taskprocessor '8a711d90-89f5-4257-aaec-7c62360b47d9' [Jun 26 16:21:41] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - BOB [Jun 26 16:21:41] DEBUG[20368] devicestate.c: Changing state for PJSIP/BOB - state 1 (Not in use) [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: actually destroying basic bridge, nobody wants it anymore [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: calling basic bridge destructor [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: calling simple_bridge technology stop [Jun 26 16:21:41] DEBUG[20432][C-00000001] bridge.c: Bridge d7592b4d-fbf6-4b7d-ad8d-c2cdcde8c1ee: calling simple_bridge technology destructor [Jun 26 16:21:41] DEBUG[20370] devicestate.c: No provider found, checking channel drivers for pjsip - BOB [Jun 26 16:21:41] DEBUG[20370] app_queue.c: Extension '102@from-internal' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 16:21:41] DEBUG[20425] 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:21:41] DEBUG[20356] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jun 26 16:21:41] DEBUG[20432][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 26 16:21:41] DEBUG[20432][C-00000001] pbx.c: Spawn extension (from-internal,102,1) exited non-zero on 'PJSIP/ALICE-00000002' [Jun 26 16:21:41] VERBOSE[20432][C-00000001] pbx.c: Spawn extension (from-internal, 102, 1) exited non-zero on 'PJSIP/ALICE-00000002' [Jun 26 16:21:41] DEBUG[20432][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/ALICE-00000002' [Jun 26 16:21:41] DEBUG[20432][C-00000001] channel.c: Hanging up channel 'PJSIP/ALICE-00000002' [Jun 26 16:21:41] DEBUG[20432][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Jun 26 16:21:41] DEBUG[20379] pjsip: endpoint .Request msg BYE/cseq=6498 (tdta0x7fba74003c30) created. [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Method is BYE [Jun 26 16:21:41] DEBUG[20379] pjsip: inv0x7fba74023 .Sending Request msg BYE/cseq=6498 (tdta0x7fba74003c30) [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 ..Sending Request msg BYE/cseq=6498 (tdta0x7fba74003c30) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba7402c ...Transaction created for Request msg BYE/cseq=6497 (tdta0x7fba74003c30) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba7402c ..Sending Request msg BYE/cseq=6497 (tdta0x7fba74003c30) in state Null [Jun 26 16:21:41] DEBUG[20379] 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:21:41] DEBUG[20379] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:41] DEBUG[20379] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:41] DEBUG[20379] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba7402c ...State changed from Null to Calling, event=TX_MSG [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 ....Transaction tsx0x7fba7402c738 state changed to Calling [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000002)' [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current transaction state is Calling [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Sending request [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Method is BYE [Jun 26 16:21:41] DEBUG[20368] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE [Jun 26 16:21:41] DEBUG[20368] devicestate.c: Changing state for PJSIP/ALICE - state 1 (Not in use) [Jun 26 16:21:41] DEBUG[20370] devicestate.c: No provider found, checking channel drivers for pjsip - ALICE [Jun 26 16:21:41] DEBUG[20370] app_queue.c: Extension '101@from-internal' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 16:21:41] DEBUG[20425] 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:21:41] DEBUG[20384] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=6497 (rdata0x7fba8433cc38) [Jun 26 16:21:41] DEBUG[20384] netsock2.c: Splitting '10.24.18.16:5060' into... [Jun 26 16:21:41] DEBUG[20384] netsock2.c: ...host '10.24.18.16' and port '5060'. [Jun 26 16:21:41] DEBUG[20384] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 26 16:21:41] DEBUG[20384] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 26 16:21:41] DEBUG[20379] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=6497 (rdata0x7fba8408b558) [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba7402c .Incoming Response msg 200/BYE/cseq=6497 (rdata0x7fba8408b558) in state Calling [Jun 26 16:21:41] DEBUG[20379] pjsip: tsx0x7fba7402c ..State changed from Calling to Completed, event=RX_MSG [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 ...Received Response msg 200/BYE/cseq=6497 (rdata0x7fba8408b558) [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 ...Transaction tsx0x7fba7402c738 state changed to Completed [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: There is no transaction involved in this state change [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Received response [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Response is 200 OK [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Destroying SIP session with endpoint ALICE [Jun 26 16:21:41] DEBUG[20379] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fba7401b228' [Jun 26 16:21:41] DEBUG[20379] rtp_engine.c: Destroyed RTP instance '0x7fba7401b228' [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 .....Session count dec to 2 by Session Module [Jun 26 16:21:41] DEBUG[20379] pjsip: dlg0x7fba74023 .....Session count dec to 1 by mod-invite [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: inv_session 0x7fba7400c5e8 has no ast session [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fba7402c738 [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current transaction state is Completed [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 26 16:21:41] DEBUG[20379] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 26 16:21:41] DEBUG[20379] taskprocessor.c: destroying taskprocessor 'c7a5f16c-5893-4f68-bb14-c8d053de19bc' [Jun 26 16:21:45] DEBUG[20354] cdr.c: CDR Engine termination request received; waiting on messages... [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Jun 26 16:21:45] VERBOSE[20354] asterisk.c: Beginning asterisk shutdown.... [Jun 26 16:21:45] VERBOSE[20354] asterisk.c: Asterisk cleanly ending (0). [Jun 26 16:21:45] VERBOSE[20354] asterisk.c: Executing last minute cleanups [Jun 26 16:21:45] VERBOSE[20354] res_musiconhold.c: Destroying musiconhold processes [Jun 26 16:21:45] DEBUG[20354] res_musiconhold.c: Destroying MOH class 'default' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor '342ac69a-7594-47b9-ada3-f3ce0e2cc6ca' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'CallCompletionCancel' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'CallCompletionRequest' [Jun 26 16:21:45] DEBUG[20354] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'CCSS core' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor '80fcf8e3-8d08-4df9-8930-fb4274d46f4e' [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeList [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeInfo [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeDestroy [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeKick [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Ping [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Events [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Logoff [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Login [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Challenge [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Hangup [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Status [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Setvar [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Getvar [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action GetConfig [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action GetConfigJSON [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action UpdateConfig [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action CreateConfig [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ListCategories [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Redirect [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Atxfer [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Originate [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Command [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ExtensionState [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action PresenceState [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action AbsoluteTimeout [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action MailboxStatus [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action MailboxCount [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ListCommands [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action SendText [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action UserEvent [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action WaitEvent [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action CoreSettings [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action CoreStatus [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Reload [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action LoggerRotate [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action CoreShowChannels [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ModuleLoad [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ModuleCheck [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action AOCMessage [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Filter [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BlindTransfer [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function AMI_CLIENT [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor '7dbe7b33-8be5-460e-b90f-92bdf7db767a' [Jun 26 16:21:45] DEBUG[20354] tcptls.c: Stopped server :: AMI server [Jun 26 16:21:45] DEBUG[20354] tcptls.c: Stopped server :: AMI TLS server [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action LocalOptimizeAway [Jun 26 16:21:45] DEBUG[20354] channel.c: Unregistering channel type 'Local' [Jun 26 16:21:45] VERBOSE[20354] channel.c: Unregistered channel type 'Local' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor '72f3e2a5-c995-430c-a181-9c6524276ed2' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor '401a944a-2d48-44be-8683-156046529ce5' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Answer' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'BackGround' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Busy' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Congestion' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'ExecIfTime' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Goto' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'GotoIf' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'GotoIfTime' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'ImportVar' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Hangup' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Incomplete' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'NoOp' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Proceeding' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Progress' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'RaiseException' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Ringing' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SayAlpha' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SayAlphaCase' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SayDigits' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SayNumber' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SayPhonetic' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Set' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'MSet' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'SetAMAFlags' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Wait' [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'WaitExten' [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ShowDialPlan [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action ExtensionStateList [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function EXCEPTION [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function TESTTIME [Jun 26 16:21:45] DEBUG[20369] taskprocessor.c: destroying taskprocessor '5302be6f-1310-4eb4-b9ee-a3d5c891da32' [Jun 26 16:21:45] DEBUG[20354] tcptls.c: Stopped server :: http server [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function FEATUREMAP [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function FEATURE [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action Bridge [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'Bridge' [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeTechnologyList [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeTechnologySuspend [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action BridgeTechnologyUnsuspend [Jun 26 16:21:45] DEBUG[20354] channel.c: Unregistering channel type 'Surrogate' [Jun 26 16:21:45] VERBOSE[20354] channel.c: Unregistered channel type 'Surrogate' [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action DataGet [Jun 26 16:21:45] VERBOSE[20354] message.c: Message handler 'dialplan' unregistered. [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function MESSAGE [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered custom function MESSAGE_DATA [Jun 26 16:21:45] VERBOSE[20354] pbx.c: Unregistered application 'MessageSend' [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action MessageSend [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action DBGet [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action DBPut [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action DBDel [Jun 26 16:21:45] VERBOSE[20354] manager.c: Manager unregistered action DBDelTree [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'stasis-core-control' [Jun 26 16:21:45] DEBUG[20354] threadpool.c: Destroying worker thread 11 [Jun 26 16:21:45] DEBUG[20354] threadpool.c: Destroying worker thread 12 [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'stasis-core' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Jun 26 16:21:45] DEBUG[20354] taskprocessor.c: destroying taskprocessor 'Sorcery' [Jun 26 16:21:45] DEBUG[20354] asterisk.c: Asterisk ending (0).