[Home]

Summary:ASTERISK-23613: Endpoint identification fails when user part of From header SIP-URI contains a tel URI style parameter
Reporter:yaron nahum (yaronna)Labels:
Date Opened:2014-04-10 08:56:06Date Closed:2017-12-18 10:29:59.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Resources/res_pjsip
Versions:12.1.0 12.2.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:CentOS release 5.4 (Final)Attachments:
Description:I have an Asterisk 12 with PJSIP configured working againt a Comverse (NetCentrex) Switch. The Comverse switch sends periodically Session Keep-Alive every 200 seconds using OPTIONS method.
The asterisk is not responding to the Keep alive therefore the call is disconnected.
Below is the debug taken from the server:
{noformat}
##############################3
[Apr 10 16:16:40] DEBUG[13801] pjsip:   sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=2 (rdata0xa5b03b4)
[Apr 10 16:16:40] VERBOSE[13801] res_pjsip_logger.c: <--- Received SIP request (393 bytes) from UDP:172.16.60.160:5080 --->
OPTIONS sip:172.16.60.160:5061;transport=UDP SIP/2.0^M
Via: SIP/2.0/UDP 172.16.60.160:5080^M
From: <sip:39919002;cpc=ordinary@172.16.60.160:5080;user=phone>;tag=1^M
To: <sip:039988120@172.16.60.160:5060>;tag=9d105b31-3396-4aa5-afe3-c519ee8b5db2^M
Call-ID: 1-17908@172.16.60.160^M
Cseq: 2 OPTIONS^M
Contact: sip:39919002@172.16.60.160:5080^M
Max-Forwards: 60^M
Subject: Simulator^M
Content-Length: 0^M
^M

[Apr 10 16:16:40] DEBUG[17772] pjsip:   sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=2 (rdata0xb411493c)
[Apr 10 16:16:40] DEBUG[17772] pjsip:    dlg0xb4111eb4 .Received Request msg OPTIONS/cseq=2 (rdata0xb411493c)
[Apr 10 16:16:40] DEBUG[17772] pjsip:    tsx0xb7d74764 ...Transaction created for Request msg OPTIONS/cseq=2 (rdata0xb411493c)
[Apr 10 16:16:40] DEBUG[17772] pjsip:    tsx0xb7d74764 ..Incoming Request msg OPTIONS/cseq=2 (rdata0xb411493c) in state Null
[Apr 10 16:16:40] DEBUG[17772] pjsip:    tsx0xb7d74764 ...State changed from Null to Trying, event=RX_MSG
[Apr 10 16:16:40] DEBUG[17772] pjsip:    dlg0xb4111eb4 ....Transaction tsx0xb7d74764 state changed to Trying
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The state change pertains to the session with sipp
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The transaction involved in this state change is 0xb7d74764
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The current transaction state is Trying
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr 10 16:16:40] DEBUG[17772] res_pjsip_session.c: Method is OPTIONS
{noformat}
Comments:By: Rusty Newton (rnewton) 2014-04-17 08:50:38.045-0500

I've reproduced this scenario (in-dialog OPTIONS message) and chan_pjsip responds to the messages in my test.

I'm not sure why it doesn't in your case.

Please post your pjsip.conf so we can see the endpoint configuration. Plus an Asterisk full log (verbose and debug) including the pjsip logger output so we can see everything.
By: Rusty Newton (rnewton) 2014-04-17 09:23:34.092-0500

I was able to reproduce the issue.

The key was the {{;cpc=ordinary}} parameter in the From header.

{noformat}
From: <sip:39919002;cpc=ordinary@172.16.60.160:5080;user=phone>;tag=1^M
{noformat}

With NOTICE messages visible you should see

{noformat}
[Apr 17 09:07:15] NOTICE[8449]: res_pjsip/pjsip_distributor.c:246 log_unidentified_request: Request from '"98765432" <sip:98765432;cpc=ordinary@192.168.1.187;user=phone>' failed for '192.168.1.187:5061' (callid: 1-8501@192.168.1.187) - No matching endpoint found
{noformat}

Removing that parameter alone, and making the rest of the OPTIONS just like yours, results in Asterisk responding to the OPTIONS request normally.
By: Rusty Newton (rnewton) 2014-04-17 09:25:24.779-0500

