Realtime PJSIP trouble / "Failed to create outgoing session"

Hello,

I have the following setup :

  • asterisk version 15.7.2 on debian 9, compiled from source
  • PJSIP realtime with ODBC - the DB tables were created with alembic

Simple dialplan :
[default]
;switch => Realtime/@extensions commented out for testing
exten => 1101,1,Dial(PJSIP/101)
exten => 1102,1,Dial(PJSIP/102)

sourcery.conf :
[test_sorcery_section]
test=memory

[test_sorcery_cache]
test/cache=test
test=memory

[res_pjsip]
endpoint=realtime,ps_endpoints
auth=realtime,ps_auths
aor=realtime,ps_aors
domain_alias=realtime,ps_domain_aliases
contact=realtime,ps_contacts

[res_pjsip_endpoint_identifier_ip]
identify=realtime,ps_endpoint_id_ips

[res_pjsip_outbound_publish]
outbound-publish=config,pjsip.conf,criteria=type=outbound-publish

[res_pjsip_outbound_registration]
registration=config,pjsip.conf,criteria=type=registration

extconfig.conf :
[settings]
ps_endpoints => odbc,asterisk
ps_auths => odbc,asterisk
ps_aors => odbc,asterisk
ps_domain_aliases => odbc,asterisk
ps_endpoint_id_ips => odbc,asterisk
ps_contacts => odbc,asterisk

I successfully regstier a sip phone (extension 102):

Connected to Asterisk 15.7.2 currently running on vmi214442 (pid = 14242)
vmi214442CLI> core set debug 9
Core debug is still 9.
vmi214442
CLI> core set verbose 9
Console verbose was OFF and is now 9.
– Added contact ‘sip:102@176.12.16.218:46212;ob’ to AOR ‘102’ with expiration of 900 seconds
== Endpoint 102 is now Reachable
– Contact 102/sip:102@176.12.16.218:46212;ob is now Reachable. RTT: 86.199 msec
vmi214442CLI>
vmi214442
CLI> pjsip show contacts

Contact: <Aor/ContactUri…> <Hash…> <RTT(ms)…>

Contact: 102/sip:102@176.12.16.218:46212;ob 94e44a37a9 Avail 153.740

Objects found: 1

So far, so good. But then if I say :
vmi214442*CLI> pjsip show endpoints

Endpoint: <Endpoint/CID…> <State…> <Channels.>
I/OAuth: <AuthId/UserName…>
Aor: <Aor…>
Contact: <Aor/ContactUri…> <Hash…> <RTT(ms)…>
Transport: <TransportId…> <BindAddress…>
Identify: <Identify/Endpoint…>
Match: <criteria…>
Channel: <ChannelId…> <State…> <Time…>
Exten: <DialedExten…> CLCID: <ConnectedLineCID…>

Endpoint: 101 Unavailable 0 of inf
InAuth: 101/101
Aor: 101 1
Transport: transport-wss wss 0 0 0.0.0.0:5060

Endpoint: 102 Not in use 0 of inf
InAuth: 102/102
Aor: 102 1
Transport: transport-udp udp 0 0 0.0.0.0:5060

Objects found: 2

== Contact 102/sip:102@176.12.16.218:46212;ob has been deleted
== Endpoint 102 is now Unreachable

My extension 102 gets immediately unregistered?!?
The same thing happens if I try to send a call there :

vmi214442*CLI> pjsip show contacts

Contact: <Aor/ContactUri…> <Hash…> <RTT(ms)…>

Contact: 101/sips:101@176.12.16.218:57464;transport=ws; fb5d76d424 Avail 65.881
Contact: 102/sip:102@176.12.16.218:46212;ob 94e44a37a9 Avail 318.445

Objects found: 2

== Contact 101/sips:101@176.12.16.218:57464;transport=ws;rtcweb-breaker=no has been deleted
== Endpoint 101 is now Unreachable
– Added contact ‘sips:101@176.12.16.218:57464;transport=ws;rtcweb-breaker=no’ to AOR ‘101’ with expiration of 200 seconds
== Endpoint 101 is now Reachable
– Contact 101/sips:101@176.12.16.218:57464;transport=ws;rtcweb-breaker=no is now Reachable. RTT: 61.815 msec
== Setting global variable ‘SIPDOMAIN’ to ‘asterisk.org
– Executing [1102@default:1] Dial(“PJSIP/101-00000000”, “PJSIP/102”) in new stack
[Jun 6 14:52:48] ERROR[14367]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint ‘102’
[Jun 6 14:52:48] WARNING[14431][C-00000001]: app_dial.c:2512 dial_exec_full: Unable to create channel of type ‘PJSIP’ (cause 3 - No route to destination)
== Everyone is busy/congested at this time (1:0/0/1)
== Contact 102/sip:102@176.12.16.218:46212;ob has been deleted
– Auto fallthrough, channel ‘PJSIP/101-00000000’ status is ‘CHANUNAVAIL’
== Endpoint 102 is now Unreachable

Happens to all endpoints, not only 102.

Please guide me, am i doing something wrong? If i’m not mistaken the fail happens in res/res_pjsip_session.c, function ast_sip_session_create_outgoing - fails to find URI to send the call to…

Thank you in advace for your help !

