PJSIP INVITE hanging at 100-Trying with UK Voip Provider

Asterisk Asterisk Support
1

Hi,

I have got very frustrated trying to get PJSIP to answer incoming calls from a UK VoIP provider Voipfone. They use a single IP and supply no authentication information on calls (unsurprisingly) and we have used them with chan_sip for years but would like to migrate to PJSIP for future support and to take advantage of some of the transport facilities etc.

Asterisk is a freshly compiled Certified 13.1 sat behind a router with ports 5065 forwarded as a SIP port and 30000-39999 forwarded as RTP range (matching the configuration in asterisk).

We have stripped the config and dialplan right down to basics to test, but calls come in, get a 100 Trying response and never progress to 200 status or hit the dialplan (I have tested that it is not dialplan by changing to a fubar context which causes the call to fail immediately), they just timeout and cancel. I have compared to previous chan_sip traces but do not have a valid PJSIP one to compare to and cannot see anything obvious (other than it not, y’know, working).

Any help or clues greatly appreciated!

/etc/asterisk/pjsip.conf:

[code]*** This Conf has been Sanitised to alias: ***
Public IPs, used in this log: wan1.our.domain=1.2.3.4 wan2.our.domain=5.6.7.8
Private IPs, subnets are show as 192.168.x.y, key local subnet is 192.168.2.y
Voipfone identifiers: aliased to 30000000, voipfone ids partially masked
Phone numbers masked to almost all 7s
*** Generated Fri Dec 11 10:38:00 GMT 2015 ***

[TRANSwan1]
type=transport
protocol=udp
bind=192.168.2.30:5065
local_net=192.168.2.0/23
external_media_address=1.2.3.4
external_signaling_address=1.2.3.4
[AUTHvoipfonePrimary]
type=auth
auth_type=userpass
password=111111
username=30000000200
[voipfonePrimary]
type=endpoint
aors=AORvoipfonePrimary
transport=TRANSwan1
outbound_auth=AUTHvoipfonePrimary
from_domain=wan1.our.domain
context=from-voipfone
disallow=all
allow=alaw
media_use_received_transport=yes
[AORvoipfonePrimary]
type=aor
contact=sip:195.189.173.27:5060
qualify_frequency=0
[IDvoipfone]
type=identify
endpoint=voipfonePrimary
match=195.189.172.1/23
[REGvoipfonePrimary]
type=registration
outbound_auth=AUTHvoipfonePrimary
server_uri=sip:30000000200@sip.voipfone.net
client_uri=sip:30000000200@wan1.our.domain:5065
contact_user=30000000200
auth_rejection_permanent=no
transport=TRANSwan1
retry_interval=60
expiration=300
[/code]

/var/log/asterisk/full (debug=5,verbose=5,pjsip logger on)

[code]*** This Log has been Sanitised to alias: ***
Public IPs, used in this log: wan1.our.domain=1.2.3.4 wan2.our.domain=5.6.7.8
Private IPs, subnets are show as 192.168.x.y, key local subnet is 192.168.2.y
Voipfone identifiers: aliased to 30000000, voipfone ids partially masked
Phone numbers masked to almost all 7s
*** Generated Wed Dec 9 18:34:15 GMT 2015 ***

[2015-12-09 17:36:38.3] DEBUG[6067] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=102 (rdata0x22ef668)
[2015-12-09 17:36:38.3] VERBOSE[6067] res_pjsip_logger.c: <— Received SIP request (954 bytes) from UDP:195.189.173.27:5060 —>
INVITE sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1 SIP/2.0
Via: SIP/2.0/UDP 195.189.173.27:5060;branch=z9hG4bK638b6901;rport
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1
Contact: sip:07777777789@195.189.173.27
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
CSeq: 102 INVITE
User-Agent: Voipfone Sip Network
Date: Wed, 09 Dec 2015 17:36:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Content-Type: application/sdp
Content-Length: 337

