[Jan 22 18:07:33] Asterisk 13.7.0 built by root @ debian1 on a i686 running Linux on 2016-01-21 14:51:32 UTC [Jan 22 18:07:33] DEBUG[3133] config.c: Parsing /etc/asterisk/logger.conf [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x93578bc) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (873 bytes) from UDP:192.168.1.13:5060 ---> INVITE sip:123@192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK15659323511365714970;rport From: ALICE ;tag=72823432 To: "123" Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 1 INVITE Contact: Max-Forwards: 70 Supported: replaces, join, path User-Agent: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 339 v=0 o=BOB 20381106 26430108 IN IP4 192.168.1.13 s=A conversation c=IN IP4 192.168.1.13 t=0 0 m=audio 10016 RTP/AVP 0 8 18 4 2 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x95af714) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint .Response msg 401/INVITE/cseq=1 (tdta0x9196e60) created [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP response (517 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK15659323511365714970 Call-ID: 14760665923996-151762700118532@192.168.1.13 From: "ALICE" ;tag=72823432 To: "123" ;tag=z9hG4bK15659323511365714970 CSeq: 1 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1453507658/38abd6d35deb4cd039acc69e668f70e1",opaque="78c538ab32b273bb",algorithm=md5,qop="auth" Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3079] pjsip: tdta0x9196e60 .Destroying txdata Response msg 401/INVITE/cseq=1 (tdta0x9196e60) [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x93578bc) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (336 bytes) from UDP:192.168.1.13:5060 ---> ACK sip:123@192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK15659323511365714970;rport From: "ALICE" ;tag=72823432 To: "123" ;tag=z9hG4bK15659323511365714970 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 1 ACK Max-Forwards: 70 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x95b6e6c) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=2 (rdata0x93578bc) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (1140 bytes) from UDP:192.168.1.13:5060 ---> INVITE sip:123@192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK1184726103184252300;rport From: ALICE ;tag=72823432 To: "123" Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 2 INVITE Contact: Authorization: Digest username="ALICE", realm="asterisk", nonce="1453507658/38abd6d35deb4cd039acc69e668f70e1", uri="sip:123@192.168.1.24", response="af9e80e81cc1cbd0a87f4b4c97dadb04", algorithm=MD5, cnonce="ebcb82d2", opaque="78c538ab32b273bb", qop=auth, nc=00000001 Max-Forwards: 70 Supported: replaces, join, path User-Agent: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 339 v=0 o=BOB 20381106 26430108 IN IP4 192.168.1.13 s=A conversation c=IN IP4 192.168.1.13 t=0 0 m=audio 10016 RTP/AVP 0 8 18 4 2 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=2 (rdata0x95b6e6c) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:07:38] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint .Response msg 401/INVITE/cseq=2 (tdta0x9196e60) created [Jan 22 18:07:38] DEBUG[3079] res_pjsip_authenticator_digest.c: Calculated nonce 1453507658/38abd6d35deb4cd039acc69e668f70e1. Actual nonce is 1453507658/38abd6d35deb4cd039acc69e668f70e1 [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] pjsip: tdta0x9196e60 .Destroying txdata Response msg 401/INVITE/cseq=2 (tdta0x9196e60) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9578bfc ..Transaction created for Request msg INVITE/cseq=2 (rdata0x95b6e6c) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9578bfc .Incoming Request msg INVITE/cseq=2 (rdata0x95b6e6c) in state Null [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9578bfc ..State changed from Null to Trying, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ...Transaction tsx0x9578bfc state changed to Trying [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 .UAS dialog created [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 .Module mod-invite added as dialog usage, data=0x9179344 [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ..Session count inc to 2 by mod-invite [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x93b02e4 .UAS invite session created for dialog dlg0x93b02e4 [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 .Module Session Module added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ..Session count inc to 2 by Session Module [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x95793d4' [Jan 22 18:07:38] DEBUG[3080] res_rtp_asterisk.c: Allocated port 12832 for RTP instance '0x95793d4' [Jan 22 18:07:38] DEBUG[3080] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:12832 (12832) for RTP instance '0x95793d4' [Jan 22 18:07:38] DEBUG[3080] pjsip: icess0x9181ccc ICE session created, comp_cnt=2, role is Unknown agent [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3080] pjsip: icess0x9181ccc Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80118, addr=192.168.1.24:12832, base=192.168.1.24:12832, prio=0x7effffff (2130706431) [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: RTP instance '0x95793d4' is setup and ready to go [Jan 22 18:07:38] DEBUG[3080] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x95793d4' [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3080] pjsip: icess0x9181ccc Candidate 1 added: comp_id=2, type=host, foundation=Hc0a80118, addr=192.168.1.24:12833, base=192.168.1.24:12833, prio=0x7efffffe (2130706430) [Jan 22 18:07:38] DEBUG[3080] pjsip: icess0x9181ccc Destroying ICE session 0x9181ccc [Jan 22 18:07:38] DEBUG[3080] pjsip: stuse0x95b1648 STUN session 0x93f5a04 destroy request, ref_cnt=4 [Jan 22 18:07:38] DEBUG[3080] pjsip: stuse0x91c93c0 STUN session 0x91c97dc destroy request, ref_cnt=3 [Jan 22 18:07:38] DEBUG[3080] pjsip: ice_session.c ICE session 0x9181ccc destroyed [Jan 22 18:07:38] DEBUG[3080] pjsip: stun_session.c STUN session 0x93f5a04 destroyed [Jan 22 18:07:38] DEBUG[3080] pjsip: stun_session.c STUN session 0x91c97dc destroyed [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 0 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 18 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 4 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 9 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6234a48 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 0 (0x93fcdec) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 2 (0x93fdca4) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 4 (0x9260f04) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 8 (0x951c99c) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 9 (0x91679f4) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 18 (0x925b59c) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 101 (0x940970c) from 0xb6234a48 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Media stream 'audio' handled by audio [Jan 22 18:07:38] DEBUG[3080] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jan 22 18:07:38] DEBUG[3080] pjsip: endpoint .Response msg 100/INVITE/cseq=2 (tdta0x95ad198) created [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 .Initial answer Response msg 100/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jan 22 18:07:38] DEBUG[3080] pjsip: inv0x93b02e4 .Sending Response msg 100/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ..Sending Response msg 100/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ..Sending Response msg 100/INVITE/cseq=2 (tdta0x95ad198) in state Trying [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP response (331 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK1184726103184252300 Call-ID: 14760665923996-151762700118532@192.168.1.13 From: "ALICE" ;tag=72823432 To: "123" CSeq: 2 INVITE Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ...State changed from Trying to Proceeding, event=TX_MSG [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ....Transaction tsx0x9578bfc state changed to Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is INCOMING [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x9578bfc [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current transaction state is Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is INCOMING [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 Module NAT added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3058] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 22 18:07:38] DEBUG[3080] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/ALICE-00000000 [Jan 22 18:07:38] DEBUG[3135][C-00000000] pbx.c: Launching 'NoOp' [Jan 22 18:07:38] DEBUG[3135][C-00000000] pbx.c: Result of 'EXTEN' is '123' [Jan 22 18:07:38] DEBUG[3135][C-00000000] pbx.c: Launching 'Dial' [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 UAC dialog created [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module Outbound INVITE Auth added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module mod-invite added as dialog usage, data=0x93f5a04 [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 .Session count inc to 2 by mod-invite [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module mod-100rel added as dialog usage, data=0x93f5b04 [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 100rel module attached [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 UAC invite session created for dialog dlg0x91c9424 [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 .Session count inc to 2 by Session Module [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module Session Module added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x957ee9c' [Jan 22 18:07:38] DEBUG[3079] res_rtp_asterisk.c: Allocated port 12494 for RTP instance '0x957ee9c' [Jan 22 18:07:38] DEBUG[3079] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:12494 (12494) for RTP instance '0x957ee9c' [Jan 22 18:07:38] DEBUG[3079] pjsip: icess0x95b6e6c ICE session created, comp_cnt=2, role is Unknown agent [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3079] pjsip: icess0x95b6e6c Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80118, addr=192.168.1.24:12494, base=192.168.1.24:12494, prio=0x7effffff (2130706431) [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: RTP instance '0x957ee9c' is setup and ready to go [Jan 22 18:07:38] DEBUG[3079] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x957ee9c' [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:38] DEBUG[3079] pjsip: icess0x95b6e6c Candidate 1 added: comp_id=2, type=host, foundation=Hc0a80118, addr=192.168.1.24:12495, base=192.168.1.24:12495, prio=0x7efffffe (2130706430) [Jan 22 18:07:38] DEBUG[3079] pjsip: icess0x95b6e6c Destroying ICE session 0x95b6e6c [Jan 22 18:07:38] DEBUG[3079] pjsip: stuse0x95b8868 STUN session 0x91b166c destroy request, ref_cnt=4 [Jan 22 18:07:38] DEBUG[3079] pjsip: stuse0x91b2238 STUN session 0x91b2654 destroy request, ref_cnt=3 [Jan 22 18:07:38] DEBUG[3079] pjsip: ice_session.c ICE session 0x95b6e6c destroyed [Jan 22 18:07:38] DEBUG[3079] pjsip: stun_session.c STUN session 0x91b166c destroyed [Jan 22 18:07:38] DEBUG[3079] pjsip: stun_session.c STUN session 0x91b2654 destroyed [Jan 22 18:07:38] DEBUG[3079] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint Request msg INVITE/cseq=5963 (tdta0x9196e60) created. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module NAT added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 Module WebSocket Transport Module added as dialog usage, data=(nil) [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 .Sending Request msg INVITE/cseq=5963 (tdta0x9196e60) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ..Sending Request msg INVITE/cseq=5963 (tdta0x9196e60) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ...Transaction created for Request msg INVITE/cseq=5962 (tdta0x9196e60) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ..Sending Request msg INVITE/cseq=5962 (tdta0x9196e60) in state Null [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_resolve.c ...Target '192.168.1.21:0' type=Unspecified resolved to '192.168.1.21:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (910 bytes) to UDP:192.168.1.21:5060 ---> INVITE sip:123@192.168.1.21 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj61a5726b-9906-4a96-9291-1bb28b958699 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: Contact: Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5962 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Type: application/sdp Content-Length: 259 v=0 o=- 783079646 783079646 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.24 t=0 0 m=audio 12494 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ...State changed from Null to Calling, event=TX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ....Transaction tsx0x9358cbc state changed to Calling [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CALLING [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Sending request [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Calling [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CALLING [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Sending request [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=5962 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (566 bytes) from UDP:192.168.1.21:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.24:5060;branch=z9hG4bKPj61a5726b-9906-4a96-9291-1bb28b958699;received=192.168.1.24;rport=5060 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5962 INVITE Server: Asterisk PBX 13.7.0-rc3 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=5962 (rdata0x91addd4) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc .Incoming Response msg 100/INVITE/cseq=5962 (rdata0x91addd4) in state Calling [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=5962 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (881 bytes) from UDP:192.168.1.21:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.24:5060;branch=z9hG4bKPj61a5726b-9906-4a96-9291-1bb28b958699;received=192.168.1.24;rport=5060 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5962 INVITE Server: Asterisk PBX 13.7.0-rc3 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 241 v=0 o=root 845660475 845660475 IN IP4 192.168.1.21 s=Asterisk PBX 13.7.0-rc3 c=IN IP4 192.168.1.21 t=0 0 m=audio 10328 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ..State changed from Calling to Proceeding, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Received Response msg 100/INVITE/cseq=5962 (rdata0x91addd4) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Transaction tsx0x9358cbc state changed to Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CALLING [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 100 Trying [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=5962 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (867 bytes) from UDP:192.168.1.21:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.24:5060;branch=z9hG4bKPj61a5726b-9906-4a96-9291-1bb28b958699;received=192.168.1.24;rport=5060 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5962 INVITE Server: Asterisk PBX 13.7.0-rc3 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 241 v=0 o=root 845660475 845660475 IN IP4 192.168.1.21 s=Asterisk PBX 13.7.0-rc3 c=IN IP4 192.168.1.21 t=0 0 m=audio 10328 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 183/INVITE/cseq=5962 (rdata0x95b989c) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc .Incoming Response msg 183/INVITE/cseq=5962 (rdata0x95b989c) in state Proceeding [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ..State changed from Proceeding to Proceeding, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Received Response msg 183/INVITE/cseq=5962 (rdata0x95b989c) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ....Route-set updated [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Transaction tsx0x9358cbc state changed to Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is EARLY [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 183 Session Progress [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....Got SDP answer in Response msg 183/INVITE/cseq=5962 (rdata0x95b989c) [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....SDP negotiation done, status=0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.21' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port ''. [Jan 22 18:07:38] DEBUG[3079] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x957ee9c' [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6270338 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6270338 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 8 (0x957d75c) from 0xb6270338 to 0x957f048 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 101 (0x91b38c4) from 0xb6270338 to 0x957f048 [Jan 22 18:07:38] DEBUG[3079] channel.c: Channel PJSIP/LocalTrunk-00000001 setting read format path: alaw -> g722 [Jan 22 18:07:38] DEBUG[3079] channel.c: Channel PJSIP/LocalTrunk-00000001 setting write format path: g722 -> alaw [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is EARLY [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 183 Session Progress [Jan 22 18:07:38] DEBUG[3080] pjsip: inv0x93b02e4 .SDP negotiation done, status=0 [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3080] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x95793d4' [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 0 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 18 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 4 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 9 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6234588 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 0 (0x935e024) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 2 (0x91847a4) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 4 (0x957eb8c) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 8 (0x9196e14) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 9 (0x91679f4) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 18 (0x935cb74) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] rtp_engine.c: Copying payload 101 (0x91847cc) from 0xb6234588 to 0x9579580 [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress [Jan 22 18:07:38] DEBUG[3080] pjsip: inv0x93b02e4 .Sending Response msg 183/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ..Sending Response msg 183/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ..Sending Response msg 183/INVITE/cseq=2 (tdta0x95ad198) in state Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP response (818 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK1184726103184252300 Call-ID: 14760665923996-151762700118532@192.168.1.13 From: "ALICE" ;tag=72823432 To: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa CSeq: 2 INVITE Server: Asterisk PBX 13.7.0 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Content-Type: application/sdp Content-Length: 257 v=0 o=- 20381106 26430110 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.24 t=0 0 m=audio 12832 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ...State changed from Proceeding to Proceeding, event=TX_MSG [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ....Transaction tsx0x9578bfc state changed to Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is EARLY [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x9578bfc [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current transaction state is Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is EARLY [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=5962 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc .Incoming Response msg 200/INVITE/cseq=5962 (rdata0x9192824) in state Proceeding [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9358cbc ..State changed from Proceeding to Terminated, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Received Response msg 200/INVITE/cseq=5962 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ....Route-set updated [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ....Route-set frozen [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Transaction tsx0x9358cbc state changed to Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONNECTING [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....SDP negotiation done, message body is ignored [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....Received Response msg 200/INVITE/cseq=5962 (rdata0x9192824), sending ACK [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint ....Request msg ACK/cseq=5962 (tdta0x91afd08) created. [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 .....Sending Request msg ACK/cseq=5962 (tdta0x91afd08) [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_resolve.c .....Target '192.168.1.21:5060' type=Unspecified resolved to '192.168.1.21:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (394 bytes) to UDP:192.168.1.21:5060 ---> ACK sip:123@192.168.1.21:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPjf58b80f2-95a7-40a8-b585-a095985c654c From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5962 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Sending request [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is ACK [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:07:38] DEBUG[3135][C-00000000] channel.c: Channel PJSIP/LocalTrunk-00000001 setting read format path: alaw -> alaw [Jan 22 18:07:38] DEBUG[3135][C-00000000] channel.c: Channel PJSIP/ALICE-00000000 setting write format path: alaw -> alaw [Jan 22 18:07:38] DEBUG[3135][C-00000000] channel.c: Channel PJSIP/ALICE-00000000 setting read format path: alaw -> alaw [Jan 22 18:07:38] DEBUG[3135][C-00000000] channel.c: Channel PJSIP/LocalTrunk-00000001 setting write format path: alaw -> alaw [Jan 22 18:07:38] DEBUG[3058] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 22 18:07:38] DEBUG[3070] devicestate.c: No provider found, checking channel drivers for PJSIP - LocalTrunk [Jan 22 18:07:38] DEBUG[3070] devicestate.c: Changing state for PJSIP/LocalTrunk - state 2 (In use) [Jan 22 18:07:38] DEBUG[3070] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE [Jan 22 18:07:38] DEBUG[3070] devicestate.c: Changing state for PJSIP/ALICE - state 2 (In use) [Jan 22 18:07:38] DEBUG[3129] app_queue.c: Device 'PJSIP/LocalTrunk' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 22 18:07:38] DEBUG[3129] 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. [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jan 22 18:07:38] DEBUG[3080] pjsip: inv0x93b02e4 .Sending Response msg 200/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ..Sending Response msg 200/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ..Sending Response msg 200/INVITE/cseq=2 (tdta0x95ad198) in state Proceeding [Jan 22 18:07:38] DEBUG[3080] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP response (852 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK1184726103184252300 Call-ID: 14760665923996-151762700118532@192.168.1.13 From: "ALICE" ;tag=72823432 To: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa CSeq: 2 INVITE Server: Asterisk PBX 13.7.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 257 v=0 o=- 20381106 26430110 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.24 t=0 0 m=audio 12832 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x9578bfc ...State changed from Proceeding to Completed, event=TX_MSG [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x93b02e4 ....Transaction tsx0x9578bfc state changed to Completed [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is CONNECTING [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9578bfc) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x9578bfc [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current transaction state is Completed [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is CONNECTING [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending response [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge_native_rtp.c: Bridge '5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2' can not use native RTP bridge as two channels are required [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Chose bridge technology simple_bridge [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling simple_bridge technology constructor [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling simple_bridge technology start [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x9198b84(PJSIP/LocalTrunk-00000001) is joining [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: pushing 0x9198b84(PJSIP/LocalTrunk-00000001) [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge_native_rtp.c: Bridge '5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2' can not use native RTP bridge as two channels are required [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Chose bridge technology simple_bridge [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2 is already using the new technology. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x9198b84(PJSIP/LocalTrunk-00000001) is joining simple_bridge technology [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x969c1dc(PJSIP/ALICE-00000000) is joining [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: pushing 0x969c1dc(PJSIP/ALICE-00000000) [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Chose bridge technology native_rtp [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling native_rtp technology constructor [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: moving 0x9198b84(PJSIP/LocalTrunk-00000001) to dummy bridge temporarily [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x9198b84(PJSIP/LocalTrunk-00000001) is leaving simple_bridge technology (dummy) [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling simple_bridge technology stop [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x969c1dc(PJSIP/ALICE-00000000) is joining native_rtp technology [Jan 22 18:07:38] DEBUG[3135][C-00000000] chan_pjsip.c: RTP changed on PJSIP/ALICE-00000000; initiating direct media update [Jan 22 18:07:38] DEBUG[3135][C-00000000] chan_pjsip.c: RTP changed on PJSIP/LocalTrunk-00000001; initiating direct media update [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x9198b84(PJSIP/LocalTrunk-00000001) is joining native_rtp technology [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling native_rtp technology start [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling simple_bridge technology destructor [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Chose bridge technology native_rtp [Jan 22 18:07:38] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2 is already using the new technology. [Jan 22 18:07:38] DEBUG[3071] cdr.c: Finalized CDR for PJSIP/LocalTrunk-00000001 - start 1453507658.324654 answer 1453507658.342379 end 1453507658.344785 dispo ANSWERED [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Delay sending reinvite to ALICE because of outstanding transaction... [Jan 22 18:07:38] DEBUG[3080] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jan 22 18:07:38] DEBUG[3080] pjsip: endpoint .Request msg INVITE/cseq=5964 (tdta0x95bb7d0) created. [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to LocalTrunk [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3080] pjsip: inv0x91c9424 .Sending Request msg INVITE/cseq=5964 (tdta0x95bb7d0) [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x91c9424 ..Sending Request msg INVITE/cseq=5964 (tdta0x95bb7d0) [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x919609c ...Transaction created for Request msg INVITE/cseq=5963 (tdta0x95bb7d0) [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x919609c ..Sending Request msg INVITE/cseq=5963 (tdta0x95bb7d0) in state Null [Jan 22 18:07:38] DEBUG[3080] pjsip: sip_resolve.c ...Target '192.168.1.21:5060' type=Unspecified resolved to '192.168.1.21:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3080] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3080] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP request (944 bytes) to UDP:192.168.1.21:5060 ---> INVITE sip:123@192.168.1.21:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPje0be177a-caa8-438d-9d6f-e978e95b8a11 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Contact: Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5963 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uas Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Type: application/sdp Content-Length: 259 v=0 o=- 783079646 783079647 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.13 t=0 0 m=audio 10016 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3080] pjsip: tsx0x919609c ...State changed from Null to Calling, event=TX_MSG [Jan 22 18:07:38] DEBUG[3080] pjsip: dlg0x91c9424 ....Transaction tsx0x919609c state changed to Calling [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x919609c) [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x919609c [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current transaction state is Calling [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Sending request [Jan 22 18:07:38] DEBUG[3080] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9358cbc Timeout timer event [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9358cbc .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9358cbc Transaction destroyed! [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Chose bridge technology native_rtp [Jan 22 18:07:38] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2 is already using the new technology. [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=5963 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (581 bytes) from UDP:192.168.1.21:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.24:5060;branch=z9hG4bKPje0be177a-caa8-438d-9d6f-e978e95b8a11;received=192.168.1.24;rport=5060 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5963 INVITE Server: Asterisk PBX 13.7.0-rc3 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=5963 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (867 bytes) from UDP:192.168.1.21:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.24:5060;branch=z9hG4bKPje0be177a-caa8-438d-9d6f-e978e95b8a11;received=192.168.1.24;rport=5060 From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5963 INVITE Server: Asterisk PBX 13.7.0-rc3 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 241 v=0 o=root 845660475 845660476 IN IP4 192.168.1.21 s=Asterisk PBX 13.7.0-rc3 c=IN IP4 192.168.1.21 t=0 0 m=audio 10328 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=5963 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c .Incoming Response msg 100/INVITE/cseq=5963 (rdata0x9192824) in state Calling [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ..State changed from Calling to Proceeding, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Received Response msg 100/INVITE/cseq=5963 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Transaction tsx0x919609c state changed to Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x919609c) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x919609c [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Proceeding [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 100 Trying [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=5963 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c .Incoming Response msg 200/INVITE/cseq=5963 (rdata0x91cba64) in state Proceeding [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ..State changed from Proceeding to Terminated, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Received Response msg 200/INVITE/cseq=5963 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 ...Transaction tsx0x919609c state changed to Terminated [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....Got SDP answer in Response msg 200/INVITE/cseq=5963 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....SDP negotiation done, status=0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.21' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port ''. [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6270308 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6270308 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 8 (0x957e164) from 0xb6270308 to 0x957f048 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 101 (0x940970c) from 0xb6270308 to 0x957f048 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x91c9424 ....Received Response msg 200/INVITE/cseq=5963 (rdata0x91cba64), sending ACK [Jan 22 18:07:38] DEBUG[3079] pjsip: tdta0x91afd08 ....Destroying txdata Request msg ACK/cseq=5962 (tdta0x91afd08) [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint ....Request msg ACK/cseq=5963 (tdta0x91afd08) created. [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x91c9424 .....Sending Request msg ACK/cseq=5963 (tdta0x91afd08) [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_resolve.c .....Target '192.168.1.21:5060' type=Unspecified resolved to '192.168.1.21:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (394 bytes) to UDP:192.168.1.21:5060 ---> ACK sip:123@192.168.1.21:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPjccd39c85-1d2c-41f4-870b-34b1f7c80a7d From: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 To: ;tag=as058c0c5c Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 5963 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x919609c [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:07:38] DEBUG[3137][C-00000000] channel.c: Dropping duplicate answer! [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=2 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (371 bytes) from UDP:192.168.1.13:5060 ---> ACK sip:192.168.1.24:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK24543218751282822643 From: ALICE ;tag=72823432 To: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 2 ACK Max-Forwards: 70 User-Agent: Voip Phone 1.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c Timeout timer event [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:07:38] DEBUG[3084] pjsip: tdta0x95bb7d0 ..Destroying txdata Request msg INVITE/cseq=5963 (tdta0x95bb7d0) [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c Transaction destroyed! [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=2 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 .Received Request msg ACK/cseq=2 (rdata0x9192824) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9578bfc ..Request to terminate transaction [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x9578bfc ...State changed from Completed to Terminated, event=USER [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ....Transaction tsx0x9578bfc state changed to Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x9578bfc [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is USER [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONNECTING [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Endpoint 'ALICE(PJSIP/ALICE-00000000)' INVITE delay check. tsx-state:Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received request [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is ACK [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Endpoint 'ALICE(PJSIP/ALICE-00000000)' sending delayed INVITE request. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint .Request msg INVITE/cseq=25531 (tdta0x9194758) created. [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to ALICE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x93b02e4 .Sending Request msg INVITE/cseq=25531 (tdta0x9194758) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ..Sending Request msg INVITE/cseq=25531 (tdta0x9194758) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ...Transaction created for Request msg INVITE/cseq=25530 (tdta0x9194758) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ..Sending Request msg INVITE/cseq=25530 (tdta0x9194758) in state Null [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_resolve.c ...Target '192.168.1.13:5060' type=Unspecified resolved to '192.168.1.13:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (933 bytes) to UDP:192.168.1.13:5060 ---> INVITE sip:ALICE@192.168.1.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj64c1e076-6b1d-4407-b40f-bea0ebf03971 From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Contact: Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25530 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Type: application/sdp Content-Length: 257 v=0 o=- 20381106 26430111 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.21 t=0 0 m=audio 10328 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ...State changed from Null to Calling, event=TX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ....Transaction tsx0x919609c state changed to Calling [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session still has an invite_tsx (0x919609c) [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x919609c [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Calling [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Sending request [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Method is INVITE [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9578bfc Timeout timer event [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9578bfc .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:07:38] DEBUG[3084] pjsip: tdta0x95ad198 ..Destroying txdata Response msg 200/INVITE/cseq=2 (tdta0x95ad198) [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x9578bfc Transaction destroyed! [Jan 22 18:07:38] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=25530 (rdata0x95af714) [Jan 22 18:07:38] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (792 bytes) from UDP:192.168.1.13:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj64c1e076-6b1d-4407-b40f-bea0ebf03971 From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25530 INVITE Contact: Supported: 100rel, replaces, timer Server: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 238 v=0 o=BOB 27574117 28146274 IN IP4 192.168.1.13 s=A conversation c=IN IP4 192.168.1.13 t=0 0 m=audio 10016 RTP/AVP 9 8 101 a=rtpmap:9 G722/16000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=25530 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c .Incoming Response msg 200/INVITE/cseq=25530 (rdata0x91cba64) in state Calling [Jan 22 18:07:38] DEBUG[3079] pjsip: tsx0x919609c ..State changed from Calling to Terminated, event=RX_MSG [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ...Received Response msg 200/INVITE/cseq=25530 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 ...Transaction tsx0x919609c state changed to Terminated [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x93b02e4 ....Got SDP answer in Response msg 200/INVITE/cseq=25530 (rdata0x91cba64) [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x93b02e4 ....SDP negotiation done, status=0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 9 based on m type on 0xb62702d8 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb62702d8 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb62702d8 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 8 (0x9196dec) from 0xb62702d8 to 0x9579580 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 9 (0x91679f4) from 0xb62702d8 to 0x9579580 [Jan 22 18:07:38] DEBUG[3079] rtp_engine.c: Copying payload 101 (0x93fdca4) from 0xb62702d8 to 0x9579580 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jan 22 18:07:38] DEBUG[3079] pjsip: inv0x93b02e4 ....Received Response msg 200/INVITE/cseq=25530 (rdata0x91cba64), sending ACK [Jan 22 18:07:38] DEBUG[3079] pjsip: endpoint ....Request msg ACK/cseq=25530 (tdta0x95bb7d0) created. [Jan 22 18:07:38] DEBUG[3079] pjsip: dlg0x93b02e4 .....Sending Request msg ACK/cseq=25530 (tdta0x95bb7d0) [Jan 22 18:07:38] DEBUG[3079] pjsip: sip_resolve.c .....Target '192.168.1.13:5060' type=Unspecified resolved to '192.168.1.13:5060' type=UDP (UDP transport) [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:38] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:38] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:38] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (408 bytes) to UDP:192.168.1.13:5060 ---> ACK sip:ALICE@192.168.1.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj00c14257-0e7a-487e-92ef-6002f00353fd From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25530 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x919609c [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:07:38] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:07:38] DEBUG[3135][C-00000000] channel.c: Dropping duplicate answer! [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c Timeout timer event [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:07:38] DEBUG[3084] pjsip: tdta0x9194758 ..Destroying txdata Request msg INVITE/cseq=25530 (tdta0x9194758) [Jan 22 18:07:38] DEBUG[3084] pjsip: tsx0x919609c Transaction destroyed! [Jan 22 18:07:50] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=9 (rdata0x95af714) [Jan 22 18:07:50] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (415 bytes) from UDP:192.168.1.13:5060 ---> REGISTER sip:192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK2505445271035256;rport From: ALICE ;tag=2907410515 To: ALICE Call-ID: 3133494014159-156033050215555@192.168.1.13 CSeq: 9 REGISTER Contact: Max-Forwards: 70 Expires: 60 Supported: path User-Agent: Voip Phone 1.0 Content-Length: 0 [Jan 22 18:07:50] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:50] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:50] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:50] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:50] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=9 (rdata0x9192824) [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:07:50] DEBUG[3079] pjsip: endpoint .Response msg 401/REGISTER/cseq=9 (tdta0x95ad198) created [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:50] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP response (516 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK2505445271035256 Call-ID: 3133494014159-156033050215555@192.168.1.13 From: "ALICE" ;tag=2907410515 To: "ALICE" ;tag=z9hG4bK2505445271035256 CSeq: 9 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1453507670/cfc71cfcde5a1a73094496ad7d2d62ea",opaque="477f563f49c08ab1",algorithm=md5,qop="auth" Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:50] DEBUG[3079] pjsip: tdta0x95ad198 .Destroying txdata Response msg 401/REGISTER/cseq=9 (tdta0x95ad198) [Jan 22 18:07:50] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=10 (rdata0x95af714) [Jan 22 18:07:50] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (682 bytes) from UDP:192.168.1.13:5060 ---> REGISTER sip:192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK742112492807024733;rport From: ALICE ;tag=2907410515 To: ALICE Call-ID: 3133494014159-156033050215555@192.168.1.13 CSeq: 10 REGISTER Contact: Authorization: Digest username="ALICE", realm="asterisk", nonce="1453507670/cfc71cfcde5a1a73094496ad7d2d62ea", uri="sip:192.168.1.24", response="df51b73f853d247f13a909c22995289a", algorithm=MD5, cnonce="ebcb82d2", opaque="477f563f49c08ab1", qop=auth, nc=00000001 Max-Forwards: 70 Expires: 60 Supported: path User-Agent: Voip Phone 1.0 Content-Length: 0 [Jan 22 18:07:50] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:50] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:50] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:50] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:50] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=10 (rdata0x9192824) [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:07:50] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:07:50] DEBUG[3079] pjsip: endpoint .Response msg 401/REGISTER/cseq=10 (tdta0x95ad198) created [Jan 22 18:07:50] DEBUG[3079] res_pjsip_authenticator_digest.c: Calculated nonce 1453507670/cfc71cfcde5a1a73094496ad7d2d62ea. Actual nonce is 1453507670/cfc71cfcde5a1a73094496ad7d2d62ea [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:07:50] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:07:50] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:07:50] DEBUG[3079] pjsip: tdta0x95ad198 .Destroying txdata Response msg 401/REGISTER/cseq=10 (tdta0x95ad198) [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract int from [0] in [0, 86400] gives [0](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract int from [0] in [0, 86400] gives [0](0) [Jan 22 18:07:50] DEBUG[3080] res_pjsip_registrar.c: Refreshed contact 'sip:ALICE@192.168.1.13:5060' on AOR 'ALICE' with new expiration of 60 seconds [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract int from [0] in [0, 86400] gives [0](0) [Jan 22 18:07:50] DEBUG[3080] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Jan 22 18:07:50] DEBUG[3080] pjsip: endpoint Response msg 200/REGISTER/cseq=10 (tdta0x9194758) created [Jan 22 18:07:50] DEBUG[3080] pjsip: tsx0x919609c .Transaction created for Request msg REGISTER/cseq=10 (rdata0x91cba64) [Jan 22 18:07:50] DEBUG[3080] pjsip: tsx0x919609c Incoming Request msg REGISTER/cseq=10 (rdata0x91cba64) in state Null [Jan 22 18:07:50] DEBUG[3080] pjsip: tsx0x919609c .State changed from Null to Trying, event=RX_MSG [Jan 22 18:07:50] DEBUG[3080] pjsip: tsx0x919609c Sending Response msg 200/REGISTER/cseq=10 (tdta0x9194758) in state Trying [Jan 22 18:07:50] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:07:50] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:07:50] DEBUG[3080] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:07:50] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:07:50] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP response (465 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK742112492807024733 Call-ID: 3133494014159-156033050215555@192.168.1.13 From: "ALICE" ;tag=2907410515 To: "ALICE" ;tag=z9hG4bK742112492807024733 CSeq: 10 REGISTER Date: Sat, 23 Jan 2016 00:07:50 GMT Contact: ;expires=59 Expires: 60 Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:07:50] DEBUG[3080] pjsip: tsx0x919609c .State changed from Trying to Completed, event=TX_MSG [Jan 22 18:07:51] DEBUG[3083] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:51] DEBUG[3082] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:51] DEBUG[3081] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:51] DEBUG[3078] threadpool.c: Destroying worker thread 9 [Jan 22 18:07:51] DEBUG[3078] threadpool.c: Destroying worker thread 8 [Jan 22 18:07:51] DEBUG[3078] threadpool.c: Destroying worker thread 7 [Jan 22 18:07:51] DEBUG[3087] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:51] DEBUG[3057] threadpool.c: Destroying worker thread 12 [Jan 22 18:07:51] DEBUG[3088] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:51] DEBUG[3057] threadpool.c: Destroying worker thread 13 [Jan 22 18:07:53] DEBUG[3086] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:53] DEBUG[3057] threadpool.c: Destroying worker thread 11 [Jan 22 18:07:58] DEBUG[3136] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:58] DEBUG[3134] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 22 18:07:58] DEBUG[3058] threadpool.c: Destroying worker thread 15 [Jan 22 18:07:58] DEBUG[3058] threadpool.c: Destroying worker thread 14 [Jan 22 18:08:00] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg SUBSCRIBE/cseq=1 (rdata0x95af714) [Jan 22 18:08:00] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (474 bytes) from UDP:192.168.1.13:5060 ---> SUBSCRIBE sip:ALICE@192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK3709249002942017188;rport From: ALICE ;tag=273126180 To: "ALICE" Call-ID: 312452029915397-29893042420134@192.168.1.13 CSeq: 1 SUBSCRIBE Contact: Max-Forwards: 70 User-Agent: Voip Phone 1.0 Expires: 30 Event: message-summary Accept: application/simple-message-summary Content-Length: 0 [Jan 22 18:08:00] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:00] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:00] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:00] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:00] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg SUBSCRIBE/cseq=1 (rdata0x91cba64) [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:08:00] DEBUG[3079] pjsip: endpoint .Response msg 401/SUBSCRIBE/cseq=1 (tdta0x95ae1a0) created [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:00] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP response (523 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK3709249002942017188 Call-ID: 312452029915397-29893042420134@192.168.1.13 From: "ALICE" ;tag=273126180 To: "ALICE" ;tag=z9hG4bK3709249002942017188 CSeq: 1 SUBSCRIBE WWW-Authenticate: Digest realm="asterisk",nonce="1453507680/7fc5a19136a0ae0b0eb4849760c4ec44",opaque="430369ec29157891",algorithm=md5,qop="auth" Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:08:00] DEBUG[3079] pjsip: tdta0x95ae1a0 .Destroying txdata Response msg 401/SUBSCRIBE/cseq=1 (tdta0x95ae1a0) [Jan 22 18:08:00] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg SUBSCRIBE/cseq=2 (rdata0x95af714) [Jan 22 18:08:00] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (744 bytes) from UDP:192.168.1.13:5060 ---> SUBSCRIBE sip:ALICE@192.168.1.24 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.13:5060;branch=z9hG4bK7395261313238921126;rport From: ALICE ;tag=273126180 To: "ALICE" Call-ID: 312452029915397-29893042420134@192.168.1.13 CSeq: 2 SUBSCRIBE Contact: Authorization: Digest username="ALICE", realm="asterisk", nonce="1453507680/7fc5a19136a0ae0b0eb4849760c4ec44", uri="sip:ALICE@192.168.1.24", response="f140f6a691a3d8b85c0c05f2281b90af", algorithm=MD5, cnonce="ebcb82d2", opaque="430369ec29157891", qop=auth, nc=00000001 Max-Forwards: 70 User-Agent: Voip Phone 1.0 Expires: 30 Event: message-summary Accept: application/simple-message-summary Content-Length: 0 [Jan 22 18:08:00] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:00] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:00] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:00] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:00] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg SUBSCRIBE/cseq=2 (rdata0x91cba64) [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.1.13:5060 does not match identify 'LocalTrunk' [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_ip.c: '192.168.1.13:5060' did not match any identify section rules [Jan 22 18:08:00] DEBUG[3079] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint ALICE [Jan 22 18:08:00] DEBUG[3079] pjsip: endpoint .Response msg 401/SUBSCRIBE/cseq=2 (tdta0x95ae1a0) created [Jan 22 18:08:00] DEBUG[3079] res_pjsip_authenticator_digest.c: Calculated nonce 1453507680/7fc5a19136a0ae0b0eb4849760c4ec44. Actual nonce is 1453507680/7fc5a19136a0ae0b0eb4849760c4ec44 [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.24' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.24' and port ''. [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port ''. [Jan 22 18:08:00] DEBUG[3079] pjsip: tdta0x95ae1a0 .Destroying txdata Response msg 401/SUBSCRIBE/cseq=2 (tdta0x95ae1a0) [Jan 22 18:08:00] DEBUG[3079] res_pjsip_pubsub.c: Body generator 0xb4680560 found for accept type application/simple-message-summary [Jan 22 18:08:00] DEBUG[3079] res_pjsip_pubsub.c: Subscription to resource ALICE is not to a list [Jan 22 18:08:00] NOTICE[3079] res_pjsip_mwi.c: AOR ALICE has no configured mailboxes. MWI subscription failed. [Jan 22 18:08:00] DEBUG[3079] pjsip: endpoint .Response msg 404/SUBSCRIBE/cseq=2 (tdta0x95ae1a0) created [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:00] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:00] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:00] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP response (373 bytes) to UDP:192.168.1.13:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.1.13:5060;rport=5060;received=192.168.1.13;branch=z9hG4bK7395261313238921126 Call-ID: 312452029915397-29893042420134@192.168.1.13 From: "ALICE" ;tag=273126180 To: "ALICE" ;tag=z9hG4bK7395261313238921126 CSeq: 2 SUBSCRIBE Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:08:00] DEBUG[3079] pjsip: tdta0x95ae1a0 .Destroying txdata Response msg 404/SUBSCRIBE/cseq=2 (tdta0x95ae1a0) [Jan 22 18:08:06] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=102 (rdata0x95af714) [Jan 22 18:08:06] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP request (444 bytes) from UDP:192.168.1.21:5060 ---> BYE sip:asterisk@192.168.1.24:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.21:5060;branch=z9hG4bK2b7e7130;rport Max-Forwards: 70 From: ;tag=as058c0c5c To: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af CSeq: 102 BYE User-Agent: Asterisk PBX 13.7.0-rc3 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=102 (rdata0x91cba64) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x91c9424 .Received Request msg BYE/cseq=102 (rdata0x91cba64) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9578bfc ...Transaction created for Request msg BYE/cseq=102 (rdata0x91cba64) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9578bfc ..Incoming Request msg BYE/cseq=102 (rdata0x91cba64) in state Null [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9578bfc ...State changed from Null to Trying, event=RX_MSG [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x91c9424 ....Transaction tsx0x9578bfc state changed to Trying [Jan 22 18:08:06] DEBUG[3079] pjsip: endpoint .....Response msg 200/BYE/cseq=102 (tdta0x95ae1a0) created [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x91c9424 ......Sending Response msg 200/BYE/cseq=102 (tdta0x95ae1a0) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9578bfc ......Sending Response msg 200/BYE/cseq=102 (tdta0x95ae1a0) in state Trying [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '192.168.1.21:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '192.168.1.21' and port '5060'. [Jan 22 18:08:06] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP response (345 bytes) to UDP:192.168.1.21:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.21:5060;rport=5060;received=192.168.1.21;branch=z9hG4bK2b7e7130 Call-ID: 16ec044e-8279-4e15-a738-6bd35c0521af From: ;tag=as058c0c5c To: "ALICE" ;tag=5a9fbde8-87e8-434b-8ec0-41b156616527 CSeq: 102 BYE Server: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9578bfc .......State changed from Trying to Completed, event=TX_MSG [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x91c9424 ........Transaction tsx0x9578bfc state changed to Completed [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x9578bfc [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current transaction state is Completed [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Sending response [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Method is BYE, Response is 200 OK [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Received request [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Method is BYE [Jan 22 18:08:06] DEBUG[3079] pjsip: tdta0x91afd08 .....Destroying txdata Request msg ACK/cseq=5963 (tdta0x91afd08) [Jan 22 18:08:06] DEBUG[3079] pjsip: tdta0x9196e60 .....Destroying txdata Request msg INVITE/cseq=5962 (tdta0x9196e60) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x91c9424 ......Session count dec to 4 by mod-invite [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'LocalTrunk(PJSIP/LocalTrunk-00000001)' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x9578bfc [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current transaction state is Completed [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 22 18:08:06] DEBUG[3058] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge_channel.c: Setting 0x9198b84(PJSIP/LocalTrunk-00000001) state from:0 to:1 [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: pulling 0x9198b84(PJSIP/LocalTrunk-00000001) [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x9198b84(PJSIP/LocalTrunk-00000001) is leaving native_rtp technology [Jan 22 18:08:06] DEBUG[3137][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x95793d4' [Jan 22 18:08:06] DEBUG[3137][C-00000000] chan_pjsip.c: RTP changed on PJSIP/ALICE-00000000; initiating direct media update [Jan 22 18:08:06] DEBUG[3137][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x957ee9c' [Jan 22 18:08:06] DEBUG[3137][C-00000000] chan_pjsip.c: RTP changed on PJSIP/LocalTrunk-00000001; initiating direct media update [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/ALICE-00000000' and 'PJSIP/LocalTrunk-00000001' - media will flow through Asterisk core [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: dissolving bridge with cause 16(Normal Clearing) [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge_channel.c: Setting 0x969c1dc(PJSIP/ALICE-00000000) state from:0 to:2 [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: queueing action type:13 sub:1001 [Jan 22 18:08:06] DEBUG[3137][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2 is dissolved, not performing smart bridge operation. [Jan 22 18:08:06] DEBUG[3137][C-00000000] channel.c: Hanging up channel 'PJSIP/LocalTrunk-00000001' [Jan 22 18:08:06] DEBUG[3137][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Jan 22 18:08:06] DEBUG[3135][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: pulling 0x969c1dc(PJSIP/ALICE-00000000) [Jan 22 18:08:06] DEBUG[3135][C-00000000] bridge_channel.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: 0x969c1dc(PJSIP/ALICE-00000000) is leaving native_rtp technology [Jan 22 18:08:06] DEBUG[3135][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2 is dissolved, not performing smart bridge operation. [Jan 22 18:08:06] DEBUG[3135][C-00000000] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 22 18:08:06] DEBUG[3135][C-00000000] pbx.c: Spawn extension (users,123,2) exited non-zero on 'PJSIP/ALICE-00000000' [Jan 22 18:08:06] DEBUG[3135][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/ALICE-00000000' [Jan 22 18:08:06] DEBUG[3135][C-00000000] channel.c: Hanging up channel 'PJSIP/ALICE-00000000' [Jan 22 18:08:06] DEBUG[3135][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Jan 22 18:08:06] DEBUG[3069][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: actually destroying basic bridge, nobody wants it anymore [Jan 22 18:08:06] DEBUG[3069][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling basic bridge destructor [Jan 22 18:08:06] DEBUG[3069][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling native_rtp technology stop [Jan 22 18:08:06] DEBUG[3069][C-00000000] bridge.c: Bridge 5a4d2e28-1e36-4ee5-ba31-5e5f9dd5e2c2: calling native_rtp technology destructor [Jan 22 18:08:06] DEBUG[3080] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jan 22 18:08:06] DEBUG[3080] pjsip: endpoint .Request msg INVITE/cseq=25532 (tdta0x95ad198) created. [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to ALICE [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Method is INVITE [Jan 22 18:08:06] DEBUG[3080] pjsip: inv0x93b02e4 .Sending Request msg INVITE/cseq=25532 (tdta0x95ad198) [Jan 22 18:08:06] DEBUG[3080] pjsip: dlg0x93b02e4 ..Sending Request msg INVITE/cseq=25532 (tdta0x95ad198) [Jan 22 18:08:06] DEBUG[3080] pjsip: tsx0x9358cbc ...Transaction created for Request msg INVITE/cseq=25531 (tdta0x95ad198) [Jan 22 18:08:06] DEBUG[3080] pjsip: tsx0x9358cbc ..Sending Request msg INVITE/cseq=25531 (tdta0x95ad198) in state Null [Jan 22 18:08:06] DEBUG[3080] pjsip: sip_resolve.c ...Target '192.168.1.13:5060' type=Unspecified resolved to '192.168.1.13:5060' type=UDP (UDP transport) [Jan 22 18:08:06] DEBUG[3080] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.24:5060 [Jan 22 18:08:06] DEBUG[3080] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3080] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3080] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:06] DEBUG[3080] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:06] VERBOSE[3080] res_pjsip_logger.c: <--- Transmitting SIP request (933 bytes) to UDP:192.168.1.13:5060 ---> INVITE sip:ALICE@192.168.1.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj3f37cfbd-e725-4d54-a0e7-85ebfde7052a From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Contact: Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25531 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Type: application/sdp Content-Length: 257 v=0 o=- 20381106 26430112 IN IP4 192.168.1.24 s=Asterisk c=IN IP4 192.168.1.24 t=0 0 m=audio 12832 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Jan 22 18:08:06] DEBUG[3080] pjsip: tsx0x9358cbc ...State changed from Null to Calling, event=TX_MSG [Jan 22 18:08:06] DEBUG[3080] pjsip: dlg0x93b02e4 ....Transaction tsx0x9358cbc state changed to Calling [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE(PJSIP/ALICE-00000000)' [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The inv session still has an invite_tsx (0x9358cbc) [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The current transaction state is Calling [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Sending request [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Method is INVITE [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Delay sending BYE to ALICE because of outstanding transaction... [Jan 22 18:08:06] DEBUG[3080] res_pjsip_session.c: Not sending reinvite to LocalTrunk because of disconnected state... [Jan 22 18:08:06] DEBUG[3070] devicestate.c: No provider found, checking channel drivers for PJSIP - ALICE [Jan 22 18:08:06] DEBUG[3070] devicestate.c: Changing state for PJSIP/ALICE - state 1 (Not in use) [Jan 22 18:08:06] DEBUG[3070] devicestate.c: No provider found, checking channel drivers for PJSIP - LocalTrunk [Jan 22 18:08:06] DEBUG[3070] devicestate.c: Changing state for PJSIP/LocalTrunk - state 1 (Not in use) [Jan 22 18:08:06] DEBUG[3129] 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. [Jan 22 18:08:06] DEBUG[3129] app_queue.c: Device 'PJSIP/LocalTrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 22 18:08:06] DEBUG[3071] cdr.c: Finalized CDR for PJSIP/ALICE-00000000 - start 1453507658.320015 answer 1453507658.342393 end 1453507686.906207 dispo ANSWERED [Jan 22 18:08:06] DEBUG[3071] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: id INTEGER [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: clid VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: src VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: dst VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: dcontext VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: channel VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: dstchannel VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: lastapp VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: lastdata VARCHAR(80) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: start DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: answer DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: end DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: duration INT(11) NOT NULL DEFAULT 0 [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: billsec INT(11) NOT NULL DEFAULT 0 [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: disposition VARCHAR(45) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: amaflags INT(11) NOT NULL DEFAULT 0 [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: accountcode VARCHAR(20) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: uniqueid VARCHAR(32) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: userfield VARCHAR(255) NOT NULL DEFAULT '' [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: Found field: PRIMARY KEY (id) [Jan 22 18:08:06] DEBUG[3071] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"ALICE" ','ALICE','123','users','PJSIP/ALICE-00000000','PJSIP/LocalTrunk-00000001','Dial','PJSIP/123@LocalTrunk,60,','2016-01-22 18:07:38','2016-01-22 18:07:38','2016-01-22 18:08:06','28','28','ANSWERED','DOCUMENTATION','1453507658.0') [Jan 22 18:08:06] DEBUG[3058] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 22 18:08:06] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=25531 (rdata0x95af714) [Jan 22 18:08:06] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (792 bytes) from UDP:192.168.1.13:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj3f37cfbd-e725-4d54-a0e7-85ebfde7052a From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25531 INVITE Contact: Supported: 100rel, replaces, timer Server: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 238 v=0 o=BOB 17434170 22970530 IN IP4 192.168.1.13 s=A conversation c=IN IP4 192.168.1.13 t=0 0 m=audio 10016 RTP/AVP 9 8 101 a=rtpmap:9 G722/16000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=25531 (rdata0x91aa1ac) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9358cbc .Incoming Response msg 200/INVITE/cseq=25531 (rdata0x91aa1ac) in state Calling [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x9358cbc ..State changed from Calling to Terminated, event=RX_MSG [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ...Received Response msg 200/INVITE/cseq=25531 (rdata0x91aa1ac) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ...Transaction tsx0x9358cbc state changed to Terminated [Jan 22 18:08:06] DEBUG[3079] pjsip: inv0x93b02e4 ....Got SDP answer in Response msg 200/INVITE/cseq=25531 (rdata0x91aa1ac) [Jan 22 18:08:06] DEBUG[3079] pjsip: inv0x93b02e4 ....SDP negotiation done, status=0 [Jan 22 18:08:06] DEBUG[3079] pjsip: inv0x93b02e4 ....Received Response msg 200/INVITE/cseq=25531 (rdata0x91aa1ac), sending ACK [Jan 22 18:08:06] DEBUG[3079] pjsip: tdta0x95bb7d0 ....Destroying txdata Request msg ACK/cseq=25530 (tdta0x95bb7d0) [Jan 22 18:08:06] DEBUG[3079] pjsip: endpoint ....Request msg ACK/cseq=25531 (tdta0x95bb7d0) created. [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 .....Sending Request msg ACK/cseq=25531 (tdta0x95bb7d0) [Jan 22 18:08:06] DEBUG[3079] pjsip: sip_resolve.c .....Target '192.168.1.13:5060' type=Unspecified resolved to '192.168.1.13:5060' type=UDP (UDP transport) [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:06] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (408 bytes) to UDP:192.168.1.13:5060 ---> ACK sip:ALICE@192.168.1.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPj1da3e1bb-c552-4546-9493-fbc73838c0b8 From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25531 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x9358cbc [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Endpoint 'ALICE()' INVITE delay check. tsx-state:Terminated [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Endpoint 'ALICE()' sending delayed BYE request. [Jan 22 18:08:06] DEBUG[3079] pjsip: endpoint .Request msg BYE/cseq=25533 (tdta0x9196e60) created. [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Method is BYE [Jan 22 18:08:06] DEBUG[3079] pjsip: inv0x93b02e4 .Sending Request msg BYE/cseq=25533 (tdta0x9196e60) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ..Sending Request msg BYE/cseq=25533 (tdta0x9196e60) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x959b8b4 ...Transaction created for Request msg BYE/cseq=25532 (tdta0x9196e60) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x959b8b4 ..Sending Request msg BYE/cseq=25532 (tdta0x9196e60) in state Null [Jan 22 18:08:06] DEBUG[3079] pjsip: sip_resolve.c ...Target '192.168.1.13:5060' type=Unspecified resolved to '192.168.1.13:5060' type=UDP (UDP transport) [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:06] DEBUG[3079] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:06] VERBOSE[3079] res_pjsip_logger.c: <--- Transmitting SIP request (408 bytes) to UDP:192.168.1.13:5060 ---> BYE sip:ALICE@192.168.1.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPja599e0e7-c93d-49eb-99b5-dbbe7e6b5355 From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25532 BYE Max-Forwards: 70 User-Agent: Asterisk PBX 13.7.0 Content-Length: 0 [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x959b8b4 ...State changed from Null to Calling, event=TX_MSG [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ....Transaction tsx0x959b8b4 state changed to Calling [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x959b8b4 [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current transaction state is Calling [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The transaction state change event is TX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is CONFIRMED [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Sending request [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Method is BYE [Jan 22 18:08:06] DEBUG[3071] cdr.c: CDR for PJSIP/LocalTrunk-00000001 is dialed and has no Party B; discarding [Jan 22 18:08:06] DEBUG[3084] pjsip: tsx0x9358cbc Timeout timer event [Jan 22 18:08:06] DEBUG[3084] pjsip: tsx0x9358cbc .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:08:06] DEBUG[3084] pjsip: tdta0x95ad198 ..Destroying txdata Request msg INVITE/cseq=25531 (tdta0x95ad198) [Jan 22 18:08:06] DEBUG[3084] pjsip: tsx0x9358cbc Transaction destroyed! [Jan 22 18:08:06] DEBUG[3084] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=25532 (rdata0x95af714) [Jan 22 18:08:06] VERBOSE[3084] res_pjsip_logger.c: <--- Received SIP response (355 bytes) from UDP:192.168.1.13:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.24:5060;rport;branch=z9hG4bKPja599e0e7-c93d-49eb-99b5-dbbe7e6b5355 From: "123" ;tag=4420202e-26cf-40bb-a9d9-aea36299fcfa To: "ALICE" ;tag=72823432 Call-ID: 14760665923996-151762700118532@192.168.1.13 CSeq: 25532 BYE Server: Voip Phone 1.0 Content-Length: 0 [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '192.168.1.13:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '192.168.1.13' and port '5060'. [Jan 22 18:08:06] DEBUG[3084] netsock2.c: Splitting '0.0.0.0:5060' into... [Jan 22 18:08:06] DEBUG[3084] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jan 22 18:08:06] DEBUG[3079] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=25532 (rdata0x95b989c) [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x959b8b4 .Incoming Response msg 200/BYE/cseq=25532 (rdata0x95b989c) in state Calling [Jan 22 18:08:06] DEBUG[3079] pjsip: tsx0x959b8b4 ..State changed from Calling to Completed, event=RX_MSG [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ...Received Response msg 200/BYE/cseq=25532 (rdata0x95b989c) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 ...Transaction tsx0x959b8b4 state changed to Completed [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: There is no transaction involved in this state change [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:08:06] DEBUG[3079] pjsip: tdta0x95bb7d0 ....Destroying txdata Request msg ACK/cseq=25531 (tdta0x95bb7d0) [Jan 22 18:08:06] DEBUG[3079] pjsip: dlg0x93b02e4 .....Session count dec to 2 by mod-invite [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x959b8b4 [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current transaction state is Completed [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The transaction state change event is RX_MSG [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Received response [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: Response is 200 OK [Jan 22 18:08:06] DEBUG[3079] res_pjsip_session.c: BYE received final response code 200 [Jan 22 18:08:11] DEBUG[3084] pjsip: tsx0x959b8b4 Timeout timer event [Jan 22 18:08:11] DEBUG[3084] pjsip: tsx0x959b8b4 .State changed from Completed to Terminated, event=TIMER [Jan 22 18:08:11] DEBUG[3084] pjsip: dlg0x93b02e4 ..Transaction tsx0x959b8b4 state changed to Terminated [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The state change pertains to the endpoint 'ALICE()' [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x959b8b4 [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The current transaction state is Terminated [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The transaction state change event is TIMER [Jan 22 18:08:11] DEBUG[3084] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 22 18:08:11] DEBUG[3079] res_pjsip_session.c: Destroying SIP session with endpoint ALICE [Jan 22 18:08:11] DEBUG[3079] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x95793d4' [Jan 22 18:08:11] DEBUG[3079] rtp_engine.c: Destroyed RTP instance '0x95793d4' [Jan 22 18:08:11] DEBUG[3079] pjsip: dlg0x93b02e4 .Session count dec to 0 by Session Module [Jan 22 18:08:11] DEBUG[3079] pjsip: dlg0x93b02e4 .Dialog destroyed [Jan 22 18:08:11] DEBUG[3079] taskprocessor.c: destroying taskprocessor '77f45be0-0237-4e55-b612-8c857b8b8b89' [Jan 22 18:08:11] DEBUG[3084] pjsip: tsx0x959b8b4 Timeout timer event [Jan 22 18:08:11] DEBUG[3084] pjsip: tsx0x959b8b4 .State changed from Terminated to Destroyed, event=TIMER [Jan 22 18:08:11] DEBUG[3084] pjsip: tdta0x9196e60 ..Destroying txdata Request msg BYE/cseq=25532 (tdta0x9196e60) [Jan 22 18:08:11] DEBUG[3084] pjsip: tsx0x959b8b4 Transaction destroyed! [Jan 22 18:08:12] DEBUG[3133] cdr.c: CDR Engine termination request received; waiting on messages... [Jan 22 18:08:12] DEBUG[3133] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Jan 22 18:08:12] VERBOSE[3133] asterisk.c: Asterisk cleanly ending (0). [Jan 22 18:08:12] VERBOSE[3133] asterisk.c: Executing last minute cleanups [Jan 22 18:08:12] DEBUG[3133] res_musiconhold.c: Destroying MOH class 'default' [Jan 22 18:08:12] DEBUG[3133] taskprocessor.c: destroying taskprocessor 'ab88baf9-6219-4d70-997a-7158e0fdb1e5' [Jan 22 18:08:12] DEBUG[3133] asterisk.c: Asterisk ending (0).