It is saying no route to desination, which sounds like a nework level problem in the OS. My guess is htat, if you had shown us the actual REGISTERs, they would have come from a different address from the one in the Contact header.

OK, here is it. Summary cause I can’t attach a file :
Register from : UDP:176.12.16.218:46212
address in pjsip show contacts : sip:102@176.12.16.218:46212;ob
The fact is that it even does not try to send the invite…

Log follows :

<--- Received SIP request (568 bytes) from UDP:176.12.16.218:46212 --->
REGISTER sip:wrtc.bgtel.bg SIP/2.0
Via: SIP/2.0/UDP 176.12.16.218:46212;rport;branch=z9hG4bKPjJ4e33nW3-E15pBIhp-KNP8RFlRXzJYTP
Route: <sip:wrtc.bgtel.bg;transport=udp;lr>
Max-Forwards: 70
From: <sip:102@wrtc.bgtel.bg>;tag=89TCQmuGCsKfG5BB6W.sVbT2f21jDzng
To: <sip:102@wrtc.bgtel.bg>
Call-ID: 6n9qfcoftZTpt9vBifZ5.mM-dn5Q2qJQ
CSeq: 123 REGISTER
User-Agent: CSipSimple_ali_n-28/r2457
Contact: <sip:102@176.12.16.218:46212;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


<--- Transmitting SIP response (551 bytes) to UDP:176.12.16.218:46212 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 176.12.16.218:46212;rport=46212;received=176.12.16.218;branch=z9hG4bKPjJ4e33nW3-E15pBIhp-KNP8RFlRXzJYTP
Call-ID: 6n9qfcoftZTpt9vBifZ5.mM-dn5Q2qJQ
From: <sip:102@wrtc.bgtel.bg>;tag=89TCQmuGCsKfG5BB6W.sVbT2f21jDzng
To: <sip:102@wrtc.bgtel.bg>;tag=z9hG4bKPjJ4e33nW3-E15pBIhp-KNP8RFlRXzJYTP
CSeq: 123 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1559828512/9c010bc1ceb956663f43cc52b5b8f2a7",opaque="1cc3f47c667a3cd6",algorithm=md5,qop="auth"
Server: Asterisk PBX 15.7.2
Content-Length:  0


<--- Received SIP request (855 bytes) from UDP:176.12.16.218:46212 --->
REGISTER sip:wrtc.bgtel.bg SIP/2.0
Via: SIP/2.0/UDP 176.12.16.218:46212;rport;branch=z9hG4bKPjTwBs0JuVvGWXYC1whK1WZwnn5LAv6suO
Route: <sip:wrtc.bgtel.bg;transport=udp;lr>
Max-Forwards: 70
From: <sip:102@wrtc.bgtel.bg>;tag=89TCQmuGCsKfG5BB6W.sVbT2f21jDzng
To: <sip:102@wrtc.bgtel.bg>
Call-ID: 6n9qfcoftZTpt9vBifZ5.mM-dn5Q2qJQ
CSeq: 124 REGISTER
User-Agent: CSipSimple_ali_n-28/r2457
Contact: <sip:102@176.12.16.218:46212;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="102", realm="asterisk", nonce="1559828512/9c010bc1ceb956663f43cc52b5b8f2a7", uri="sip:wrtc.bgtel.bg", response="4c15b5076142ddeaeda97cab683445a5", algorithm=md5, cnonce="26Tw4gbzdyqqNGShuZVrESHiKaCDgBZ6", opaque="42ce852216b66449", qop=auth, nc=00000001
Content-Length:  0


    -- Added contact 'sip:102@176.12.16.218:46212;ob' to AOR '102' with expiration of 900 seconds
<--- Transmitting SIP response (501 bytes) to UDP:176.12.16.218:46212 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 176.12.16.218:46212;rport=46212;received=176.12.16.218;branch=z9hG4bKPjTwBs0JuVvGWXYC1whK1WZwnn5LAv6suO
Call-ID: 6n9qfcoftZTpt9vBifZ5.mM-dn5Q2qJQ
From: <sip:102@wrtc.bgtel.bg>;tag=89TCQmuGCsKfG5BB6W.sVbT2f21jDzng
To: <sip:102@wrtc.bgtel.bg>;tag=z9hG4bKPjTwBs0JuVvGWXYC1whK1WZwnn5LAv6suO
CSeq: 124 REGISTER
Date: Thu, 06 Jun 2019 13:41:52 GMT
Contact: <sip:102@176.12.16.218:46212;ob>;expires=899
Expires: 900
Server: Asterisk PBX 15.7.2
Content-Length:  0

...

  == Endpoint 102 is now Reachable
    -- Contact 102/sip:102@176.12.16.218:46212;ob is now Reachable.  RTT: 107.759 msec

vmi214442*CLI> pjsip show contacts

  Contact:  <Aor/ContactUri..............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

  Contact:  101/sips:101@176.12.16.218:58448;transport=ws; eb17f306df Avail        63.587
  Contact:  102/sip:102@176.12.16.218:46212;ob             94e44a37a9 Avail       107.759

Objects found: 2