v=0
o=root 39459 39459 IN IP4 195.189.173.27
s=session
c=IN IP4 195.189.173.27
t=0 0
m=audio 55154 RTP/AVP 8 2 97 3 110 101
a=sendrecv
a=rtpmap:8 PCMA/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:3 GSM/8000
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=102 (rdata0x22556e8)
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username ‘07777777789’
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_endpoint_identifier_ip.c: Source address 195.189.173.27:5060 matches identify ‘IDvoipfone’
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint voipfonePrimary
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: tsx0x7f3468007 …Transaction created for Request msg INVITE/cseq=102 (rdata0x22556e8)
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: tsx0x7f3468007 .Incoming Request msg INVITE/cseq=102 (rdata0x22556e8) in state Null
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: tsx0x7f3468007 …State changed from Null to Trying, event=RX_MSG
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f3468007268 state changed to Trying
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e .UAS dialog created
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e .Module mod-invite added as dialog usage, data=0x7f346801bcd8
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e …Session count inc to 2 by mod-invite
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: inv0x7f346800e .UAS invite session created for dialog dlg0x7f346800ebf8
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e .Module Session Module added as dialog usage, data=(nil)
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e …Session count inc to 2 by Session Module
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Negotiating incoming SDP media stream ‘audio’ using audio SDP handler
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Using engine ‘asterisk’ for RTP instance ‘0x7f346800a278’
[2015-12-09 17:36:38.3] DEBUG[6062] res_rtp_asterisk.c: Allocated port 34220 for RTP instance ‘0x7f346800a278’
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: icess0x7f34680 ICE session created, comp_cnt=2, role is Unknown agent
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: Splitting ‘192.168.2.30’ into…
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: …host ‘192.168.2.30’ and port ‘’.
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: icess0x7f34680 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a8ca1e, addr=192.168.2.30:34220, base=192.168.2.30:34220, prio=0x7effffff (2130706431)
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: RTP instance ‘0x7f346800a278’ is setup and ready to go
[2015-12-09 17:36:38.3] DEBUG[6062] res_rtp_asterisk.c: Setup RTCP on RTP instance ‘0x7f346800a278’
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: Splitting ‘192.168.2.30’ into…
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: …host ‘192.168.2.30’ and port ‘’.
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: icess0x7f34680 Candidate 1 added: comp_id=2, type=host, foundation=Hc0a8ca1e, addr=192.168.2.30:34221, base=192.168.2.30:34221, prio=0x7efffffe (2130706430)
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: icess0x7f34680 Destroying ICE session 0x7f3468021058
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: stuse0x7f34680 STUN session 0x7f3468012298 destroy request, ref_cnt=4
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: stuse0x7f34680 STUN session 0x7f3468014a78 destroy request, ref_cnt=3
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: ice_session.c ICE session 0x7f3468021058 destroyed
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: stun_session.c STUN session 0x7f3468012298 destroyed
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: stun_session.c STUN session 0x7f3468014a78 destroyed
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 8 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 2 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 97 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 3 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 110 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Setting payload 101 (0x7f346800b668) based on m type on 0x7f3483df1580
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 2 (0x7f3468006778) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 3 (0x7f34680171d8) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 8 (0x7f346800b6e8) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 97 (0x7f346800b768) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 101 (0x7f346802add8) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] rtp_engine.c: Copying payload 110 (0x7f346802ad58) from 0x7f3483df1580 to 0x7f346800a440
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Media stream ‘audio’ handled by audio
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: endpoint .Response msg 100/INVITE/cseq=102 (tdta0x7f3468005200) created
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e .Initial answer Response msg 100/INVITE/cseq=102 (tdta0x7f3468005200)
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: inv0x7f346800e .Sending Response msg 100/INVITE/cseq=102 (tdta0x7f3468005200)
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e …Sending Response msg 100/INVITE/cseq=102 (tdta0x7f3468005200)
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: tsx0x7f3468007 …Sending Response msg 100/INVITE/cseq=102 (tdta0x7f3468005200) in state Trying
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:36:38.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:36:38.3] VERBOSE[6062] res_pjsip_logger.c: <— Transmitting SIP response (371 bytes) to UDP:195.189.173.27:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 195.189.173.27:5060;rport=5060;received=195.189.173.27;branch=z9hG4bK638b6901
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1
CSeq: 102 INVITE
Content-Length: 0

