[asterisk-users] Unexpected termination of the call when pick up (res_pjsip)

Wed Feb 10 15:20:30 CST 2016

Please help find the cause of strange behavior res_pjsip.

Making outgoint call to other sip server (CommuniGatePro), my asterisk 
suddenly sends BYE after picking up!
Partial log of an outgoing call with full debug is attached and on web: 
http://pastebin.com/tLNCpx4d

No diagnostic messages why asterisk suddenly decided to hangup i don't 
found :(

There are suggestions or strong belief about the reasons of such behavior?

Thanks.

Dmitriy.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20160211/5dd36102/attachment.html>
-------------- next part --------------
[2016-02-10 22:58:17] VERBOSE[25442] res_pjsip_logger.c: <--- Received SIP response (1111 bytes) from UDP:83.143.192.141:5060 --->
SIP/2.0 183 Call progress
Via: SIP/2.0/UDP 85.142.148.80:5060;rport=5060;branch=z9hG4bKPj1be0328e-fb97-426c-93fe-cf12e32f501a
Record-Route: <sip:3532080.dialog.cgatepro;lr>
Record-Route: <sip:83.143.192.141:5060;lr>
From: "admin" <sip:77777716 at stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a
To: <sip:+7980xxxxxxx at stc.euroset.ru>;tag=B955C4E4-606476-16E1127B
Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7
CSeq: 3711 INVITE
Contact: <sip:signode-606476-16E1127B at 83.143.192.141>
Supported: 100rel,timer,replaces,histinfo,precondition
User-Agent: CommuniGatePro-callLeg/5.4.10
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,MESSAGE,SUBSCRIBE,NOTIFY,PRACK,UPDATE,REFER
Content-Type: application/sdp
Content-Length: 376

v=0
o=CGPLeg606476 1366433634 683216818 IN IP4 83.143.192.141
s=SIP Call
c=IN IP4 83.143.192.141
t=0 0
m=audio 60132 RTP/AVP 8 101
c=IN IP4 83.143.192.141
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=rtcpping:F:1253794:125379478
m=video 60136 RTP/AVP 100
c=IN IP4 83.143.192.141
a=inactive
a=rtcpping:F:1253795:125379578

[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The state change pertains to the endpoint 'srv_d15140(PJSIP/srv_d15140-00000255)'
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffdf039dc58)
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: There is no transaction involved in this state change
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The current inv state is EARLY
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Source of transaction state change is RX_MSG
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Received response
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Response is 183 Call progress
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The state change pertains to the endpoint 'srv_d15140(PJSIP/srv_d15140-00000255)'
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffdf039dc58)
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7ffdf039dc58
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The current transaction state is Proceeding
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The transaction state change event is RX_MSG
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: The current inv state is EARLY
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Received response
[2016-02-10 22:58:17] DEBUG[27034] res_pjsip_session.c: Response is 183 Call progress
[2016-02-10 22:58:17] VERBOSE[7404][C-0000018e] app_dial.c: PJSIP/srv_d15140-00000255 is making progress passing it to PJSIP/admin-00000254
[2016-02-10 22:58:17] DEBUG[31024] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: Splitting '109.60.222.253' into...
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: ...host '109.60.222.253' and port ''.
[2016-02-10 22:58:17] DEBUG[31024] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffddc198f58'
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Don't have a default tx payload type 96 format for m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7ffdc23b7320
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 0 (0x7ffddd7ac7a0) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 2 (0x7ffddc10bd20) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 8 (0x7ffdde1b0ea0) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 18 (0x7ffddda3fae0) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 96 (0x7ffddd6a3410) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 97 (0x7ffddd8a38e0) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] rtp_engine.c: Copying payload 101 (0x7ffddd9d6ca0) from 0x7ffdc23b7320 to 0x7ffddc199120
[2016-02-10 22:58:17] DEBUG[31024] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2016-02-10 22:58:17] DEBUG[25442] netsock2.c: Splitting '185.45.152.174' into...
[2016-02-10 22:58:17] DEBUG[31024] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress
[2016-02-10 22:58:17] DEBUG[25442] netsock2.c: ...host '185.45.152.174' and port ''.
[2016-02-10 22:58:17] DEBUG[31024] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 85.142.148.80:5060
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: Splitting '109.60.222.253' into...
[2016-02-10 22:58:17] DEBUG[29343] res_pjsip_outbound_registration.c: Received REGISTER response 401(Unauthorized)
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: ...host '109.60.222.253' and port ''.
[2016-02-10 22:58:17] DEBUG[5230][C-00000147] audiohook.c: Read factory 0x7ffddc89cac8 was pretty quick last time, waiting for them.
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: Splitting '85.142.148.80' into...
[2016-02-10 22:58:17] DEBUG[31024] netsock2.c: ...host '85.142.148.80' and port ''.