<--- Transmitting SIP request (431 bytes) to UDP:176.12.16.218:46212 --->
OPTIONS sip:102@176.12.16.218:46212;ob SIP/2.0
Via: SIP/2.0/UDP 207.180.224.10:5060;rport;branch=z9hG4bKPj5c49ef41-e7a5-4a72-bdd3-622302b828aa
From: <sip:102@207.180.224.10>;tag=d30ee158-12c9-49f6-bc84-bf1793c7c29c
To: <sip:102@176.12.16.218;ob>
Contact: <sip:102@207.180.224.10:5060>
Call-ID: 33536115-beee-402b-acbe-0b29e11df6c0
CSeq: 44577 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 15.7.2
Content-Length:  0


<--- Received SIP response (1113 bytes) from UDP:176.12.16.218:46212 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.180.224.10:5060;rport=5060;received=207.180.224.10;branch=z9hG4bKPj5c49ef41-e7a5-4a72-bdd3-622302b828aa
Call-ID: 33536115-beee-402b-acbe-0b29e11df6c0
From: <sip:102@207.180.224.10>;tag=d30ee158-12c9-49f6-bc84-bf1793c7c29c
To: <sip:102@176.12.16.218;ob>;tag=z9hG4bKPj5c49ef41-e7a5-4a72-bdd3-622302b828aa
CSeq: 44577 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: CSipSimple_ali_n-28/r2457
Content-Type: application/sdp
Content-Length:   280

v=0
o=- 3768817320 3768817320 IN IP4 10.0.0.162
s=pjmedia
t=0 0
m=audio 4000 RTP/AVP 99 0 8 101
c=IN IP4 10.0.0.162
a=sendrecv
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

<--- Transmitting SIP request (431 bytes) to UDP:176.12.16.218:46212 --->
OPTIONS sip:102@176.12.16.218:46212;ob SIP/2.0
Via: SIP/2.0/UDP 207.180.224.10:5060;rport;branch=z9hG4bKPj5a2efbd1-fa56-4e00-ad1e-cf94ea901493
From: <sip:102@207.180.224.10>;tag=2a3f2292-45d7-4c1b-9f6d-ba4767d54a6b
To: <sip:102@176.12.16.218;ob>
Contact: <sip:102@207.180.224.10:5060>
Call-ID: b9e2aded-ca67-4763-bbab-fc38de61d690
CSeq: 34377 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 15.7.2
Content-Length:  0


<--- Received SIP response (1113 bytes) from UDP:176.12.16.218:46212 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.180.224.10:5060;rport=5060;received=207.180.224.10;branch=z9hG4bKPj5a2efbd1-fa56-4e00-ad1e-cf94ea901493
Call-ID: b9e2aded-ca67-4763-bbab-fc38de61d690
From: <sip:102@207.180.224.10>;tag=2a3f2292-45d7-4c1b-9f6d-ba4767d54a6b
To: <sip:102@176.12.16.218;ob>;tag=z9hG4bKPj5a2efbd1-fa56-4e00-ad1e-cf94ea901493
CSeq: 34377 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: CSipSimple_ali_n-28/r2457
Content-Type: application/sdp
Content-Length:   280

v=0
o=- 3768817330 3768817330 IN IP4 10.0.0.162
s=pjmedia
t=0 0
m=audio 4000 RTP/AVP 99 0 8 101
c=IN IP4 10.0.0.162
a=sendrecv
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

vmi214442*CLI> 
vmi214442*CLI> 
vmi214442*CLI> 
vmi214442*CLI> call here :
No such command 'call here :' (type 'core show help call here' for other possible commands)
vmi214442*CLI> 

<--- Received SIP request (2081 bytes) from WSS:176.12.16.218:58448 --->
INVITE sip:1102@asterisk.org SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKmNLARwaHkbENLBFhbIXMuFJz0QUsKaBS;rport
From: "test"<sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>
Contact: "test"<sips:101@df7jal23ls0d.invalid;rtcweb-breaker=no;click2call=no;transport=wss>;+g.oma.sip-im;language="en,fr"
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
CSeq: 29857 INVITE
Content-Type: application/sdp
Content-Length: 1512
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 sipML5-v1.2016.03.04
Organization: Doubango Telecom

v=0
o=mozilla...THIS_IS_SDPARTA-67.0 2418193502161601500 0 IN IP4 127.0.0.1
s=Doubango Telecom - firefox
t=0 0
a=sendrecv
a=fingerprint:sha-256 73:44:F6:F4:16:8F:8C:76:92:6B:89:65:EA:68:2F:B5:A0:E8:DB:3E:4E:3C:23:AF:8A:9F:97:45:47:C1:6B:C2
a=group:BUNDLE 0
a=ice-options:trickle
a=msid-semantic:WMS *
m=audio 53693 UDP/TLS/RTP/SAVPF 109 9 0 8 101
c=IN IP4 176.12.16.218
a=candidate:0 1 UDP 2122252543 10.0.0.167 53693 typ host
a=candidate:5 1 TCP 2105524479 10.0.0.167 9 typ host tcptype active
a=candidate:0 2 UDP 2122252542 10.0.0.167 33475 typ host
a=candidate:5 2 TCP 2105524478 10.0.0.167 9 typ host tcptype active
a=candidate:2 1 UDP 1686052607 176.12.16.218 53693 typ srflx raddr 10.0.0.167 rport 53693
a=candidate:2 2 UDP 1686052606 176.12.16.218 33475 typ srflx raddr 10.0.0.167 rport 33475
a=sendrecv
a=end-of-candidates
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2/recvonly urn:ietf:params:rtp-hdrext:csrc-audio-level
a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid
a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1
a=fmtp:101 0-15
a=ice-pwd:17e0e0a85c3a7abe1f9920db1ac5b5bd
a=ice-ufrag:1cbf0051
a=mid:0
a=msid:{24e05874-eb5b-4697-92fe-2d1737216675} {54bc3c3a-a2b4-4b5e-ba97-0ac8ab1372db}
a=rtcp:33475 IN IP4 176.12.16.218
a=rtcp-mux
a=rtpmap:109 opus/48000/2
a=rtpmap:9 G722/8000/1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=setup:actpass
a=ssrc:367690960 cname:{036d1371-c533-4abe-8fd2-8e3ac86a7b96}