Well.. in the case of the parameter being present, Asterisk does respond with a 401 Unauthorized.  Can you verify that Asterisk doesn't respond at all, with any message in your case?  Getting your configuration would still be very helpful.
By: yaron nahum (yaronna) 2014-04-22 04:57:41.881-0500

In my case a response is not sent at all. I have tried to remove the cpc=ordinary and it is still not responding to OPTIONS message.

my pjsip.conf is very simple:

[sipp]
type=endpoint
transport=transport-udp
;send_pai=yes
context=from-external
;trust_id_outbound=yes
;trust_id_inbound=yes
;callerid_privacy=allowed
disallow=all
allow=alaw
100rel=required
from_domain=172.16.60.160
;qualify_frequency=10
;outbound_auth=mytrunk_auth
aors=sipp
direct_media_glare_mitigation=none
direct_media=no
;redirect_method=uri_core
;                   ;A few NAT relevant options that may come in handy.
;force_rport=yes    ;It's a good idea to read the configuration help for each
;direct_media=no    ;of these options.
;ice_support=yes
;timers_min_se=90
;timers=required

[sipp]
type=aor
;max_contacts=2
contact=sip:172.16.60.160:5080\;user=phone
contact=sip:172.16.10.2:5060
contact=sip:172.16.10.3:5060

;contact=sip:10.25.153.150:5060
;qualify_frequency=10
;default_expiration=10


[sipp]
type=identify
endpoint=sipp
match=10.25.153.150
match=172.16.60.160
match=172.16.10.2
match=172.16.10.3


;OSP
[osp]
type=endpoint
send_pai=yes
transport=transport-udp
context=from-osp
disallow=all
allow=alaw
;100rel=required
;qualify_frequency=10
;outbound_auth=mytrunk_auth
aors=osp
;redirect_method=uri_core

;                   ;A few NAT relevant options that may come in handy.
;force_rport=yes    ;It's a good idea to read the configuration help for each
;direct_media=no    ;of these options.
;ice_support=yes

[osp]
type=aor
;max_contacts=2
;contact=sip:172.16.60.160:5080
;contact=sip:10.25.153.150:5060
;qualify_frequency=10
;default_expiration=10
contact=sip:10.9.1.38:5060
contact=sip:10.9.129.38:5060

[osp]
type=identify
endpoint=osp
match=10.9.1.38
match=10.9.129.38

and in my extensions.ael I just do Answer(), Wait(500) and than hangup.

One thing I find very strange is timeout message after the ACK is received. you can see it at the bottom of my response. Can you send me a trace that works - I will try to simulate it here and then try to play with it until it breaks.

[Apr 22 10:56:21] DEBUG[27818] pjsip:   sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0xa239e5c)
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The transaction involved in this state change is 0xb58bef9c
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The current transaction state is Completed
[Apr 22 10:56:21] VERBOSE[27818] res_pjsip_logger.c: <--- Received SIP request (373 bytes) from UDP:172.16.60.160:5080 --->
��ACK sip:172.16.60.160:5060;transport=UDP SIP/2.0^M
��Via: SIP/2.0/UDP 10.1.1.1:5060;branch=z9hG4bK-29027-1-4^M
��Max-Forwards: 60^M
��From: "Anonymous" <sip:anonymous@192.168.225.2>;tag=1^M
��To: <sip:039988120@172.16.60.160:5060;user=phone>;tag=b2018fc9-735a-4f8d-9227-ee766b8dee81^M
��Call-ID: 1-29027@172.16.60.160^M
��Cseq: 1 ACK^M
��Content-Type: application/sdp^M
��User-Agent: Simulator^M
��^M
��
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The current inv state is CONNECTING
[Apr 22 10:56:21] DEBUG[27813] pjsip:   sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0xa002a7c)
[Apr 22 10:56:21] DEBUG[27813] pjsip:    dlg0xb4d80ae4 .Received Request msg ACK/cseq=1 (rdata0xa002a7c)
[Apr 22 10:56:21] DEBUG[27813] pjsip:    tsx0xb58bef9c ..Request to terminate transaction
[Apr 22 10:56:21] DEBUG[27813] pjsip:    tsx0xb58bef9c ...State changed from Completed to Terminated, event=USER
[Apr 22 10:56:21] DEBUG[27813] pjsip:    dlg0xb4d80ae4 ....Transaction tsx0xb58bef9c state changed to Terminated
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The state change pertains to the session with sipp
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The inv session still has an invite_tsx (0xb58bef9c)
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The transaction involved in this state change is 0xb58bef9c
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The current transaction state is Terminated
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The transaction state change event is USER
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The current inv state is CONNECTING
[Apr 22 10:56:21] DEBUG[27813] pjsip:   tdta0xb7dfee48 .....Destroying txdata Response msg 200/INVITE/cseq=1 (tdta0xb7dfee48)
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The state change pertains to the session with sipp
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: There is no transaction involved in this state change
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: Received request
[Apr 22 10:56:21] DEBUG[27813] res_pjsip_session.c: Method is ACK
[Apr 22 10:56:21] DEBUG[27818] pjsip:    tsx0xb58bef9c Timeout timer event kululu
[Apr 22 10:56:21] DEBUG[27818] pjsip:    tsx0xb58bef9c .State changed from Terminated to Destroyed, event=TIMER
[Apr 22 10:56:21] DEBUG[27818] pjsip:    tdta0xa009798 ..Destroying txdata Response msg 200/INVITE/cseq=1 (tdta0xa009798)
[Apr 22 10:56:21] DEBUG[27818] pjsip:    tsx0xb58bef9c Transaction destroyed!