<cutted>

[2016-02-10 22:58:20] VERBOSE[25442] res_pjsip_logger.c: <--- Received SIP response (1153 bytes) from UDP:83.143.192.141:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 85.142.148.80:5060;rport=5060;branch=z9hG4bKPj1be0328e-fb97-426c-93fe-cf12e32f501a
Record-Route: <sip:3532080.dialog.cgatepro;lr>
Record-Route: <sip:83.143.192.141:5060;lr>
From: "admin" <sip:77777716 at stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a
To: <sip:+7980xxxxxxx at stc.euroset.ru>;tag=B955C4E4-606476-16E1127B
Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7
CSeq: 3711 INVITE
Contact: <sip:signode-606476-16E1127B at 83.143.192.141>
Require: timer
Supported: 100rel,timer,replaces,histinfo,precondition
Session-Expires: 1800;refresher=uac
User-Agent: CommuniGatePro-callLeg/5.4.10
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,MESSAGE,SUBSCRIBE,NOTIFY,PRACK,UPDATE,REFER
Content-Type: application/sdp
Content-Length: 376

v=0
o=CGPLeg606476 1366433634 683216819 IN IP4 83.143.192.141
s=SIP Call
c=IN IP4 83.143.192.141
t=0 0
m=audio 60132 RTP/AVP 8 101
c=IN IP4 83.143.192.141
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=rtcpping:F:1253794:125379479
m=video 60136 RTP/AVP 100
c=IN IP4 83.143.192.141
a=inactive
a=rtcpping:F:1253795:125379579

[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The state change pertains to the endpoint 'srv_d15140(PJSIP/srv_d15140-00000255)'
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffdf039dc58)
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: There is no transaction involved in this state change
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The current inv state is CONNECTING
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Source of transaction state change is RX_MSG
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Received response
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Response is 200 OK
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: Splitting '83.143.192.141' into...
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: ...host '83.143.192.141' and port ''.
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: Splitting '83.143.192.141' into...
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: ...host '83.143.192.141' and port ''.
[2016-02-10 22:58:20] VERBOSE[31024] res_pjsip_logger.c: <--- Transmitting SIP request (515 bytes) to UDP:83.143.192.141:5060 --->
ACK sip:signode-606476-16E1127B at 83.143.192.141 SIP/2.0
Via: SIP/2.0/UDP 85.142.148.80:5060;rport;branch=z9hG4bKPjabf90732-f195-468d-9e4b-39af83c27519
From: "admin" <sip:77777716 at stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a
To: <sip:+7980xxxxxxx at stc.euroset.ru>;tag=B955C4E4-606476-16E1127B
Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7
CSeq: 3711 ACK
Route: <sip:83.143.192.141:5060;lr>
Route: <sip:3532080.dialog.cgatepro;lr>
Max-Forwards: 70
User-Agent: ruVoIP.net PBX
Content-Length:  0