<--- Transmitting SIP response (547 bytes) to WSS:176.12.16.218:58448 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/WSS df7jal23ls0d.invalid;rport=58448;received=176.12.16.218;branch=z9hG4bKmNLARwaHkbENLBFhbIXMuFJz0QUsKaBS
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
From: "test" <sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>;tag=z9hG4bKmNLARwaHkbENLBFhbIXMuFJz0QUsKaBS
CSeq: 29857 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1559828543/addc0a4a5b1eae668de588776982a920",opaque="597721ea67b01a43",algorithm=md5,qop="auth"
Server: Asterisk PBX 15.7.2
Content-Length:  0


<--- Received SIP request (365 bytes) from WSS:176.12.16.218:58448 --->
ACK sip:1102@asterisk.org SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKmNLARwaHkbENLBFhbIXMuFJz0QUsKaBS;rport
From: "test"<sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>;tag=z9hG4bKmNLARwaHkbENLBFhbIXMuFJz0QUsKaBS
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
CSeq: 29857 ACK
Content-Length: 0
Max-Forwards: 70


<--- Received SIP request (2363 bytes) from WSS:176.12.16.218:58448 --->
INVITE sip:1102@asterisk.org SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKJXbhkfVAuEJIsNpA4ynQvylKp8WJ7Sis;rport
From: "test"<sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>
Contact: "test"<sips:101@df7jal23ls0d.invalid;rtcweb-breaker=no;click2call=no;transport=wss>;+g.oma.sip-im;language="en,fr"
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
CSeq: 29858 INVITE
Content-Type: application/sdp
Content-Length: 1512
Max-Forwards: 70
Authorization: Digest username="101",realm="asterisk",nonce="1559828543/addc0a4a5b1eae668de588776982a920",uri="sip:1102@asterisk.org",response="9e60385cd75464b25b19a42f7994f2d7",algorithm=md5,cnonce="81dc5088b8afb88785756d6c4f4512ee",opaque="597721ea67b01a43",qop=auth,nc=00000001
User-Agent: IM-client/OMA1.0 sipML5-v1.2016.03.04
Organization: Doubango Telecom

v=0
o=mozilla...THIS_IS_SDPARTA-67.0 2418193502161601500 0 IN IP4 127.0.0.1
s=Doubango Telecom - firefox
t=0 0
a=sendrecv
a=fingerprint:sha-256 73:44:F6:F4:16:8F:8C:76:92:6B:89:65:EA:68:2F:B5:A0:E8:DB:3E:4E:3C:23:AF:8A:9F:97:45:47:C1:6B:C2
a=group:BUNDLE 0
a=ice-options:trickle
a=msid-semantic:WMS *
m=audio 53693 UDP/TLS/RTP/SAVPF 109 9 0 8 101
c=IN IP4 176.12.16.218
a=candidate:0 1 UDP 2122252543 10.0.0.167 53693 typ host
a=candidate:5 1 TCP 2105524479 10.0.0.167 9 typ host tcptype active
a=candidate:0 2 UDP 2122252542 10.0.0.167 33475 typ host
a=candidate:5 2 TCP 2105524478 10.0.0.167 9 typ host tcptype active
a=candidate:2 1 UDP 1686052607 176.12.16.218 53693 typ srflx raddr 10.0.0.167 rport 53693
a=candidate:2 2 UDP 1686052606 176.12.16.218 33475 typ srflx raddr 10.0.0.167 rport 33475
a=sendrecv
a=end-of-candidates
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2/recvonly urn:ietf:params:rtp-hdrext:csrc-audio-level
a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid
a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1
a=fmtp:101 0-15
a=ice-pwd:17e0e0a85c3a7abe1f9920db1ac5b5bd
a=ice-ufrag:1cbf0051
a=mid:0
a=msid:{24e05874-eb5b-4697-92fe-2d1737216675} {54bc3c3a-a2b4-4b5e-ba97-0ac8ab1372db}
a=rtcp:33475 IN IP4 176.12.16.218
a=rtcp-mux
a=rtpmap:109 opus/48000/2
a=rtpmap:9 G722/8000/1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=setup:actpass
a=ssrc:367690960 cname:{036d1371-c533-4abe-8fd2-8e3ac86a7b96}

  == Setting global variable 'SIPDOMAIN' to 'asterisk.org'