By: Per Jensen (pjensen00) 2014-06-06 13:59:43.052-0500

I have a similar issue except that I'm getting 404's even though I have a proper context that matches.  I never get to the default context, just the 404 sent back.  My setup however, its openSIPS sending a probe via an OPTIONS packet.  

Here are the relevant lines that should explain my current plight.  

Asterisk CLI
{noformat}
CLI output
<--- Received SIP request (421 bytes) from UDP:172.31.12.252:5060 --->
OPTIONS sip:ADDRESS(censored for security reasons) SIP/2.0
Via: SIP/2.0/UDP ADDRESS(removed for security reasons):5060;branch=z9hG4bKa1b.1fb55715.0
To: ADDRESS(censored for security reasons)
From: <sip:prober@localhost>;tag=bfb847842ed8d831146951d66a19ae48-7366
CSeq: 10 OPTIONS
Call-ID: 1fbca1b21c80bd4f-6112@ADDRESS(censored for security reasons)
Max-Forwards: 70
Content-Length: 0
User-Agent: OpenSIPS (1.11.1-tls (x86_64/linux))


[Jun  6 17:11:31] DEBUG[29433]: res_pjsip_endpoint_identifier_ip.c:128 ip_identify: No identify sections to match against
[Jun  6 17:11:31] DEBUG[29433]: res_pjsip_endpoint_identifier_user.c:104 username_identify: Retrieved endpoint prober
<--- Transmitting SIP response (792 bytes) to UDP:ADDRESS(censored for security reasons):5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP ADDRESS(censored for security reasons):5060;rport;received=172.31.12.252;branch=z9hG4bKa1b.1fb55715.0
Call-ID: 1fbca1b21c80bd4f-6112@172.31.12.252
From: <sip:prober@localhost>;tag=bfb847842ed8d831146951d66a19ae48-7366
To: <sip:ADDRESS(censored for security reasons)>;tag=z9hG4bKa1b.1fb55715.0
CSeq: 10 OPTIONS
Accept: application/sdp, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/simple-message-summary, application/pidf+xml, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Content-Length:  0
{noformat}

pjsip.conf
{noformat}
[prober]
type=endpoint
transport=simpletrans
context=default
allow=all
;dtmf_mode=auto
direct_media=no
rtp_symmetric=yes
identify_by=username

[prober]
type=identify
username=prober
{noformat}

extensions.conf
{noformat}
[default]
exten => _.,1,Hangup()
{noformat}
By: Per Jensen (pjensen00) 2014-07-15 16:52:52.251-0500

As of Asterisk 12.4-rc1 I do not have this issue.  My extensions.conf needed to match the extension _! instead of _.
By: Joshua C. Colp (jcolp) 2017-12-18 10:29:59.814-0600

Asterisk now stops the usage of tel: URIs in all places due to issues that other code caused. If you'd like to add support for the tel: URI please open a new issue with a patch.