[Aug 26 13:43:09] Asterisk SVN-branch-12-r397614M built by root @ newtonr-laptop on a x86_64 running Linux on 2013-08-25 00:44:21 UTC [Aug 26 13:43:09] DEBUG[8452] config.c: Parsing /etc/asterisk/logger.conf [Aug 26 13:43:09] VERBOSE[8452] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Aug 26 13:43:09] VERBOSE[8452] logger.c: Asterisk Queue Logger restarted [Aug 26 13:43:12] VERBOSE[8468] res_pjsip_logger.c: <--- Received SIP request (689 bytes) from UDP:127.0.0.1:22200 ---> INVITE sip:912561234567@127.0.0.1 SIP/2.0 Call-ID: 310de214cc9a502e3dd088a19ac31a81@0:0:0:0:0:0:0:0 CSeq: 1 INVITE From: "6002" ;tag=3d9c482e To: Via: SIP/2.0/UDP 127.0.0.1:22200;branch=z9hG4bK-363031-19e3380be146dc59d73e79c54eb1bfb9 Max-Forwards: 70 Contact: "6002" User-Agent: Jitsi2.2.4603.9615Linux Content-Type: application/sdp Content-Length: 207 v=0 o=6002 0 0 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 5017 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6002 [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] VERBOSE[8469] res_pjsip_logger.c: <--- Transmitting SIP response (518 bytes) to UDP:127.0.0.1:22200 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 127.0.0.1:22200;rport;received=127.0.0.1;branch=z9hG4bK-363031-19e3380be146dc59d73e79c54eb1bfb9 Call-ID: 310de214cc9a502e3dd088a19ac31a81@0:0:0:0:0:0:0:0 From: "6002" ;tag=3d9c482e To: ;tag=z9hG4bK-363031-19e3380be146dc59d73e79c54eb1bfb9 CSeq: 1 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1377542592/f6316283e1673b4e27853c3d2f66c13b",opaque="7f3893d049a5cda7",algorithm=md5,qop="auth" Content-Length: 0 [Aug 26 13:43:12] VERBOSE[8468] res_pjsip_logger.c: <--- Received SIP request (374 bytes) from UDP:127.0.0.1:22200 ---> ACK sip:912561234567@127.0.0.1 SIP/2.0 Call-ID: 310de214cc9a502e3dd088a19ac31a81@0:0:0:0:0:0:0:0 Max-Forwards: 70 From: "6002" ;tag=3d9c482e To: ;tag=z9hG4bK-363031-19e3380be146dc59d73e79c54eb1bfb9 Via: SIP/2.0/UDP 127.0.0.1:22200;branch=z9hG4bK-363031-19e3380be146dc59d73e79c54eb1bfb9 CSeq: 1 ACK Content-Length: 0 [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6002 [Aug 26 13:43:12] VERBOSE[8468] res_pjsip_logger.c: <--- Received SIP request (948 bytes) from UDP:127.0.0.1:22200 ---> INVITE sip:912561234567@127.0.0.1 SIP/2.0 Call-ID: 310de214cc9a502e3dd088a19ac31a81@0:0:0:0:0:0:0:0 CSeq: 2 INVITE From: "6002" ;tag=3d9c482e To: Max-Forwards: 70 Contact: "6002" User-Agent: Jitsi2.2.4603.9615Linux Content-Type: application/sdp Via: SIP/2.0/UDP 127.0.0.1:22200;branch=z9hG4bK-363031-e411f2454563b307ce702c5b1e3d59c2 Authorization: Digest username="6002",realm="asterisk",nonce="1377542592/f6316283e1673b4e27853c3d2f66c13b",uri="sip:912561234567@127.0.0.1",response="568f8af066abcb4020c149faa284fa4a",algorithm=md5,opaque="7f3893d049a5cda7",qop=auth,cnonce="xyz",nc=00000001 Content-Length: 207 v=0 o=6002 0 0 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 5017 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6002 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_authenticator_digest.c: Calculated nonce 1377542592/f6316283e1673b4e27853c3d2f66c13b. Actual nonce is 1377542592/f6316283e1673b4e27853c3d2f66c13b [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f2850011b98' [Aug 26 13:43:12] DEBUG[8469] res_rtp_asterisk.c: Allocated port 18952 for RTP instance '0x7f2850011b98' [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: RTP instance '0x7f2850011b98' is setup and ready to go [Aug 26 13:43:12] DEBUG[8469] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f2850011b98' [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Setting payload 0 based on m type on 0x7f289c1831a0 [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Setting payload 101 based on m type on 0x7f289c1831a0 [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Copying payload 0 from 0x7f289c1831a0 to 0x7f2850011cd8 [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Copying payload 101 from 0x7f289c1831a0 to 0x7f2850011cd8 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '127.0.0.1' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '127.0.0.1' and port ''. [Aug 26 13:43:12] VERBOSE[8469] res_pjsip_logger.c: <--- Transmitting SIP response (313 bytes) to UDP:127.0.0.1:22200 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 127.0.0.1:22200;rport;received=127.0.0.1;branch=z9hG4bK-363031-e411f2454563b307ce702c5b1e3d59c2 Call-ID: 310de214cc9a502e3dd088a19ac31a81@0:0:0:0:0:0:0:0 From: "6002" ;tag=3d9c482e To: CSeq: 2 INVITE Content-Length: 0 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The state change pertains to the session with 6002 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2850004a68) [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current inv state is INCOMING [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Sending response [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The state change pertains to the session with 6002 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2850004a68) [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction involved in this state change is 0x7f2850004a68 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current transaction state is Proceeding [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current inv state is INCOMING [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Method is INVITE [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8469] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6002-00000000 [Aug 26 13:43:12] DEBUG[8584][C-00000000] pbx.c: Result of 'EXTEN' is '912561234567' [Aug 26 13:43:12] DEBUG[8584][C-00000000] pbx.c: Launching 'Dial' [Aug 26 13:43:12] VERBOSE[8584][C-00000000] pbx.c: -- Executing [912561234567@from-internal:1] Dial("PJSIP/6002-00000000", "PJSIP/12561234567@mytrunk") in new stack [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8454] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:43:12] DEBUG[8584][C-00000000] channel.c: Not copying variable DIALEDTIME. [Aug 26 13:43:12] DEBUG[8584][C-00000000] channel.c: Not copying variable ANSWEREDTIME. [Aug 26 13:43:12] DEBUG[8584][C-00000000] channel.c: Not copying variable DIALEDPEERNAME. [Aug 26 13:43:12] DEBUG[8584][C-00000000] channel.c: Not copying variable DIALEDPEERNUMBER. [Aug 26 13:43:12] DEBUG[8584][C-00000000] channel.c: Not copying variable DIALSTATUS. [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f2850058058' [Aug 26 13:43:12] DEBUG[8469] res_rtp_asterisk.c: Allocated port 17922 for RTP instance '0x7f2850058058' [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] rtp_engine.c: RTP instance '0x7f2850058058' is setup and ready to go [Aug 26 13:43:12] DEBUG[8469] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f2850058058' [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Method is INVITE [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '65.254.44.194' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '65.254.44.194' and port ''. [Aug 26 13:43:12] DEBUG[8469] netsock2.c: Splitting '192.168.1.55' into... [Aug 26 13:43:12] DEBUG[8469] netsock2.c: ...host '192.168.1.55' and port ''. [Aug 26 13:43:12] VERBOSE[8469] res_pjsip_logger.c: <--- Transmitting SIP request (889 bytes) to UDP:65.254.44.194:5060 ---> INVITE sip:12561234567@65.254.44.194:5060 SIP/2.0 Via: SIP/2.0/UDP 173.17.135.67:5060;rport;branch=z9hG4bKPjCeQksTbZsX5HSt6mlWm5J0l9M9GhMjD4 From: "6002" ;tag=CYtrX0Dhl8oCluX91mGSs-8ahd85-DGV To: sip:65.254.44.194 Contact: Call-ID: 3ISelmfOwGlKiO46sB.EQEV9dOknUHu0 CSeq: 23477 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 263 v=0 o=- 1729287182 1729287182 IN IP4 newtonr-laptop s=Asterisk c=IN IP4 192.168.1.55 t=0 0 m=audio 17922 RTP/AVP 0 101 c=IN IP4 173.17.135.67 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The state change pertains to the session with mytrunk [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2850064518) [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current inv state is CALLING [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Sending request [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Method is INVITE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The state change pertains to the session with mytrunk [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2850064518) [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction involved in this state change is 0x7f2850064518 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current transaction state is Calling [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current inv state is CALLING [Aug 26 13:43:12] VERBOSE[8584][C-00000000] app_dial.c: -- Called PJSIP/12561234567@mytrunk [Aug 26 13:43:12] VERBOSE[8468] res_pjsip_logger.c: <--- Received SIP response (299 bytes) from UDP:65.254.44.194:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;branch=z9hG4bKPjCeQksTbZsX5HSt6mlWm5J0l9M9GhMjD4 From: "6002" ;tag=CYtrX0Dhl8oCluX91mGSs-8ahd85-DGV To: sip:65.254.44.194 Call-ID: 3ISelmfOwGlKiO46sB.EQEV9dOknUHu0 CSeq: 23477 INVITE Content-Length: 0 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The state change pertains to the session with mytrunk [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2850064518) [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction involved in this state change is 0x7f2850064518 [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current transaction state is Proceeding [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 26 13:43:12] DEBUG[8469] res_pjsip_session.c: The current inv state is CALLING