<--- Transmitting SIP response (351 bytes) to WSS:176.12.16.218:58448 --->
SIP/2.0 100 Trying
Via: SIP/2.0/WSS df7jal23ls0d.invalid;rport=58448;received=176.12.16.218;branch=z9hG4bKJXbhkfVAuEJIsNpA4ynQvylKp8WJ7Sis
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
From: "test" <sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>
CSeq: 29858 INVITE
Server: Asterisk PBX 15.7.2
Content-Length:  0


    -- Executing [1102@default:1] Dial("PJSIP/101-00000001", "PJSIP/102") in new stack
[Jun  6 15:42:23] ERROR[14687]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint '102'
[Jun  6 15:42:23] WARNING[14833][C-00000002]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
  == Everyone is busy/congested at this time (1:0/0/1)
    -- Auto fallthrough, channel 'PJSIP/101-00000001' status is 'CHANUNAVAIL'
  == Contact 102/sip:102@176.12.16.218:46212;ob has been deleted
  == Endpoint 102 is now Unreachable
<--- Transmitting SIP response (429 bytes) to WSS:176.12.16.218:58448 --->
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/WSS df7jal23ls0d.invalid;rport=58448;received=176.12.16.218;branch=z9hG4bKJXbhkfVAuEJIsNpA4ynQvylKp8WJ7Sis
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
From: "test" <sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>;tag=76198bf1-3d0e-4285-af11-5492da017ee9
CSeq: 29858 INVITE
Server: Asterisk PBX 15.7.2
Reason: Q.850;cause=34
Content-Length:  0


<--- Received SIP request (362 bytes) from WSS:176.12.16.218:58448 --->
ACK sip:1102@asterisk.org SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKJXbhkfVAuEJIsNpA4ynQvylKp8WJ7Sis;rport
From: "test"<sip:101@wrtc.bgtel.bg>;tag=yru9NokWbrRUUrrnLyhJ
To: <sip:1102@asterisk.org>;tag=76198bf1-3d0e-4285-af11-5492da017ee9
Call-ID: 962b8d80-fc62-e724-7597-381bb086d9db
CSeq: 29858 ACK
Content-Length: 0
Max-Forwards: 70


vmi214442*CLI> pjsip show contacts

  Contact:  <Aor/ContactUri..............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

  Contact:  101/sips:101@176.12.16.218:58448;transport=ws; eb17f306df Avail        71.086

Objects found: 1

endpoint get Unreachable you need to verify why, this is most of the time related to networking issue

Without actually checking hte code, I still think that the diagnostic is the underlying OS one, and that this is a router issue not an Asterisk one.

Gentleman,

the endpoints get unreachable exactly at the moment i execute “pjsip show endpoints”!
I can not stress how many times I tried varying my

  • waiting time before executing “pjsip show endpoints”
  • trying with different endpoints
  • trying different transport (UDP or websocket)
  • and different IP addresses (public and private behind nat)
  • changing various mostly nat-related endpoint settings like described here : https://wiki.asterisk.org/wiki/display/AST/Configuring+res_pjsip+to+work+through+NAT
  • restarting asterisk, and the server itself
  • trying with different sip clients

Again, it happens at the moment I press enter and show endpoints gets executed. Yes, the same thing happens when i try a call there, but it is not a networking issue!
I must have done something wrong in my config, I don’t really believe this to be a bug, it couldn’t be …

So any suggestions what should I try next or what debug should I gather - please tell me!

Indeed, that’s what I want to know, why it gets unreachable. But a networking issue it is not (at least this time).

Looking at the actual code, it would seem that Asterisk overloads this error and it is not (necessary) the underlying OS error, but rather one involving a failure in ast_sip_session_create_outgoing(). That calls a lot of lower level routines, all of which could fail, and I would have to go through all of them to work out which ones don’t produce an error messages before failing the call.

Hi @david551, thank you.

I’m not sure if this helps, but I will provide it.
I have some log added, here is 101 trying to call 102 :

 vmi214442*CLI> 
    -- Attempted to remove non-existent contact 'sip:102@176.12.16.218:37779;ob' from AOR '102' by request
    -- Added contact 'sip:102@176.12.16.218:37779;ob' to AOR '102' with expiration of 900 seconds
  == Endpoint 102 is now Reachable
    -- Contact 102/sip:102@176.12.16.218:37779;ob is now Reachable.  RTT: 80.063 msec
  == WebSocket connection from '176.12.16.218:43906' for protocol 'sip' accepted using version '13'
    -- Added contact 'sips:101@176.12.16.218:43906;transport=ws;rtcweb-breaker=no' to AOR '101' with expiration of 200 seconds
  == Endpoint 101 is now Reachable
    -- Contact 101/sips:101@176.12.16.218:43906;transport=ws;rtcweb-breaker=no is now Reachable.  RTT: 120.376 msec
vmi214442*CLI> 
vmi214442*CLI> 
vmi214442*CLI> 
vmi214442*CLI> 
vmi214442*CLI> 
  == Setting global variable 'SIPDOMAIN' to 'asterisk.org'
    -- Executing [1102@default:1] Dial("PJSIP/101-00000000", "PJSIP/102") in new stack
