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.
[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:77777...@stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a To: <sip:+7980xxxx...@stc.euroset.ru>;tag=B955C4E4-606476-16E1127B Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7 CSeq: 3711 INVITE Contact: <sip:signode-606476-16E1127B@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:77777...@stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a To: <sip:+7980xxxx...@stc.euroset.ru>;tag=B955C4E4-606476-16E1127B Call-ID: 5ac4642d-007b-4e29-908a-1b06417148c7 CSeq: 3711 INVITE Contact: <sip:signode-606476-16E1127B@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@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:77777...@stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a To: <sip:+7980xxxx...@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@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:77777...@stc.euroset.ru>;tag=0ea59f7e-817c-48a1-8e44-6e896322609a To: <sip:+7980xxxx...@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:357...@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
-- _____________________________________________________________________ -- 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
