asterisk users - Feb 2016 - Unexpected termination of the call when pick up (res_pjsip)

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

How are you initiating the call out to that server? Are you dialing from an
internal phone or doing it from the CLI? It looks like it is from an
internal extension, if I were guessing, but that side of the call isn't in
your log.

If it is from an internal extension, I think a SIP trace on that side would
help.

On Wed, Feb 10, 2016, 3:20 PM Dmitriy Serov <serov.d.p at gmail.com>
wrote:
> 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.
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
> New to Asterisk? Join us for a live introductory webinar every Thurs:
>                http://www.asterisk.org/hello
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20160210/cbec9324/attachment.html>

The call initiated from internal extension.

I have made two test call:
Successful call from device on res_pjsip via endpoint on chan_sip: 
http://pastebin.com/LWeDYstj
Unsuccessful call from device on res_pjsip via endpoint on res_pjsip: 
http://pastebin.com/hepVb6Nu

And ones again i don't see anything that would make asterisk send BYE.

I would be grateful for any ideas.

11.02.2016 1:47, Trey Hilyard ?????:
>
> How are you initiating the call out to that server? Are you dialing 
> from an internal phone or doing it from the CLI? It looks like it is 
> from an internal extension, if I were guessing, but that side of the 
> call isn't in your log.
>
> If it is from an internal extension, I think a SIP trace on that side 
> would help.
>
>
> On Wed, Feb 10, 2016, 3:20 PM Dmitriy Serov <serov.d.p at gmail.com 
> <mailto:serov.d.p at gmail.com>> wrote:
>
>     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.
>     --
>     _____________________________________________________________________
>     -- Bandwidth and Colocation Provided by http://www.api-digital.com --
>     New to Asterisk? Join us for a live introductory webinar every Thurs:
>     http://www.asterisk.org/hello
>
>     asterisk-users mailing list
>     To UNSUBSCRIBE or update options visit:
>     http://lists.digium.com/mailman/listinfo/asterisk-users
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20160211/459baa92/attachment.html>