[Jun  7 12:59:07] ERROR[24524]: res_pjsip_session.c:2468 ast_sip_session_create_outgoing: Temp debug, location is (null), uri is (null)
[Jun  7 12:59:07] ERROR[24524]: res_pjsip_session.c:2470 ast_sip_session_create_outgoing: Temp debug, now location is 102
[Jun  7 12:59:07] ERROR[24524]: res_pjsip_session.c:2476 ast_sip_session_create_outgoing: Temp debug, uri becomes 102
[Jun  7 12:59:07] ERROR[24524]: res_pjsip_session.c:2486 ast_sip_session_create_outgoing: Temp debug, uri is 102 at the end
[Jun  7 12:59:07] ERROR[24524]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint '102'
[Jun  7 12:59:07] WARNING[24576][C-00000001]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
  == Contact 102/sip:102@176.12.16.218:37779;ob has been deleted
  == Everyone is busy/congested at this time (1:0/0/1)
  == Endpoint 102 is now Unreachable
    -- Auto fallthrough, channel 'PJSIP/101-00000000' status is 'CHANUNAVAIL'

And the modified code itself :


 struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint *endpoint,
        struct ast_sip_contact *contact, const char *location, const char *request_user,
        struct ast_stream_topology *req_topology)
{
        const char *uri = NULL;
        RAII_VAR(struct ast_sip_aor *, found_aor, NULL, ao2_cleanup);
        RAII_VAR(struct ast_sip_contact *, found_contact, NULL, ao2_cleanup);
        pjsip_timer_setting timer;
        pjsip_dialog *dlg;
        struct pjsip_inv_session *inv_session;
        RAII_VAR(struct ast_sip_session *, session, NULL, ao2_cleanup);
        struct ast_sip_session *ret_session;

        /* If no location has been provided use the AOR list from the endpoint itself */
        if (location || !contact) {
                ast_log(LOG_ERROR, "Temp debug, location is %s, uri is %s\n", location, uri);
                location = S_OR(location, endpoint->aors);
                ast_log(LOG_ERROR, "Temp debug, now location is %s\n", location);

                ast_sip_location_retrieve_contact_and_aor_from_list_filtered(location, AST_SIP_CONTACT_FILTER_REACHABLE,
                        &found_aor, &found_contact);
                if (!found_contact || ast_strlen_zero(found_contact->uri)) {
                        uri = location;
                        ast_log(LOG_ERROR, "Temp debug, uri becomes %s\n", uri);
                } else {
                        uri = found_contact->uri;
                        ast_log(LOG_ERROR, "Temp debug, else uri becomes %s\n", uri);
                }
        } else {
                uri = contact->uri;
                ast_log(LOG_ERROR, "Temp debug, we never enter here\n");
        }

        ast_log(LOG_ERROR, "Temp debug, uri is %s at the end\n", uri);

        /* If we still have no URI to dial fail to create the session */
        if (ast_strlen_zero(uri)) {
                ast_log(LOG_ERROR, "Endpoint '%s': No URI available.  Is endpoint registered?\n",
                        ast_sorcery_object_get_id(endpoint));
                return NULL;
        }

BTW I have tried it with 16.4, the same happens :frowning:

There is a lot more code after the part you have instrumented. The function ends at:

    /* Avoid unnecessary ref manipulation to return a session */
    ret_session = session;
    session = NULL;
    return ret_session;
}

And is going to fail unless the return ret_session is executed.

Mhm I see, ok here is some more :slight_smile:
I think we never reach “Temp debug 2” or further ?

 vmi214442*CLI> 
  == Setting global variable 'SIPDOMAIN' to 'asterisk.org'
    -- Executing [1102@default:1] Dial("PJSIP/101-00000000", "PJSIP/102") in new stack
[Jun  7 14:30:56] ERROR[29069]: res_pjsip_session.c:2468 ast_sip_session_create_outgoing: Temp debug, location is (null), uri is (null)
[Jun  7 14:30:56] ERROR[29069]: res_pjsip_session.c:2470 ast_sip_session_create_outgoing: Temp debug, now location is 102
[Jun  7 14:30:56] ERROR[29069]: res_pjsip_session.c:2476 ast_sip_session_create_outgoing: Temp debug, uri becomes 102
[Jun  7 14:30:56] ERROR[29069]: res_pjsip_session.c:2486 ast_sip_session_create_outgoing: Temp debug, uri is 102 at the end
[Jun  7 14:30:56] ERROR[29069]: res_pjsip_session.c:2495 ast_sip_session_create_outgoing: Temp debug 1
[Jun  7 14:30:56] ERROR[29069]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint '102'
[Jun  7 14:30:56] WARNING[29121][C-00000001]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
  == Everyone is busy/congested at this time (1:0/0/1)
    -- Auto fallthrough, channel 'PJSIP/101-00000000' status is 'CHANUNAVAIL'
  == Contact 102/sip:102@176.12.16.218:37779;ob has been deleted
  == Endpoint 102 is now Unreachable

code :

struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint *endpoint,
        struct ast_sip_contact *contact, const char *location, const char *request_user,
        struct ast_stream_topology *req_topology)
{
        const char *uri = NULL;
        RAII_VAR(struct ast_sip_aor *, found_aor, NULL, ao2_cleanup);
        RAII_VAR(struct ast_sip_contact *, found_contact, NULL, ao2_cleanup);
        pjsip_timer_setting timer;
        pjsip_dialog *dlg;
        struct pjsip_inv_session *inv_session;
        RAII_VAR(struct ast_sip_session *, session, NULL, ao2_cleanup);
        struct ast_sip_session *ret_session;