[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: Splitting '83.143.192.141' into...
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: ...host '83.143.192.141' and port ''.
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: Splitting '83.143.192.141' into...
[2016-02-10 22:58:20] DEBUG[31024] netsock2.c: ...host '83.143.192.141' and port ''.
[2016-02-10 22:58:20] VERBOSE[31024] res_pjsip_logger.c: <--- Transmitting SIP request (515 bytes) to UDP:83.143.192.141:5060 --->
BYE sip:signode-606476-16E1127B at 83.143.192.141 SIP/2.0
Via: SIP/2.0/UDP 85.142.148.80:5060;rport;branch=z9hG4bKPjfc22d16c-96ac-48a6-bd40-54f0ca6e6628
From: "admin" <sip:77777716 at stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a
To: <sip:+7980xxxxxxx at stc.euroset.ru>;tag=B955C4E4-606476-16E1127B
Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7
CSeq: 3712 BYE
Route: <sip:83.143.192.141:5060;lr>
Route: <sip:3532080.dialog.cgatepro;lr>
Max-Forwards: 70
User-Agent: ruVoIP.net PBX
Content-Length:  0

[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The state change pertains to the endpoint 'srv_d15140(PJSIP/srv_d15140-00000255)'
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffdf039dc58)
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7ffde0124b18
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The current transaction state is Calling
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The transaction state change event is TX_MSG
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The current inv state is CONNECTING
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Sending request
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Method is BYE
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The state change pertains to the endpoint 'srv_d15140(PJSIP/srv_d15140-00000255)'
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7ffdf039dc58
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The current transaction state is Terminated
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The transaction state change event is RX_MSG
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: The current inv state is CONNECTING
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Received response
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Response is 200 OK
[2016-02-10 22:58:20] DEBUG[25553] manager.c: Examining AMI event:
Event: Newstate
Privilege: call,all
Channel: PJSIP/srv_d15140-00000255
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 34
CallerIDName: <unknown>
ConnectedLineNum: 77777716
ConnectedLineName: admin
Language: ru
AccountCode: 9999
Context: ext-fromservers
Exten: 34
Priority: 1
Uniqueid: 1455134292.636
Linkedid: 1455134292.635

[2016-02-10 22:58:20] DEBUG[29343] res_pjsip_outbound_registration.c: Outbound REGISTER attempt 1 to 'sip:sipde.zadarma.com' with client 'sip:357152 at zadarma.com'
[2016-02-10 22:58:20] DEBUG[25428] devicestate.c: No provider found, checking channel drivers for PJSIP - srv_d15140
[2016-02-10 22:58:20] VERBOSE[7404][C-0000018e] app_dial.c: PJSIP/srv_d15140-00000255 answered PJSIP/admin-00000254
[2016-02-10 22:58:20] DEBUG[31024] res_pjsip_session.c: Method is BYE
[2016-02-10 22:58:20] DEBUG[25428] devicestate.c: Changing state for PJSIP/srv_d15140 - state 2 (In use)
[2016-02-10 22:58:20] DEBUG[25442] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 85.142.148.80:5060
[2016-02-10 22:58:20] DEBUG[25442] netsock2.c: Splitting '185.45.152.174' into...
[2016-02-10 22:58:20] DEBUG[25442] netsock2.c: ...host '185.45.152.174' and port ''.
[2016-02-10 22:58:20] DEBUG[25553] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: PJSIP/admin-00000254
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 77777716
CallerIDName: admin
ConnectedLineNum: 34
ConnectedLineName: <unknown>
Language: ru
AccountCode: 9999
Context: context-demon-int
Exten: 34
Priority: 3
Uniqueid: 1455134292.635
Linkedid: 1455134292.635
Variable: DIALSTATUS
Value: ANSWER

[2016-02-10 22:58:20] DEBUG[25479] app_queue.c: Device 'PJSIP/srv_d15140' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2016-02-10 22:58:20] DEBUG[25553] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/srv_d15140
State: INUSE