[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: tsx0x7f3468007 …State changed from Trying to Proceeding, event=TX_MSG
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f3468007268 state changed to Proceeding
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The state change pertains to the session with voipfonePrimary
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: There is no transaction involved in this state change
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The current inv state is INCOMING
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Source of transaction state change is TX_MSG
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Sending response
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The state change pertains to the session with voipfonePrimary
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The transaction involved in this state change is 0x7f3468007268
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The current transaction state is Proceeding
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The transaction state change event is TX_MSG
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: The current inv state is INCOMING
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Sending response
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[2015-12-09 17:36:38.3] DEBUG[6062] res_pjsip_session.c: Method is INVITE
[2015-12-09 17:36:38.3] DEBUG[6062] pjsip: dlg0x7f346800e Module NAT added as dialog usage, data=(nil)

<<>>

[2015-12-09 17:37:00.3] DEBUG[6067] pjsip: sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=102 (rdata0x22ef668)
[2015-12-09 17:37:00.3] VERBOSE[6067] res_pjsip_logger.c: <— Received SIP request (498 bytes) from UDP:195.189.173.27:5060 —>
CANCEL sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1 SIP/2.0
Via: SIP/2.0/UDP 195.189.173.27:5060;branch=z9hG4bK638b6901;rport
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1
Contact: sip:07777777789@195.189.173.27
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
CSeq: 102 CANCEL
User-Agent: Voipfone Sip Network
Content-Length: 0

[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg CANCEL/cseq=102 (rdata0x22556e8)
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e .Received Request msg CANCEL/cseq=102 (rdata0x22556e8)
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f346801b …Transaction created for Request msg CANCEL/cseq=102 (rdata0x22556e8)
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f346801b …Incoming Request msg CANCEL/cseq=102 (rdata0x22556e8) in state Null
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f346801b …State changed from Null to Trying, event=RX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f346801bf68 state changed to Trying
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The state change pertains to the session with voipfonePrimary
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction involved in this state change is 0x7f346801bf68
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current transaction state is Trying
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction state change event is RX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current inv state is INCOMING
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Received request
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Method is CANCEL
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: endpoint …Response msg 200/CANCEL/cseq=102 (tdta0x7f3468018f60) created
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Sending Response msg 200/CANCEL/cseq=102 (tdta0x7f3468018f60)
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f346801b …Sending Response msg 200/CANCEL/cseq=102 (tdta0x7f3468018f60) in state Trying
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:37:00.3] VERBOSE[6062] res_pjsip_logger.c: <— Transmitting SIP response (408 bytes) to UDP:195.189.173.27:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 195.189.173.27:5060;rport=5060;received=195.189.173.27;branch=z9hG4bK638b6901
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1;tag=80d4f907-97d9-4f60-aca9-e31e85c36335
CSeq: 102 CANCEL
Content-Length: 0

[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f346801b …State changed from Trying to Completed, event=TX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f346801bf68 state changed to Completed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The state change pertains to the session with voipfonePrimary
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction involved in this state change is 0x7f346801bf68
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current transaction state is Completed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction state change event is TX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current inv state is INCOMING
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Sending response
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Method is CANCEL, Response is 200 OK
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Sending Response msg 487/INVITE/cseq=102 (tdta0x7f3468005200)
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f3468007 …Sending Response msg 487/INVITE/cseq=102 (tdta0x7f3468005200) in state Proceeding
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:37:00.3] VERBOSE[6062] res_pjsip_logger.c: <— Transmitting SIP response (424 bytes) to UDP:195.189.173.27:5060 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 195.189.173.27:5060;rport=5060;received=195.189.173.27;branch=z9hG4bK638b6901
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1;tag=80d4f907-97d9-4f60-aca9-e31e85c36335
CSeq: 102 INVITE
Content-Length: 0

[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f3468007 …State changed from Proceeding to Completed, event=TX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f3468007268 state changed to Completed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The state change pertains to the session with voipfonePrimary
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: There is no transaction involved in this state change
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current inv state is DISCONNCTD
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Source of transaction state change is TX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Sending response
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Method is INVITE, Response is 487 Request Terminated
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Destroying SIP session with endpoint voipfonePrimary
[2015-12-09 17:37:00.3] DEBUG[6062] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7f346800a278’
[2015-12-09 17:37:00.3] DEBUG[6062] rtp_engine.c: Destroyed RTP instance ‘0x7f346800a278’
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Session count dec to 6 by Session Module
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Session count dec to 5 by mod-invite
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: inv_session 0x7f346801bcd8 has no ast session
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction involved in this state change is 0x7f3468007268
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current transaction state is Completed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction state change event is TX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current inv state is DISCONNCTD
[2015-12-09 17:37:00.3] DEBUG[6062] taskprocessor.c: destroying taskprocessor ‘8e62eeb2-cd3e-4da5-8c79-ee3862217338’
[2015-12-09 17:37:00.3] DEBUG[6067] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=102 (rdata0x22ef668)
[2015-12-09 17:37:00.3] VERBOSE[6067] res_pjsip_logger.c: <— Received SIP request (533 bytes) from UDP:195.189.173.27:5060 —>
ACK sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1 SIP/2.0
Via: SIP/2.0/UDP 195.189.173.27:5060;branch=z9hG4bK638b6901;rport
From: “Main” sip:07777777789@195.189.173.27;tag=VFaaaaaaaace8a35a8431a34d370b1
To: sip:30000000*200@1.2.3.4:5065;x-uid=aaaaaaaa-ff2c-4857-bc79-4b1dc52855c1;tag=80d4f907-97d9-4f60-aca9-e31e85c36335
Contact: sip:07777777789@195.189.173.27
Call-ID: VFaaaaaaaa93914b5830f1e55a826c3b@voipfone
CSeq: 102 ACK
User-Agent: Voipfone Sip Network
Content-Length: 0

[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=102 (rdata0x22556e8)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username ‘07777777789’
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: Splitting ‘195.189.173.27’ into…
[2015-12-09 17:37:00.3] DEBUG[6062] netsock2.c: …host ‘195.189.173.27’ and port ‘’.
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_endpoint_identifier_ip.c: Source address 195.189.173.27:5060 matches identify ‘IDvoipfone’
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint voipfonePrimary
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f3468007 .Incoming Request msg ACK/cseq=102 (rdata0x22556e8) in state Completed
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: tsx0x7f3468007 …State changed from Completed to Confirmed, event=RX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] pjsip: dlg0x7f346800e …Transaction tsx0x7f3468007268 state changed to Confirmed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: inv_session 0x7f346801bcd8 has no ast session
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f3468007268)
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction involved in this state change is 0x7f3468007268
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current transaction state is Confirmed
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The transaction state change event is RX_MSG
[2015-12-09 17:37:00.3] DEBUG[6062] res_pjsip_session.c: The current inv state is DISCONNCTD
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tsx0x7f3468007 Timeout timer event
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tsx0x7f3468007 .State changed from Confirmed to Terminated, event=TIMER
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: dlg0x7f346800e …Transaction tsx0x7f3468007268 state changed to Terminated
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: inv_session 0x7f346801bcd8 has no ast session
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: The transaction involved in this state change is 0x7f3468007268
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: The current transaction state is Terminated
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: The transaction state change event is TIMER
[2015-12-09 17:37:00.4] DEBUG[6067] res_pjsip_session.c: The current inv state is DISCONNCTD
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tsx0x7f3468007 Timeout timer event
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tsx0x7f3468007 .State changed from Terminated to Destroyed, event=TIMER
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tdta0x7f346800 …Destroying txdata Response msg 487/INVITE/cseq=102 (tdta0x7f3468005200)
[2015-12-09 17:37:00.4] DEBUG[6067] pjsip: tsx0x7f3468007 Transaction destroyed!
[2015-12-09 17:37:04.8] VERBOSE[6132] asterisk.c: Remote UNIX connection disconnected
[/code]

2

You won’t get beyond trying unless the dialplan does something that causes this. You don’t appear t have verbose logging on to show what the diaplan is doing, and you haven’t provided the dialplan.

3

Thanks David,

(sorry for the delay posting this: I tried to do it yesterday but the forum was messing me around).

That was my initial thought too, so I stripped out all complicated logic from the target context:

dialplan show | grep -A 5 \'from-voipfone\'
[ Context 'from-voipfone' created by 'pbx_ael' ]
  '_.' =>           1. Answer()                                   [pbx_ael]
                    2. NoOp(Grabbed Call)                         [pbx_ael]
                    3. Goto(bt-in,777799,1)                       [pbx_ael]

I also thought that it might not marry up to this context, hence I tried changing it to fubar-from-voipfone and the same trace would then throw errors.

Even with Verbose on 5 there is no output from the dialplan to follow, hence my impression that this was a PJSIP issue.

Could there be anything funny about AEL-generated contexts? I may try this later on to review.

Input and opinions (even theories about the moon landings at this stage) very welcome!

4

How did you compile and install PJSIP? If shared libraries aren’t used then each module will have a separate running PJSIP internally, which can cause all sorts of weird things to happen.

5

I have a bash script to download and compile (we don’t plan on doing it that often, but value the ability to rebuild in a VM):

(sudo-ing might be a bit inconsistent, it does normally get run as root but I know it shouldn’t :wink:)
PJSIP Section:

wget http://www.pjsip.org/release/2.2.1/pjproject-2.2.1.tar.bz2
        tar -xjf pjproject-2.2.1.tar.bz2
        rm -I pjproject-2.2.1.tar.bz2
        cd pjproject-2.2.1
        ./configure CFLAGS=-fPIC CXXFLAGS=-fPIC --enable-shared --prefix=/usr --disable-opencore-amr --disable-video --disable-resample --disable-sound --with-external-speex --with-external-srtp --with-external-gsm
        make dep
        make
        make install
        sudo cp /usr/lib/pkgconfig/libpjproject.pc /usr/lib64/pkgconfig/
        cd ..

and for Asterisk itself:

#Asterisk and associated sources id asterisk &>/dev/null || useradd asterisk abranch=certified-asterisk-13.1- wget http://downloads.asterisk.org/pub/telephony/certified-asterisk/${abranch}current.tar.gz tar -xzf ${abranch}current.tar.gz rm -I ${abranch}current.tar.gz wget http://downloads.asterisk.org/pub/telephony/libpri/libpri-1.4-current.tar.gz wget http://downloads.asterisk.org/pub/telephony/dahdi-linux-complete/dahdi-linux-complete-current.tar.gz tar -xzf libpri-1.4-current.tar.gz rm -I libpri-1.4-current.tar.gz tar -xzf dahdi-linux-complete-current.tar.gz rm -I dahdi-linux-complete-current.tar.gz cd ${abranch}* sudo contrib/scripts/install_prereq install cd ../libpri-1.4.* make sudo make install cd ../dahdi-linux-complete* make all sudo make install cd ../${abranch}* contrib/scripts/get_mp3_source.sh ./configure make menuselect.makeopts menuselect/menuselect --enable format_mp3 --disable app_disa --disable app_exec --disable app_flash --disable app_adsiprog --disable app_alarmreceiver --disable app_dahdiras --enable app_fax --disable app_getcpeid --disable app_ices --enable app_meetme --disable app_nbscat --disable app_osplookup --disable chan_mgcp --disable chan_phone --disable chan_skinny --disable chan_unistim --disable chan_vpb --disable pbx_realtime --disable res_adsi --disable res_calendar --disable res_realtime --disable res_smdi --enable aelparse --enable conf2ael --enable streamplayer --disable CORE-SOUNDS-EN-GSM --enable CORE-SOUNDS-EN_GB-GSM --enable EXTRA-SOUNDS-EN_GB-GSM menuselect.makeopts make menuselect #note: it may have been customised further (modules etc wise) here make make install ldconfig make progdocs cp contrib/init.d/rc.redhat.asterisk /etc/init.d/asterisk read -p ready

Given that the menuselect may have been changed (it goes into the gui after the automated) the output of module show | grep pjsip is:
[ul]func_pjsip_endpoint.so Get information about a PJSIP endpoint 0 Running core
res_pjsip.so Basic SIP resource 29 Running core
res_pjsip_acl.so PJSIP ACL Resource 0 Running core
res_pjsip_authenticator_digest.so PJSIP authentication resource 0 Running core
res_pjsip_caller_id.so PJSIP Caller ID Support 0 Running core
res_pjsip_dialog_info_body_generator.so PJSIP Extension State Dialog Info+XML Pr 0 Running core
res_pjsip_diversion.so PJSIP Add Diversion Header Support 0 Running core
res_pjsip_dtmf_info.so PJSIP DTMF INFO Support 0 Running core
res_pjsip_endpoint_identifier_anonymous.so PJSIP Anonymous endpoint identifier 0 Running core
res_pjsip_endpoint_identifier_ip.so PJSIP IP endpoint identifier 0 Running core
res_pjsip_endpoint_identifier_user.so PJSIP username endpoint identifier 0 Running core
res_pjsip_exten_state.so PJSIP Extension State Notifications 0 Running core
res_pjsip_header_funcs.so PJSIP Header Functions 0 Running core
res_pjsip_keepalive.so PJSIP Stateful Connection Keepalive Supp 1 Running core
res_pjsip_log_forwarder.so PJSIP Log Forwarder 0 Running core
res_pjsip_logger.so PJSIP Packet Logger 0 Running core
res_pjsip_messaging.so PJSIP Messaging Support 0 Running core
res_pjsip_multihomed.so PJSIP Multihomed Routing Support 0 Running core
res_pjsip_mwi.so PJSIP MWI resource 0 Running core
res_pjsip_mwi_body_generator.so PJSIP MWI resource 0 Running core
res_pjsip_nat.so PJSIP NAT Support 0 Running core
res_pjsip_notify.so CLI/AMI PJSIP NOTIFY Support 0 Running core
res_pjsip_one_touch_record_info.so PJSIP INFO One Touch Recording Support 0 Running core
res_pjsip_outbound_authenticator_digest.so PJSIP authentication resource 0 Running core
res_pjsip_outbound_publish.so PJSIP Outbound Publish Support 2 Running unknown
res_pjsip_outbound_registration.so PJSIP Outbound Registration Support 0 Running core
res_pjsip_path.so PJSIP Path Header Support 0 Running core
res_pjsip_pidf_body_generator.so PJSIP Extension State PIDF Provider 0 Running core
res_pjsip_pidf_digium_body_supplement.so PJSIP PIDF Digium presence supplement 0 Running core
res_pjsip_pidf_eyebeam_body_supplement.so PJSIP PIDF Eyebeam supplement 0 Running core
res_pjsip_publish_asterisk.so PJSIP Asterisk Event PUBLISH Support 0 Running unknown
res_pjsip_pubsub.so PJSIP event resource 5 Running core
res_pjsip_refer.so PJSIP Blind and Attended Transfer Suppor 0 Running core
res_pjsip_registrar.so PJSIP Registrar Support 0 Running core
res_pjsip_registrar_expire.so PJSIP Contact Auto-Expiration 0 Running core
res_pjsip_rfc3326.so PJSIP RFC3326 Support 0 Running core
res_pjsip_sdp_rtp.so PJSIP SDP RTP/AVP stream handler 0 Running core
res_pjsip_send_to_voicemail.so PJSIP REFER Send to Voicemail Support 0 Running core
res_pjsip_session.so PJSIP Session resource 18 Running core
res_pjsip_t38.so PJSIP T.38 UDPTL Support 0 Running core
res_pjsip_transport_websocket.so PJSIP WebSocket Transport Support 0 Running core
res_pjsip_xpidf_body_generator.so PJSIP Extension State PIDF Provider 0 Running core
[/ul]
Is there anything else I can do to diagnose the sort of situation you are discussing?

6

What is the output of “ldd /usr/lib/asterisk/modules/chan_pjsip.so”?

7

ldd /usr/lib/asterisk/modules/chan_pjsip.so:

linux-vdso.so.1 => (0x00007fffca9b4000) libpjsua2.so.2 => /usr/lib/libpjsua2.so.2 (0x00007f134a3f4000) libstdc++.so.6 => /usr/lib64/libstdc++.so.6 (0x00007f134a0ee000) libpjsua.so.2 => /usr/lib/libpjsua.so.2 (0x00007f1349e2c000) libpjsip-ua.so.2 => /usr/lib/libpjsip-ua.so.2 (0x00007f1349c0e000) libpjsip-simple.so.2 => /usr/lib/libpjsip-simple.so.2 (0x00007f13499f7000) libpjsip.so.2 => /usr/lib/libpjsip.so.2 (0x00007f134979b000) libpjmedia-codec.so.2 => /usr/lib/libpjmedia-codec.so.2 (0x00007f134958a000) libpjmedia-videodev.so.2 => /usr/lib/libpjmedia-videodev.so.2 (0x00007f1349389000) libpjmedia-audiodev.so.2 => /usr/lib/libpjmedia-audiodev.so.2 (0x00007f1349182000) libpjmedia.so.2 => /usr/lib/libpjmedia.so.2 (0x00007f1348f06000) libpjnath.so.2 => /usr/lib/libpjnath.so.2 (0x00007f1348cd6000) libpjlib-util.so.2 => /usr/lib/libpjlib-util.so.2 (0x00007f1348aa5000) libsrtp.so.0 => /usr/lib64/libsrtp.so.0 (0x00007f134888d000) libgsm.so.1 => /usr/lib64/libgsm.so.1 (0x00007f1348682000) libspeex.so.1 => /usr/lib64/libspeex.so.1 (0x00007f1348468000) libspeexdsp.so.1 => /usr/lib64/libspeexdsp.so.1 (0x00007f1348255000) libpj.so.2 => /usr/lib/libpj.so.2 (0x00007f1348022000) libuuid.so.1 => /lib64/libuuid.so.1 (0x00007f1347e1d000) libm.so.6 => /lib64/libm.so.6 (0x00007f1347b99000) librt.so.1 => /lib64/librt.so.1 (0x00007f1347991000) libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f1347773000) libcrypto.so.10 => /usr/lib64/libcrypto.so.10 (0x00007f1347390000) libssl.so.10 => /usr/lib64/libssl.so.10 (0x00007f1347124000) libc.so.6 => /lib64/libc.so.6 (0x00007f1346d8f000) libilbccodec.so.2 => /usr/lib/libilbccodec.so.2 (0x00007f1346b7d000) libg7221codec.so.2 => /usr/lib/libg7221codec.so.2 (0x00007f134696b000) libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x00007f1346754000) /lib64/ld-linux-x86-64.so.2 (0x00007f134a8ad000) libdl.so.2 => /lib64/libdl.so.2 (0x00007f134654f000) libz.so.1 => /lib64/libz.so.1 (0x00007f1346339000) libgssapi_krb5.so.2 => /lib64/libgssapi_krb5.so.2 (0x00007f13460f4000) libkrb5.so.3 => /lib64/libkrb5.so.3 (0x00007f1345e0d000) libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00007f1345c09000) libk5crypto.so.3 => /lib64/libk5crypto.so.3 (0x00007f13459dc000) libkrb5support.so.0 => /lib64/libkrb5support.so.0 (0x00007f13457d1000) libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00007f13455cd000) libresolv.so.2 => /lib64/libresolv.so.2 (0x00007f13453b3000) libselinux.so.1 => /lib64/libselinux.so.1 (0x00007f1345194000)

Thanks Joshua, Happy New Year

8

Further piece of information from a couple of people on the provider’s forums (which generally are better known for their tumbleweed than anything else!)

A user has reported the same issue, which he eventually traced to failing to menuselect chan_pjsip (i.e. not actually compiling it). As best I can tell that is not my direct issue, but I assume this fits into your line of enquiry on the compilation and the PJSIP linkage. Feeling out of my depth now!

9

Your build looks right (in that stuff is against shared libraries) so I’m not quite sure what else could be causing this… it’s either environment specific OR something in the SIP signaling but I can’t see what. I’d suggest creating an issue on the issue tracker[1] with the details. We should be able to construct a SIPp scenario using the signaling to determine if that is the reason.

[1] issues.asterisk.org/jira