        /* If no location has been provided use the AOR list from the endpoint itself */
        if (location || !contact) {
                ast_log(LOG_ERROR, "Temp debug, location is %s, uri is %s\n", location, uri);
                location = S_OR(location, endpoint->aors);
                ast_log(LOG_ERROR, "Temp debug, now location is %s\n", location);

                ast_sip_location_retrieve_contact_and_aor_from_list_filtered(location, AST_SIP_CONTACT_FILTER_REACHABLE,
                        &found_aor, &found_contact);
                if (!found_contact || ast_strlen_zero(found_contact->uri)) {
                        uri = location;
                        ast_log(LOG_ERROR, "Temp debug, uri becomes %s\n", uri);
                } else {
                        uri = found_contact->uri;
                        ast_log(LOG_ERROR, "Temp debug, else uri becomes %s\n", uri);
                }
        } else {
                uri = contact->uri;
                ast_log(LOG_ERROR, "Temp debug, we never enter here\n");
        }

        ast_log(LOG_ERROR, "Temp debug, uri is %s at the end\n", uri);

        /* If we still have no URI to dial fail to create the session */
        if (ast_strlen_zero(uri)) {
                ast_log(LOG_ERROR, "Endpoint '%s': No URI available.  Is endpoint registered?\n",
                        ast_sorcery_object_get_id(endpoint));
                return NULL;
        }

        ast_log(LOG_ERROR, "Temp debug 1\n");

        if (!(dlg = ast_sip_create_dialog_uac(endpoint, uri, request_user))) {
                return NULL;
        }

        ast_log(LOG_ERROR, "Temp debug 2\n");

        if (setup_outbound_invite_auth(dlg)) {
                pjsip_dlg_terminate(dlg);
                return NULL;
        }
...

I am experiencing the same issue with 16.3 and 16.4

When the endpoint registers I can do a ‘pjsip show contacts’ and I can see the registered contact.

When I issue a ‘pjsip show endpoints’ I immediately get ‘Endpoint xxxx@yyy.com is now Unreachable’

If I reconfigure as statically in pjsip.conf the extensions register and work fine, switching to realtime causes the issue.

So for me this was an issue with the latest mysql ODBC driver (v.8.0.16) - not sure if it was specific to my OS (Ubuntu 18.04)

I downloaded the v5.3.11 here: https://www.mirrorservice.org/sites/ftp.mysql.com/Downloads/Connector-ODBC/5.3/mysql-connector-odbc-5.3.11-linux-ubuntu18.04-x86-64bit.tar.gz

Using this driver fixed the issue for me.

Hi @peter , glad you joined in.

Have you tried a call cause yes with odbc v5.3.11 the endpoints do not get disconnected when I issue “pjsip show endpoints”, however no calls. Even no contacts when I say “pjsip show contacts”. Here is my log :

I register 102 :

    -- Added contact 'sip:102@176.12.16.218:37995;ob' to AOR '102' with expiration of 900 seconds
  == Endpoint 102 is now Reachable
    -- Contact 102/sip:102@176.12.16.218:37995;ob is now Reachable.  RTT: 147.620 msec
vmi214442*CLI> 
vmi214442*CLI> pjsip show contacts
No objects found. 

vmi214442*CLI> pjsip show endpoints

 Endpoint:  <Endpoint/CID.....................................>  <State.....>  <Channels.>
    I/OAuth:  <AuthId/UserName...........................................................>
        Aor:  <Aor............................................>  <MaxContact>
      Contact:  <Aor/ContactUri..........................> <Hash....> <Status> <RTT(ms)..>
  Transport:  <TransportId........>  <Type>  <cos>  <tos>  <BindAddress..................>
   Identify:  <Identify/Endpoint.........................................................>
        Match:  <criteria.........................>
    Channel:  <ChannelId......................................>  <State.....>  <Time.....>
        Exten: <DialedExten...........>  CLCID: <ConnectedLineCID.......>
==========================================================================================

 Endpoint:  101                                                  Not in use    0 of inf
     InAuth:  101/101
        Aor:  101                                                1
  Transport:  transport-wss             wss      0      0  0.0.0.0:5060

