[Jan 23 10:41:33] DEBUG[129589] manager.c: Running action 'Command'
[Jan 23 10:41:33] DEBUG[129589] manager.c: Running action 'PJSIPShowEndpoints'
[Jan 23 10:41:34] DEBUG[129506] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=1 (rdata0x7f717c173ed8)
[Jan 23 10:41:34] DEBUG[129506] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000038 to use for Request msg OPTIONS/cseq=1 (rdata0x7f717c173ed8)
[Jan 23 10:41:34] DEBUG[26730] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:34] DEBUG[26730] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:34] DEBUG[26730] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.100.1:5060 matches identify 'ITSP1_identify'
[Jan 23 10:41:34] DEBUG[26730] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint ITSP1
[Jan 23 10:41:34] DEBUG[26730] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:34] DEBUG[26730] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:48] DEBUG[129521] res_pjsip_registrar_expire.c: Woke up at 1516683408 Interval: 30
[Jan 23 10:41:48] DEBUG[129521] res_pjsip_registrar_expire.c: Expiring 0 contacts
[Jan 23 10:41:54] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP request (298 bytes) from UDP:192.168.100.1:5060 --->
OPTIONS sip:192.168.100.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.1:5060;branch=z9hG4bKm03VMdAYq_
From: <sip:192.168.100.1:5060>;tag=GVGoPJKTsQx29-125-157-1.001
To: <sip:192.168.100.10:5060>
Call-ID: g4UV6urc2xz-47Iwnhxt@itspgw
CSeq: 1 OPTIONS
Max-Forwards: 70
Content-Length: 0
[Jan 23 10:41:54] DEBUG[129506] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=1 (rdata0x7f717c185958)
[Jan 23 10:41:54] DEBUG[129506] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000039 to use for Request msg OPTIONS/cseq=1 (rdata0x7f717c185958)
[Jan 23 10:41:54] DEBUG[108019] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:54] DEBUG[108019] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:54] DEBUG[108019] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.100.1:5060 matches identify 'ITSP1_identify'
[Jan 23 10:41:54] DEBUG[108019] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint ITSP1
[Jan 23 10:41:54] DEBUG[108019] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:54] DEBUG[108019] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:54] VERBOSE[108019] res_pjsip_logger.c: <--- Transmitting SIP response (802 bytes) to UDP:192.168.100.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.1:5060;rport=5060;received=192.168.100.1;branch=z9hG4bKm03VMdAYq_
Call-ID: g4UV6urc2xz-47Iwnhxt@itspgw
From: <sip:192.168.100.1>;tag=GVGoPJKTsQx29-125-157-1.001
To: <sip:192.168.100.10>;tag=z9hG4bKm03VMdAYq_
CSeq: 1 OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/cpim-pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Server: PBX
Content-Length: 0
[Jan 23 10:41:56] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP request (1355 bytes) from UDP:192.168.100.1:5060 --->
INVITE sip:9123*9865555555@192.168.100.10;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.100.1:5060;branch=z9hG4bK6M5zLXA-kr
From: <sip:9855555555@astgw;user=phone>;tag=D1c88gwQSS-12623-21-7-120
To: <sip:9123*9865555555@192.168.100.10;user=phone>
Call-ID: mt8Byun65r7fYy7ulV4W@itspgw
CSeq: 1 INVITE
Contact: <sip:192.168.100.1:5060>
Max-Forwards: 70
Supported: 100rel,timer
Allow: INVITE,PRACK,ACK,UPDATE,CANCEL,BYE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY
Privacy: none
P-Asserted-Identity: <sip:9855555555@astgw;user=phone>
Min-SE: 90
Session-Expires: 1800
P-Charging-Vector: icid-value=192.168.100.12047415243321
Accept: application/sdp,
application/isup,
multipart/mixed,
application/dtmf,
application/dtmf-relay
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 521
v=0
o=- 570019316 570019316 IN IP4 192.168.103.2
s=-
c=IN IP4 192.168.103.2
t=0 0
m=audio 10594 RTP/AVP 8 18 97 98 3 99 100 96
c=IN IP4 192.168.103.2
a=rtpmap:8 PCMA/8000/1
a=rtpmap:18 G729/8000/1
a=rtpmap:97 AMR/8000/1
a=fmtp:97 mode-set=0,2,4,7;mode-change-period=2;mode-change-neighbor=1
a=rtpmap:98 AMR/8000/1
a=fmtp:98 mode-set=0,2,4,7
a=rtpmap:3 GSM/8000/1
a=rtpmap:99 GSM-EFR/8000/1
a=rtpmap:100 AMR/8000/1
a=fmtp:100 mode-set=0,2,4
a=rtpmap:96 telephone-event/8000/1
a=fmtp:96 0-15
a=sendrecv
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f717c1973d8)
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000039 to use for Request msg INVITE/cseq=1 (rdata0x7f717c1973d8)
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.100.1:5060 matches identify 'ITSP1_identify'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint ITSP1
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:56] DEBUG[17863] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000039 to use for Request msg INVITE/cseq=1 (rdata0x7f717c1a0118)
[Jan 23 10:41:56] VERBOSE[17863] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '192.168.100.10'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jan 23 10:41:56] VERBOSE[17863] res_pjsip_logger.c: <--- Transmitting SIP response (343 bytes) to UDP:192.168.100.1:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.100.1:5060;rport=5060;received=192.168.100.1;branch=z9hG4bK6M5zLXA-kr
Call-ID: mt8Byun65r7fYy7ulV4W@itspgw
From: <sip:9855555555@astgw;user=phone>;tag=D1c88gwQSS-12623-21-7-120
To: <sip:9123*9865555555@192.168.100.10;user=phone>
CSeq: 1 INVITE
Server: PBX
Content-Length: 0
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1()'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f71501a2ba8)
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current inv state is INCOMING
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1()'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f71501a2ba8)
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f71501a2ba8
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current inv state is INCOMING
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: Splitting '192.168.103.2' into...
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: ...host '192.168.103.2' and port ''.
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: Splitting '192.168.100.10' into...
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: ...host '192.168.100.10' and port ''.
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_sdp_rtp.c: Endpoint ITSP1: Binding RTP media to 192.168.100.10
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f71542b4d10'
[Jan 23 10:41:56] DEBUG[17863] res_rtp_asterisk.c: Allocated port 17986 for RTP instance '0x7f71542b4d10'
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: RTP instance '0x7f71542b4d10' is setup and ready to go
[Jan 23 10:41:56] DEBUG[17863] acl.c: Attached to given IP address
[Jan 23 10:41:56] DEBUG[17863] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f71542b4d10'
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 98 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 99 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 100 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Setting tx payload type 96 based on m type on 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 3 (0x7f71540da878) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f7154204b78) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f71542053f8) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 96 (0x7f71540dbdc8) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 97 (0x7f7154205ad8) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 98 (0x7f71540d9ff8) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 99 (0x1337378) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Crossover copying tx to rx payload mapping 100 (0x7f71540db548) from 0x7f712a8fc280 to 0x7f712a8fc280
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 3 (0x7f71540da878) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 8 (0x7f7154204b78) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 18 (0x7f71542053f8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 96 (0x7f71540dbdc8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 97 (0x7f7154205ad8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 98 (0x7f71540d9ff8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 99 (0x1337378) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying rx payload mapping 100 (0x7f71540db548) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 3 (0x7f71540da878) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 8 (0x7f7154204b78) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 18 (0x7f71542053f8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 96 (0x7f71540dbdc8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 97 (0x7f7154205ad8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 98 (0x7f71540d9ff8) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 99 (0x1337378) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] rtp_engine.c: Copying tx payload mapping 100 (0x7f71540db548) from 0x7f712a8fc280 to 0x7f71542b4ed8
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Media stream 'audio' handled by audio
[Jan 23 10:41:56] DEBUG[17863] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f71542b4d10'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Method is INVITE
[Jan 23 10:41:56] DEBUG[17863] channel.c: Channel 0x7f71542d3e30 'PJSIP/ITSP1-0000da96' allocated
[Jan 23 10:41:56] DEBUG[17863] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/ITSP1-0000da96
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] pbx_variables.c: Result of 'EXTEN' is '9123*9865555555'
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] pbx.c: Launching 'Goto'
[Jan 23 10:41:56] VERBOSE[54314][C-0000daa6] pbx.c: Executing [9123*9865555555@DID_trunk_1:1] Goto("PJSIP/ITSP1-0000da96", "BEEP_IN_ONNET,9865555555,1") in new stack
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: PJSIP/ITSP1-0000da96
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9123*9865555555
Priority: 1
Uniqueid: 1516683416.111748
Linkedid: 1516683416.111748
[Jan 23 10:41:56] VERBOSE[54314][C-0000daa6] pbx_builtins.c: Goto (BEEP_IN_ONNET,9865555555,1)
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] pbx.c: Launching 'Hangup'
[Jan 23 10:41:56] VERBOSE[54314][C-0000daa6] pbx.c: Executing [9865555555@BEEP_IN_ONNET:1] Hangup("PJSIP/ITSP1-0000da96", "16") in new stack
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/ITSP1-0000da96'
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] pbx.c: Spawn extension (BEEP_IN_ONNET,9865555555,1) exited non-zero on 'PJSIP/ITSP1-0000da96'
[Jan 23 10:41:56] VERBOSE[54314][C-0000daa6] pbx.c: Spawn extension (BEEP_IN_ONNET, 9865555555, 1) exited non-zero on 'PJSIP/ITSP1-0000da96'
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/ITSP1-0000da96'
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] channel.c: Channel 0x7f71542d3e30 'PJSIP/ITSP1-0000da96' hanging up. Refs: 2
[Jan 23 10:41:56] DEBUG[54314][C-0000daa6] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Method is INVITE, Response is 603 Decline
[Jan 23 10:41:56] VERBOSE[26730] res_pjsip_logger.c: <--- Transmitting SIP response (409 bytes) to UDP:192.168.100.1:5060 --->
SIP/2.0 603 Decline
Via: SIP/2.0/UDP 192.168.100.1:5060;rport=5060;received=192.168.100.1;branch=z9hG4bK6M5zLXA-kr
Call-ID: mt8Byun65r7fYy7ulV4W@itspgw
From: <sip:9855555555@astgw;user=phone>;tag=D1c88gwQSS-12623-21-7-120
To: <sip:9123*9865555555@192.168.100.10;user=phone>;tag=e1f2893b-cd47-4b7b-82ff-72e141f57c6b
CSeq: 1 INVITE
Server: PBX
Reason: Q.850;cause=16
Content-Length: 0
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da96)'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f71501a2ba8)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da96)'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f71501a2ba8)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f71501a2ba8
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current transaction state is Completed
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:41:56] DEBUG[26730] channel.c: Channel 0x7f71542d3e30 'PJSIP/ITSP1-0000da96' destroying
[Jan 23 10:41:56] DEBUG[129492] cdr.c: Finalized CDR for PJSIP/ITSP1-0000da96 - start 1516683416.501300 answer 0.000000 end 1516683416.502495 dispo NO ANSWER
[Jan 23 10:41:56] DEBUG[129478] threadpool.c: Increasing threadpool stasis-core's size by 1
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: PJSIP/ITSP1-0000da96
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9123*9865555555
Priority: 1
Uniqueid: 1516683416.111748
Linkedid: 1516683416.111748
Extension: 9123*9865555555
Application: Goto
AppData: BEEP_IN_ONNET,9865555555,1
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Destroying SIP session with endpoint ITSP1
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: PJSIP/ITSP1-0000da96
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_IN_ONNET
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111748
Linkedid: 1516683416.111748
Extension: 9865555555
Application: Hangup
AppData: 16
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: SoftHangupRequest
Privilege: call,all
Channel: PJSIP/ITSP1-0000da96
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_IN_ONNET
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111748
Linkedid: 1516683416.111748
Cause: 16
[Jan 23 10:41:56] DEBUG[129492] res_odbc.c: Reusing ODBC handle 0x148bf80 from class 'asterisk'
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: PJSIP/ITSP1-0000da96
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_IN_ONNET
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111748
Linkedid: 1516683416.111748
Cause: 16
Cause-txt: Normal Clearing
[Jan 23 10:41:56] DEBUG[129492] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate, clid, src, dst, dcontext, channel, lastapp, lastdata, duration, billsec, disposition, amaflags, uniqueid) VALUES ({ ts '2018-01-23 10:41:56' }, '"" <9855555555>', '9855555555', '9865555555', 'BEEP_IN_ONNET', 'PJSIP/ITSP1-0000da96', 'Hangup', '16', 0, 0, 'NO ANSWER', 3, '1516683416.111748')]
[Jan 23 10:41:56] DEBUG[26730] rtp_engine.c: Destroyed RTP instance '0x7f71542b4d10'
[Jan 23 10:41:56] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for PJSIP - ITSP1
[Jan 23 10:41:56] DEBUG[129489] devicestate.c: Changing state for PJSIP/ITSP1 - state 1 (Not in use)
[Jan 23 10:41:56] DEBUG[129492] res_odbc.c: Releasing ODBC handle 0x148bf80 into pool
[Jan 23 10:41:56] DEBUG[129588] manager.c: Running action 'Originate'
[Jan 23 10:41:56] DEBUG[54316] channel.c: Channel 0x7f71c0011170 'Local/9865555555@BEEP_LOOP-00006cf7;1' allocated
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[54316] channel.c: Channel 0x7f71c0005100 'Local/9865555555@BEEP_LOOP-00006cf7;2' allocated
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
Extension: 9865555555
Application: AppDial2
AppData: (Outgoing Line)
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewCallerid
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
CID-CallingPres: 0 (Presentation Allowed, Not Screened)
[Jan 23 10:41:56] VERBOSE[54317] dial.c: Called 9865555555@BEEP_LOOP
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'commonID' is '1516683416.111748'
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewConnectedLine
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] pbx.c: Launching 'Set'
[Jan 23 10:41:56] VERBOSE[54318][C-0000daa7] pbx.c: Executing [9865555555@BEEP_LOOP:1] Set("Local/9865555555@BEEP_LOOP-00006cf7;2", "CDR(userfield)=1516683416.111748") in new stack
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewCallerid
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
CID-CallingPres: 0 (Presentation Allowed, Not Screened)
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewConnectedLine
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: LocalBridge
Privilege: call,all
LocalOneChannel: Local/9865555555@BEEP_LOOP-00006cf7;1
LocalOneChannelState: 0
LocalOneChannelStateDesc: Down
LocalOneCallerIDNum: 9855555555
LocalOneCallerIDName: <unknown>
LocalOneConnectedLineNum: 9855555555
LocalOneConnectedLineName: <unknown>
LocalOneLanguage: en
LocalOneAccountCode:
LocalOneContext: BEEP_LOOP
LocalOneExten: 9865555555
LocalOnePriority: 1
LocalOneUniqueid: 1516683416.111749
LocalOneLinkedid: 1516683416.111749
LocalTwoChannel: Local/9865555555@BEEP_LOOP-00006cf7;2
LocalTwoChannelState: 4
LocalTwoChannelStateDesc: Ring
LocalTwoCallerIDNum: 9855555555
LocalTwoCallerIDName: <unknown>
LocalTwoConnectedLineNum: 9855555555
LocalTwoConnectedLineName: <unknown>
LocalTwoLanguage: en
LocalTwoAccountCode:
LocalTwoContext: BEEP_LOOP
LocalTwoExten: 9865555555
LocalTwoPriority: 1
LocalTwoUniqueid: 1516683416.111750
LocalTwoLinkedid: 1516683416.111749
Context: BEEP_LOOP
Exten: 9865555555
LocalOptimization: Yes
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: DialBegin
Privilege: call,all
DestChannel: Local/9865555555@BEEP_LOOP-00006cf7;1
DestChannelState: 0
DestChannelStateDesc: Down
DestCallerIDNum: 9855555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: BEEP_LOOP
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111749
DestLinkedid: 1516683416.111749
DialString: 9865555555@BEEP_LOOP
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Extension: 9865555555
Application: Set
AppData: CDR(userfield)=1516683416.111748
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'EXTEN' is '9865555555'
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'trunk' is 'ITSP1'
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] pbx.c: Launching 'Dial'
[Jan 23 10:41:56] VERBOSE[54318][C-0000daa7] pbx.c: Executing [9865555555@BEEP_LOOP:2] Dial("Local/9865555555@BEEP_LOOP-00006cf7;2", "PJSIP/9865555555@ITSP1") in new stack
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Extension: 9865555555
Application: Dial
AppData: PJSIP/9865555555@ITSP1
[Jan 23 10:41:56] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP request (390 bytes) from UDP:192.168.100.1:5060 --->
ACK sip:9123*9865555555@192.168.100.10;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.100.1:5060;branch=z9hG4bK6M5zLXA-kr
From: <sip:9855555555@astgw;user=phone>;tag=D1c88gwQSS-12623-21-7-120
To: <sip:9123*9865555555@192.168.100.10;user=phone>;tag=e1f2893b-cd47-4b7b-82ff-72e141f57c6b
Call-ID: mt8Byun65r7fYy7ulV4W@itspgw
CSeq: 1 ACK
Max-Forwards: 70
Content-Length: 0
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150115aa8 for Request msg ACK/cseq=1 (rdata0x7f717c1a8e58)
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000039 to use for Request msg ACK/cseq=1 (rdata0x7f717c1a8e58)
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: Splitting '192.168.100.1' into...
[Jan 23 10:41:56] DEBUG[17863] netsock2.c: ...host '192.168.100.1' and port ''.
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.100.1:5060 matches identify 'ITSP1_identify'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint ITSP1
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: inv_session 0x7f71540a9618 has no ast session
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f71501a2ba8)
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f71501a2ba8
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current transaction state is Confirmed
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Channel 0x7f714400d010 'PJSIP/ITSP1-0000da97' allocated
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: s
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] rtp_engine.c: Can't find native functions for channel 'Local/9865555555@BEEP_LOOP-00006cf7;2'
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Inheriting variable __commonID from Local/9865555555@BEEP_LOOP-00006cf7;2 to PJSIP/ITSP1-0000da97.
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Inheriting variable __callType from Local/9865555555@BEEP_LOOP-00006cf7;2 to PJSIP/ITSP1-0000da97.
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Inheriting variable __isSuccess from Local/9865555555@BEEP_LOOP-00006cf7;2 to PJSIP/ITSP1-0000da97.
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Inheriting variable __trunk from Local/9865555555@BEEP_LOOP-00006cf7;2 to PJSIP/ITSP1-0000da97.
[Jan 23 10:41:56] VERBOSE[54318][C-0000daa7] app_dial.c: Called PJSIP/9865555555@ITSP1
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Channel PJSIP/ITSP1-0000da97 setting read format path: alaw -> slin
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Channel Local/9865555555@BEEP_LOOP-00006cf7;2 setting write format path: slin -> slin
[Jan 23 10:41:56] DEBUG[26730] netsock2.c: Splitting '192.168.100.10' into...
[Jan 23 10:41:56] DEBUG[26730] netsock2.c: ...host '192.168.100.10' and port ''.
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_sdp_rtp.c: Endpoint ITSP1: Binding RTP media to 192.168.100.10
[Jan 23 10:41:56] DEBUG[26730] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f718800cd00'
[Jan 23 10:41:56] DEBUG[26730] res_rtp_asterisk.c: Allocated port 19614 for RTP instance '0x7f718800cd00'
[Jan 23 10:41:56] DEBUG[26730] rtp_engine.c: RTP instance '0x7f718800cd00' is setup and ready to go
[Jan 23 10:41:56] DEBUG[26730] acl.c: Attached to given IP address
[Jan 23 10:41:56] DEBUG[26730] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f718800cd00'
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Channel Local/9865555555@BEEP_LOOP-00006cf7;2 setting read format path: slin -> slin
[Jan 23 10:41:56] DEBUG[54318][C-0000daa7] channel.c: Channel PJSIP/ITSP1-0000da97 setting write format path: slin -> alaw
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
Extension: 9865555555
Application: AppDial
AppData: (Outgoing Line)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Method is INVITE
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewCallerid
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
CID-CallingPres: 0 (Presentation Allowed, Not Screened)
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewConnectedLine
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: DialBegin
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
DestChannel: PJSIP/ITSP1-0000da97
DestChannelState: 0
DestChannelStateDesc: Down
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: DID_trunk_1
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111751
DestLinkedid: 1516683416.111749
DialString: 9865555555@ITSP1
[Jan 23 10:41:56] DEBUG[26730] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.100.1'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.100.1' is 'UDP'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip/pjsip_resolver.c: Target '192.168.100.1' is an IP address, skipping resolution
[Jan 23 10:41:56] DEBUG[26730] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.100.10:5060 (this may be re-written again later)
[Jan 23 10:41:56] DEBUG[129588] manager.c: Examining AMI event:
Event: NewConnectedLine
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
[Jan 23 10:41:56] VERBOSE[26730] res_pjsip_logger.c: <--- Transmitting SIP request (826 bytes) to UDP:192.168.100.1:5060 --->
INVITE sip:9865555555@192.168.100.1 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.10:5060;rport;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>
Contact: <sip:asterisk@192.168.100.10:5060>
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: PBX
Content-Type: application/sdp
Content-Length: 181
v=0
o=- 1006350561 1006350561 IN IP4 192.168.100.10
s=Asterisk
c=IN IP4 192.168.100.10
t=0 0
m=audio 19614 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
a=maxptime:150
a=sendrecv
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current inv state is CALLING
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f715043dfa8
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current transaction state is Calling
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:56] DEBUG[26730] res_pjsip_session.c: The current inv state is CALLING
[Jan 23 10:41:56] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (342 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 INVITE
Content-Length: 0
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 100/INVITE/cseq=30248 (rdata0x7f717c042a08)
[Jan 23 10:41:56] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f715043dfa8
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: The current inv state is CALLING
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Received response
[Jan 23 10:41:56] DEBUG[17863] res_pjsip_session.c: Response is 100 Trying
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (757 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 INVITE
RSeq: 1
Contact: <sip:192.168.100.1:5060>
Require: 100rel
Allow: INVITE,PRACK,ACK,UPDATE,CANCEL,BYE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 171
v=0
o=- 570019318 570019318 IN IP4 192.168.103.1
s=-
c=IN IP4 192.168.103.1
t=0 0
m=audio 9914 RTP/AVP 8
c=IN IP4 192.168.103.1
a=rtpmap:8 PCMA/8000/1
a=sendrecv
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 183/INVITE/cseq=30248 (rdata0x7f717c0b4148)
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Response is 183 Session Progress
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 23 10:41:58] DEBUG[26730] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f718800cd00'
[Jan 23 10:41:58] DEBUG[26730] netsock2.c: Splitting '192.168.103.1' into...
[Jan 23 10:41:58] DEBUG[26730] netsock2.c: ...host '192.168.103.1' and port ''.
[Jan 23 10:41:58] DEBUG[26730] acl.c: For destination '192.168.103.1', our source address is '192.168.100.10'.
[Jan 23 10:41:58] DEBUG[26730] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f718800cd00'
[Jan 23 10:41:58] VERBOSE[26730] res_rtp_asterisk.c: 0x7f7188031a90 -- Strict RTP learning after remote address set to: 192.168.103.1:9914
[Jan 23 10:41:58] DEBUG[26730] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f712aa6fbf0
[Jan 23 10:41:58] DEBUG[26730] rtp_engine.c: Copying tx payload mapping 8 (0x7f718806fcd8) from 0x7f712aa6fbf0 to 0x7f718800cec8
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 23 10:41:58] DEBUG[26730] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.100.1'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.100.1' is 'UDP'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip/pjsip_resolver.c: Target '192.168.100.1' is an IP address, skipping resolution
[Jan 23 10:41:58] VERBOSE[26730] res_pjsip_logger.c: <--- Transmitting SIP request (420 bytes) to UDP:192.168.100.1:5060 --->
PRACK sip:192.168.100.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.10:5060;rport;branch=z9hG4bKPj1e796b4d-fa80-48cd-823b-ff3f307494c2
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30249 PRACK
RAck: 1 30248 INVITE
Max-Forwards: 70
User-Agent: PBX
Content-Length: 0
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f715021d108
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current transaction state is Calling
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f715043dfa8
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Response is 183 Session Progress
[Jan 23 10:41:58] VERBOSE[54318][C-0000daa7] app_dial.c: PJSIP/ITSP1-0000da97 is making progress passing it to Local/9865555555@BEEP_LOOP-00006cf7;2
[Jan 23 10:41:58] VERBOSE[54317] dial.c: Local/9865555555@BEEP_LOOP-00006cf7;1 is making progress
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialState
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
DestChannel: PJSIP/ITSP1-0000da97
DestChannelState: 0
DestChannelStateDesc: Down
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: DID_trunk_1
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111751
DestLinkedid: 1516683416.111749
DialStatus: PROGRESS
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialState
Privilege: call,all
DestChannel: Local/9865555555@BEEP_LOOP-00006cf7;1
DestChannelState: 0
DestChannelStateDesc: Down
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: BEEP_LOOP
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111749
DestLinkedid: 1516683416.111749
DialStatus: PROGRESS
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (369 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1e796b4d-fa80-48cd-823b-ff3f307494c2;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30249 PRACK
Content-Length: 0
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 200/PRACK/cseq=30249 (rdata0x7f717c0cf9a8)
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f715021d108
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The current transaction state is Completed
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Response is 200 OK
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: PRACK received final response code 200
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (748 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 INVITE
RSeq: 2
Contact: <sip:192.168.100.1:5060>
Require: 100rel
Allow: INVITE,PRACK,ACK,UPDATE,CANCEL,BYE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 171
v=0
o=- 570019318 570019319 IN IP4 192.168.103.1
s=-
c=IN IP4 192.168.103.1
t=0 0
m=audio 9914 RTP/AVP 8
c=IN IP4 192.168.103.1
a=rtpmap:8 PCMA/8000/1
a=sendrecv
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 180/INVITE/cseq=30248 (rdata0x7f717c04b748)
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Response is 180 Ringing
[Jan 23 10:41:58] DEBUG[17863] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.100.1'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.100.1' is 'UDP'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip/pjsip_resolver.c: Target '192.168.100.1' is an IP address, skipping resolution
[Jan 23 10:41:58] VERBOSE[17863] res_pjsip_logger.c: <--- Transmitting SIP request (420 bytes) to UDP:192.168.100.1:5060 --->
PRACK sip:192.168.100.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.10:5060;rport;branch=z9hG4bKPjb851a239-76cb-41a9-b695-8b50be61e793
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30250 PRACK
RAck: 2 30248 INVITE
Max-Forwards: 70
User-Agent: PBX
Content-Length: 0
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f7150219e68
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current transaction state is Calling
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f715043dfa8
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Response is 180 Ringing
[Jan 23 10:41:58] VERBOSE[54318][C-0000daa7] app_dial.c: PJSIP/ITSP1-0000da97 is ringing
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Newstate
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Newstate
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: NewCallerid
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
CID-CallingPres: 0 (Presentation Allowed, Not Screened)
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialState
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
DestChannel: PJSIP/ITSP1-0000da97
DestChannelState: 5
DestChannelStateDesc: Ringing
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: DID_trunk_1
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111751
DestLinkedid: 1516683416.111749
DialStatus: RINGING
[Jan 23 10:41:58] VERBOSE[54317] dial.c: Local/9865555555@BEEP_LOOP-00006cf7;1 is ringing
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialState
Privilege: call,all
DestChannel: Local/9865555555@BEEP_LOOP-00006cf7;1
DestChannelState: 5
DestChannelStateDesc: Ringing
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: BEEP_LOOP
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111749
DestLinkedid: 1516683416.111749
DialStatus: RINGING
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for PJSIP - ITSP1
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: Changing state for PJSIP/ITSP1 - state 6 (Ringing)
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for Local - 9865555555@BEEP_LOOP
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: Changing state for Local/9865555555@BEEP_LOOP - state 2 (In use)
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/ITSP1
State: RINGING
[Jan 23 10:41:58] DEBUG[129529] app_queue.c: Device 'PJSIP/ITSP1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 23 10:41:58] DEBUG[129588] manager.c: Running action 'Setvar'
[Jan 23 10:41:58] DEBUG[129529] app_queue.c: Device 'Local/9865555555@BEEP_LOOP' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: Local/9865555555@BEEP_LOOP
State: INUSE
[Jan 23 10:41:58] DEBUG[129588] manager.c: Running action 'Hangup'
[Jan 23 10:41:58] VERBOSE[129588] manager.c: Manager 'beep' from 192.168.102.10, hanging up channel: Local/9865555555@BEEP_LOOP-00006cf7;1
[Jan 23 10:41:58] DEBUG[129588] channel.c: Soft-Hanging (0x20) up channel 'Local/9865555555@BEEP_LOOP-00006cf7;1'
[Jan 23 10:41:58] DEBUG[54317] channel.c: Channel 0x7f71c0011170 'Local/9865555555@BEEP_LOOP-00006cf7;1' hanging up. Refs: 3
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialEnd
Privilege: call,all
DestChannel: Local/9865555555@BEEP_LOOP-00006cf7;1
DestChannelState: 5
DestChannelStateDesc: Ringing
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: BEEP_LOOP
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111749
DestLinkedid: 1516683416.111749
DialStatus: NOANSWER
[Jan 23 10:41:58] DEBUG[54316] channel.c: Channel 0x7f71c0011170 'Local/9865555555@BEEP_LOOP-00006cf7;1' destroying
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: HangupRequest
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Cause: 0
[Jan 23 10:41:58] DEBUG[129492] cdr.c: Finalized CDR for Local/9865555555@BEEP_LOOP-00006cf7;1 - start 1516683416.504868 answer 0.000000 end 1516683418.693239 dispo NO ANSWER
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;1
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111749
Linkedid: 1516683416.111749
Cause: 0
Cause-txt: Unknown
[Jan 23 10:41:58] DEBUG[129492] res_odbc.c: Reusing ODBC handle 0x148bf80 from class 'asterisk'
[Jan 23 10:41:58] DEBUG[129492] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate, clid, src, dst, dcontext, channel, lastapp, lastdata, duration, billsec, disposition, amaflags, uniqueid) VALUES ({ ts '2018-01-23 10:41:56' }, '"" <9865555555>', '9865555555', '9865555555', 'BEEP_LOOP', 'Local/9865555555@BEEP_LOOP-00006cf7;1', 'AppDial2', '(Outgoing Line)', 2, 0, 'NO ANSWER', 3, '1516683416.111749')]
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] channel.c: Channel 0x7f714400d010 'PJSIP/ITSP1-0000da97' hanging up. Refs: 2
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP)
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] app_dial.c: Exiting with DIALSTATUS=CANCEL.
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx.c: Spawn extension (BEEP_LOOP,9865555555,2) exited non-zero on 'Local/9865555555@BEEP_LOOP-00006cf7;2'
[Jan 23 10:41:58] VERBOSE[54318][C-0000daa7] pbx.c: Spawn extension (BEEP_LOOP, 9865555555, 2) exited non-zero on 'Local/9865555555@BEEP_LOOP-00006cf7;2'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] channel.c: Soft-Hanging (0x10) up channel 'Local/9865555555@BEEP_LOOP-00006cf7;2'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] channel.c: Soft-Hanging (0x80) up channel 'Local/9865555555@BEEP_LOOP-00006cf7;2'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'commonID' is '1516683416.111748'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'callType' is '1'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'isSuccess' is '1'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx_variables.c: Result of 'HANGUPCAUSE' is '0'
[Jan 23 10:41:58] DEBUG[129492] res_odbc.c: Releasing ODBC handle 0x148bf80 into pool
[Jan 23 10:41:58] DEBUG[26730] rtp_engine.c: Destroyed RTP instance '0x7f718800cd00'
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Method is CANCEL
[Jan 23 10:41:58] DEBUG[129492] cdr.c: Finalized CDR for Local/9865555555@BEEP_LOOP-00006cf7;2 - start 1516683416.505069 answer 0.000000 end 1516683418.693883 dispo NO ANSWER
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for Local - 9865555555@BEEP_LOOP
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: Changing state for Local/9865555555@BEEP_LOOP - state 1 (Not in use)
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx_variables.c: Function CDR(disposition) result is 'NO ANSWER'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] pbx.c: Launching 'Verbose'
[Jan 23 10:41:58] VERBOSE[54318][C-0000daa7] pbx.c: Executing [h@BEEP_LOOP:1] Verbose("Local/9865555555@BEEP_LOOP-00006cf7;2", "1516683416.111748,1,1,0,NO ANSWER") in new stack
[Jan 23 10:41:58] VERBOSE[26730] res_pjsip_logger.c: <--- Transmitting SIP request (397 bytes) to UDP:192.168.100.1:5060 --->
CANCEL sip:9865555555@192.168.100.1 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.10:5060;rport;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 CANCEL
Reason: Q.850;cause=0
Max-Forwards: 70
User-Agent: PBX
Content-Length: 0
[Jan 23 10:41:58] VERBOSE[54318][C-0000daa7] app_verbose.c: 1,1,0,NO ANSWER
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] channel.c: Channel 0x7f71c0005100 'Local/9865555555@BEEP_LOOP-00006cf7;2' hanging up. Refs: 2
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: OriginateResponse
Privilege: call,all
ActionID: 1516683416.5043
Response: Failure
Channel: LOCAL/9865555555@BEEP_LOOP
Context: BEEP_DUMMY
Exten: 1
Reason: 0
Uniqueid: <unknown>
CallerIDNum: 9855555555
CallerIDName: <unknown>
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1(PJSIP/ITSP1-0000da97)'
[Jan 23 10:41:58] DEBUG[54318][C-0000daa7] channel.c: Channel 0x7f71c0005100 'Local/9865555555@BEEP_LOOP-00006cf7;2' destroying
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f71500e2fc8
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current transaction state is Calling
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 23 10:41:58] DEBUG[26730] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[129529] app_queue.c: Device 'Local/9865555555@BEEP_LOOP' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DialEnd
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
DestChannel: PJSIP/ITSP1-0000da97
DestChannelState: 5
DestChannelStateDesc: Ringing
DestCallerIDNum: 9865555555
DestCallerIDName: <unknown>
DestConnectedLineNum: 9855555555
DestConnectedLineName: <unknown>
DestLanguage: en
DestAccountCode:
DestContext: DID_trunk_1
DestExten: 9865555555
DestPriority: 1
DestUniqueid: 1516683416.111751
DestLinkedid: 1516683416.111749
DialStatus: CANCEL
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: SoftHangupRequest
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: 9865555555
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Cause: 16
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Newexten
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: h
Priority: 1
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Extension: h
Application: Verbose
AppData: 1516683416.111748,1,1,0,NO ANSWER
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: Local/9865555555@BEEP_LOOP-00006cf7;2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 9855555555
CallerIDName: <unknown>
ConnectedLineNum: 9865555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: BEEP_LOOP
Exten: h
Priority: 2
Uniqueid: 1516683416.111750
Linkedid: 1516683416.111749
Cause: 0
Cause-txt: Unknown
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: Local/9865555555@BEEP_LOOP
State: NOT_INUSE
[Jan 23 10:41:58] DEBUG[129492] res_odbc.c: Reusing ODBC handle 0x148bf80 from class 'asterisk'
[Jan 23 10:41:58] DEBUG[129492] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate, clid, src, dst, dcontext, channel, dstchannel, lastapp, lastdata, duration, billsec, disposition, amaflags, uniqueid, userfield) VALUES ({ ts '2018-01-23 10:41:56' }, '"" <9855555555>', '9855555555', '9865555555', 'BEEP_LOOP', 'Local/9865555555@BEEP_LOOP-00006cf7;2', 'PJSIP/ITSP1-0000da97', 'Dial', 'PJSIP/9865555555@ITSP1', 2, 0, 'NO ANSWER', 3, '1516683416.111750', '1516683416.111748')]
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for Local - 9865555555@BEEP_LOOP
[Jan 23 10:41:58] DEBUG[129489] core_local.c: Checking if extension 9865555555@BEEP_LOOP exists (devicestate)
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: Changing state for Local/9865555555@BEEP_LOOP - state 1 (Not in use)
[Jan 23 10:41:58] DEBUG[129492] res_odbc.c: Releasing ODBC handle 0x148bf80 into pool
[Jan 23 10:41:58] DEBUG[26730] channel.c: Channel 0x7f714400d010 'PJSIP/ITSP1-0000da97' destroying
[Jan 23 10:41:58] DEBUG[129529] app_queue.c: Device 'Local/9865555555@BEEP_LOOP' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: No provider found, checking channel drivers for PJSIP - ITSP1
[Jan 23 10:41:58] DEBUG[129489] devicestate.c: Changing state for PJSIP/ITSP1 - state 1 (Not in use)
[Jan 23 10:41:58] DEBUG[129529] app_queue.c: Device 'PJSIP/ITSP1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 23 10:41:58] DEBUG[129492] cdr.c: Finalized CDR for PJSIP/ITSP1-0000da97 - start 1516683416.509793 answer 0.000000 end 1516683418.695929 dispo FAILED
[Jan 23 10:41:58] DEBUG[129492] cdr.c: CDR for PJSIP/ITSP1-0000da97 is dialed and has no Party B; discarding
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: PJSIP/ITSP1-0000da97
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9865555555
CallerIDName: <unknown>
ConnectedLineNum: 9855555555
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: DID_trunk_1
Exten: 9865555555
Priority: 1
Uniqueid: 1516683416.111751
Linkedid: 1516683416.111749
Cause: 0
Cause-txt: Unknown
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: Local/9865555555@BEEP_LOOP
State: NOT_INUSE
[Jan 23 10:41:58] DEBUG[129588] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/ITSP1
State: NOT_INUSE
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (369 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPjb851a239-76cb-41a9-b695-8b50be61e793;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30250 PRACK
Content-Length: 0
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 200/PRACK/cseq=30250 (rdata0x7f717c05ec68)
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (370 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 CANCEL
Content-Length: 0
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 200/CANCEL/cseq=30248 (rdata0x7f717c0706e8)
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1()'
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f7150219e68
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The current transaction state is Completed
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: The current inv state is EARLY
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: Response is 200 OK
[Jan 23 10:41:58] DEBUG[108019] res_pjsip_session.c: PRACK received final response code 200
[Jan 23 10:41:58] VERBOSE[129506] res_pjsip_logger.c: <--- Received SIP response (386 bytes) from UDP:192.168.100.1:5060 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8;rport=5060;received=192.168.100.10
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 INVITE
Content-Length: 0
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f7150200058 for Response msg 487/INVITE/cseq=30248 (rdata0x7f717c0875b8)
[Jan 23 10:41:58] DEBUG[129506] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ITSP1-00006d4f associated with dialog dlg0x7f7150200058
[Jan 23 10:41:58] VERBOSE[17863] res_pjsip_logger.c: <--- Transmitting SIP request (400 bytes) to UDP:192.168.100.1:5060 --->
ACK sip:9865555555@192.168.100.1 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.10:5060;rport;branch=z9hG4bKPj1c202229-0358-4157-8887-6ebc818a96b8
From: <sip:9855555555@192.168.100.10>;tag=e92bbbda-04c2-48ec-aefe-33af0b2475ee
To: <sip:9865555555@192.168.100.1>;tag=RFEzXhOOuN-11207-6919-7-109
Call-ID: 6f1e1932-cf1b-4543-ac88-d2c4b15547f9
CSeq: 30248 ACK
Max-Forwards: 70
User-Agent: PBX
Content-Length: 0
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1()'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Received response
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Response is 487 Request Terminated
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The state change pertains to the endpoint 'ITSP1()'
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f715043dfa8
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current transaction state is Completed
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:41:58] DEBUG[17863] res_pjsip_session.c: Destroying SIP session with endpoint ITSP1
[Jan 23 10:42:01] VERBOSE[129484] asterisk.c: Remote UNIX connection
[Jan 23 10:42:01] VERBOSE[54356] asterisk.c: Remote UNIX connection disconnected
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: inv_session 0x7f71540a9618 has no ast session
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f71501a2ba8
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: The current transaction state is Terminated
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 23 10:42:01] DEBUG[129506] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: inv_session 0x7f7154096898 has no ast session
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f715021d108
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current transaction state is Terminated
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:42:03] DEBUG[129589] manager.c: Running action 'Command'
[Jan 23 10:42:03] DEBUG[129589] manager.c: Running action 'PJSIPShowEndpoints'
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: inv_session 0x7f7154096898 has no ast session
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f71500e2fc8
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current transaction state is Terminated
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: inv_session 0x7f7154096898 has no ast session
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f715043dfa8)
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f7150219e68
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current transaction state is Terminated
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 23 10:42:03] DEBUG[129506] res_pjsip_session.c: The current inv state is DISCONNCTD