 Endpoint:  102                                                  Not in use    0 of inf
     InAuth:  102/102
        Aor:  102                                                1
  Transport:  transport-udp             udp      0      0  0.0.0.0:5060


Objects found: 2

– no disconnect messages here, but no contacts also and the call again fails.

hmmm,

Yes calling is working for me, but I get the contacts filled on registration:

asterisk01*CLI> pjsip show contacts

Contact: <Aor/ContactUri..............................> <Hash....> <Status> <RTT(ms)..> ==========================================================================================

Contact: 0001@somedomain.com/sip:0001-vrcotjv7b50m2@10.1 8e910b17b9 NonQual nan
Contact: 0002@somedomain.com/sip:0002-fsgourr530om8@10.1 702f312b4c NonQual nan

I presume that that the ps_contacts table is not getting updated when registration takes place?

Hmmm, but it gets updated :

MariaDB [asterisk]> select * from ps_contacts;
Empty set (0.00 sec)

MariaDB [asterisk]> select * from ps_contacts;
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
| id                                      | uri                                                             | expiration_time | qualify_frequency | outbound_proxy | path | user_agent                            | qualify_timeout | reg_server | authenticate_qualify | via_addr             | via_port | call_id                              | endpoint | prune_on_boot |
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
| 101^3B@081abe6612fa091b114670a1271b94cd | sips:101@176.12.16.218:35254^3Btransport=ws^3Brtcweb-breaker=no |      1560268750 |                10 |                |      | IM-client/OMA1.0 sipML5-v1.2016.03.04 |               3 |            | no                   | df7jal23ls0d.invalid |        0 | b94f79dc-064d-efc8-f54a-40c5673531b3 | 101      | yes           |
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
1 row in set (0.00 sec)

MariaDB [asterisk]> 
MariaDB [asterisk]> 
MariaDB [asterisk]> 
MariaDB [asterisk]> 
MariaDB [asterisk]> select * from ps_contacts;
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
| id                                      | uri                                                             | expiration_time | qualify_frequency | outbound_proxy | path | user_agent                            | qualify_timeout | reg_server | authenticate_qualify | via_addr             | via_port | call_id                              | endpoint | prune_on_boot |
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
| 101^3B@081abe6612fa091b114670a1271b94cd | sips:101@176.12.16.218:35254^3Btransport=ws^3Brtcweb-breaker=no |      1560268750 |                10 |                |      | IM-client/OMA1.0 sipML5-v1.2016.03.04 |               3 |            | no                   | df7jal23ls0d.invalid |        0 | b94f79dc-064d-efc8-f54a-40c5673531b3 | 101      | yes           |
| 102^3B@ade44845821be7424558ff141e7669b4 | sip:102@176.12.16.218:37995^3Bob                                |      1560269481 |                10 |                |      | CSipSimple_ali_n-28/r2457             |               3 |            | no                   | 176.12.16.218        |    37995 | kmzfQmEl7JrUcq8inyiYYWqMATPDYxak     | 102      | no            |
+-----------------------------------------+-----------------------------------------------------------------+-----------------+-------------------+----------------+------+---------------------------------------+-----------------+------------+----------------------+----------------------+----------+--------------------------------------+----------+---------------+
2 rows in set (0.00 sec)

MariaDB [asterisk]> 

Damn if I know what’s going on here … version 16.4 right … ODBC is
mysql-connector-odbc-5.3.11

How about the odbc config ?

odbc.ini :
[asterisk]
Driver = MySQL
Description = MySQL connection to asterisk database
Server = localhost
Port = 3306
Database = asterisk
UserName = root
Password = --deleted–
Socket = /var/run/mysqld/mysqld.sock

odbcinst.ini :
[MySQL]
Description = ODBC for MySQL
Driver = /usr/lib/x86_64-linux-gnu/odbc/libmyodbc5a.so
Setup = /usr/lib/x86_64-linux-gnu/odbc/libmyodbc5S.so
UsageCount = 10

Here is my configuration files and system info, hope it helps:

/etc/odbcinst.ini

[MySQL]
Description = ODBC for MySQL
Driver = /usr/lib/x86_64-linux-gnu/odbc/libmyodbc5a.so
Setup = /usr/lib/x86_64-linux-gnu/odbc/libodbcmyS.so
FileUsage = 1

/etc/odbc.ini

[asterisk]
Driver = MySQL
Description = MySQL connection to ‘asterisk’ database
Server = x.x.x.x
Port = 3306
Database = asterisk
Socket = /var/run/mysqld/mysqld.sock
option=3

/etc/asterisk/res_odbc.conf

[asterisk]
enabled => yes
dsn => asterisk
username => asterisk
password => --removed--
pre-connect => yes

/etc/asterisk/sorcery.conf

[res_pjsip] ; Realtime PJSIP configuration wizard
endpoint=realtime,ps_endpoints
auth=realtime,ps_auths
aor=realtime,ps_aors
domain_alias=realtime,ps_domain_aliases
contact=realtime,ps_contacts
 
[res_pjsip_endpoint_identifier_ip]
identify=realtime,ps_endpoint_id_ips

/etc/asterisk/extconfig.conf

[settings]
ps_endpoints => odbc,asterisk
ps_auths => odbc,asterisk
ps_aors => odbc,asterisk
ps_domain_aliases => odbc,asterisk
ps_endpoint_id_ips => odbc,asterisk
ps_contacts => odbc,asterisk
extensions => odbc,asterisk

Using Ubuntu 18:

lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.2 LTS
Release:	18.04
Codename:	bionic

Using Asterisk 16.4 compiled from source

asterisk01*CLI> core show version
Asterisk 16.4.0 built by root @ asterisk01 on a x86_64 running Linux on 2019-06-10 12:27:37 UTC

Using mysql installed from ubuntu repo:

mysql> SHOW VARIABLES LIKE "%version%";
+-------------------------+-------------------------+
| Variable_name           | Value                   |
+-------------------------+-------------------------+
| innodb_version          | 5.7.26                  |
| protocol_version        | 10                      |
| slave_type_conversions  |                         |
| tls_version             | TLSv1,TLSv1.1           |
| version                 | 5.7.26-0ubuntu0.18.04.1 |
| version_comment         | (Ubuntu)                |
| version_compile_machine | x86_64                  |
| version_compile_os      | Linux                   |
+-------------------------+-------------------------+
8 rows in set (0.01 sec)

Thank you Peter, but no luck at my side … but I’m on debian, not ubuntu … I will leave this at rest for some time, hopefully some other suggestion will pop up :slight_smile:
Thanks again !