ASTERISK-28961: res_pjsip_outbound_registration: Re-registration is incorrectly timed when response contains two identical Contact headers

[Home]

Summary: ASTERISK-28961: res_pjsip_outbound_registration: Re-registration is incorrectly timed when response contains two identical Contact headers

Reporter: Robert Sutton (rsutton@noojee.com.au) Labels:

Date Opened: 2020-06-24 01:00:21 Date Closed:

Priority: Minor Regression?

Status: Open/New Components: pjproject/pjsip Resources/res_pjsip_outbound_registration

Versions: 16.10.0 16.11.1 Frequency of
Occurrence Occasional

Related
Issues:

Environment: 18.04 ubuntu, asterisk 16.10, docker, pjsip Attachments:

Description: Systems periodically get into a state where they stop registering the trunks to the sip provider.

Our up stream provider tells us that when this happens it lasts for about an hour and then starts working again (happened at 3am, by the time we investigated it had resolved itself).

We've also observed (historically from logs) that when it happens asterisk still thinks that it is registered. ie show registrations, show endpoints, show contacts.

This is not much to go on, but we are having trouble catching a system in the act.

if the required logging doesn't generate to much load, we cloud leave it turned on.

What logging levels would be required to be useful here?

Comments: By: Asterisk Team (asteriskteam) 2020-06-24 01:00:21.972-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Kevin Harwell (kharwell) 2020-06-24 16:44:47.513-0500

Anything in the log warning, error, or notice wise? For instance see anything similar to the following: "... task processor queue reached ..."

If the Asterisk system shows everything is fine from a registration perspective (e.g. CLI shows outbound registrations, etc... look okay) then how do you know something is wrong? Is it a case of the upstream provider expiring the registration, Asterisk doesn't send a refresh but still shows everything is "fine"?

If that's the case is no outbound sip registration observed? Like if you got a pcap then a SIP register never goes out to the provider?
By: Asterisk Team (asteriskteam) 2020-07-09 12:00:00.892-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Robert Sutton (rsutton@noojee.com.au) 2020-07-14 21:13:26.039-0500

OK, So I found an occurrence where asterisk ignored the returned expiry.

This resulted in the trunk going off line for an hour.

It is interesting that the contact appeared twice in the response from the sip provider (this is unusual), but I do wonder if asterisk may have logged it incorrectly.

{noformat}
Jul 14 17:44:42 : res_pjsip_outbound_registration.c sip_outbound_registration_response_cb Received REGISTER response 401(Unauthorized)
Jul 14 17:44:42 : res_pjsip_outbound_registration.c handle_registration_response Processing REGISTER response 401 from server 'sip:trunk.com' for client 'sip:customer@trunk.com'
Jul 14 17:44:42 : res_pjsip_outbound_registration.c handle_registration_response Sending authenticated REGISTER to server 'sip:trunk.com' from client 'sip:customer@trunk.com'
Jul 14 17:44:42 : <--- Transmitting SIP request (935 bytes) to UDP:1.2.3.5:5060 --->
Jul 14 17:44:42 : REGISTER sip:trunk.com SIP/2.0
Jul 14 17:44:42 : Via: SIP/2.0/UDP 1.2.3.4:5060;rport;branch=z9hG4bKPj718c833e-7e36-4509-ac44-879e8e9f155b
Jul 14 17:44:42 : From: <sip:customer@trunk.com>;tag=c82c4b96-f29a-4b36-85e2-a50c8a4f4849
Jul 14 17:44:42 : To: <sip:customer@trunk.com>
Jul 14 17:44:42 : Call-ID: 4fae2819-4bb1-4205-b412-f44457b54474
Jul 14 17:44:42 : CSeq: 40622 REGISTER
Jul 14 17:44:42 : Contact: <sip:customer@1.2.3.4:5060;line=oxaimwu>
Jul 14 17:44:42 : Expires: 3600
Jul 14 17:44:42 : Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Jul 14 17:44:42 : Max-Forwards: 70
Jul 14 17:44:42 : User-Agent: Asterisk PBX 16.11.1
Jul 14 17:44:42 : Authorization: Digest username="customer", realm="trunk.com", nonce="a6bc471d-be32-44bb-832a-e48df33a7570", uri="sip:trunk.com", response="a6275e95bfcd66150dcd647b403c5336", algorithm=MD5, cnonce="65c4872c317849a8bc11f6a33f4fde5e", qop=auth, nc=00000001
Jul 14 17:44:42 : Content-Length: 0
Jul 14 17:44:42 :
Jul 14 17:44:42 :
Jul 14 17:44:42 : <--- Received SIP response (745 bytes) from UDP:1.2.3.5:5060 --->
Jul 14 17:44:42 : SIP/2.0 200 OK
Jul 14 17:44:42 : Via: SIP/2.0/UDP 1.2.3.4:5060;received=1.2.3.4;rport=5060;branch=z9hG4bKPj718c833e-7e36-4509-ac44-879e8e9f155b
Jul 14 17:44:42 : From: <sip:customer@trunk.com>;tag=c82c4b96-f29a-4b36-85e2-a50c8a4f4849
Jul 14 17:44:42 : To: <sip:customer@trunk.com>;tag=yQSjSU5jj0v0c
Jul 14 17:44:42 : Call-ID: 4fae2819-4bb1-4205-b412-f44457b54474
Jul 14 17:44:42 : CSeq: 40622 REGISTER
Jul 14 17:44:42 : Contact: <sip:customer@1.2.3.4:5060;line=oxaimwu>;expires=120
Jul 14 17:44:42 : Contact: <sip:customer@1.2.3.4:5060;line=oxaimwu>;expires=120
Jul 14 17:44:42 : Date: Tue, 14 Jul 2020 07:44:42 GMT
Jul 14 17:44:42 : User-Agent: ColouredLines-sipswitch
Jul 14 17:44:42 : Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Jul 14 17:44:42 : Supported: timer, path, replaces
Jul 14 17:44:42 : Content-Length: 0
Jul 14 17:44:42 :
Jul 14 17:44:42 :
Jul 14 17:44:42 : res_pjsip_outbound_registration.c sip_outbound_registration_response_cb Received REGISTER response 200(OK)
Jul 14 17:44:42 : res_pjsip_outbound_registration.c handle_registration_response Processing REGISTER response 200 from server 'sip:trunk.com' for client 'sip:customer@trunk.com'
Jul 14 17:44:42 : res_pjsip_outbound_registration.c handle_registration_response Outbound registration to 'sip:trunk.com' with client 'sip:customer@trunk.com' successful
Jul 14 17:44:42 : res_pjsip_outbound_registration.c schedule_registration Scheduling outbound registration to server 'sip:trunk.com' from client 'sip:customer@trunk.com' in 3590 seconds
Jul 14 17:44:52 : res_pjsip/pjsip_resolver.c sip_resolve [0x7f297c040d38] Starting initial resolution using parallel queries for target 'trunk.com'
Jul 14 17:44:52 : res_pjsip/pjsip_resolver.c sip_resolve_callback [0x7f297c040d38] All parallel queries completed
Jul 14 17:44:52 : res_pjsip/pjsip_resolver.c sip_resolve_callback [0x7f297c040d38] Resolution completed - 1 viable targets
J
{noformat}
By: Asterisk Team (asteriskteam) 2020-07-14 21:13:26.537-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Benjamin Keith Ford (bford) 2020-07-15 09:39:48.329-0500

From the output you provided, it appears that the registration is completing successfully. There are a couple lines above that show a REGISTER that does not have authentication. I'm assuming these are different entities?

To echo Kevin, how do you know that something is wrong? Are there any indications on Asterisk's end that something is not working, or any details from the provider?
By: Robert Sutton (rsutton@noojee.com.au) 2020-07-15 16:37:04.308-0500

To summarize the problem; the sip provider requires registration re-registration every 120 seconds and asterisk on the other 700+ occasions this day does the right thing, but on this one occasion asterisk ignores that and decides that the next registration is not required for an hour. This results in the trunk being unregistered for 58 minutes. Our up stream provider has confirmed this, and also the absence of incoming calls also confirms this.

As asterisk asterisk has successfully registered and thinks it doesn't need to register again for an hour, so it thinks that it is registered for the next hour despite that not being the case.

In the full logs it can be seen that there is a registration from asterisk every 2 minutes of the day, except after this event where there are no registrations for this trunk for an hour after which things go back to normal.

An Unauthorized is just part of the normal process of registering. As I understand it sip auth requires attempting registering without a password and the parts of the failed response are used to hash the password when submitting the proper auth.

here are the important parts

the sip provider responds with expires=120, so after this successful registration we will become unregistered if we don't register again.
{noformat}Jul 14 17:44:42 : Contact: <sip:customer@1.2.3.4:5060;line=oxaimwu>;expires=120{noformat}

then asterisk decides to schedule the next registration for 1 hours time (3590 seconds)
{noformat}Jul 14 17:44:42 : res_pjsip_outbound_registration.c schedule_registration Scheduling outbound registration to server 'sip:trunk.com' from client 'sip:customer@trunk.com' in 3590 seconds{noformat}
By: Joshua C. Colp (jcolp) 2020-07-16 05:34:01.925-0500

Yes, the underlying cause is the two Contact headers. Since they're identical there should be only one. When there are two the PJSIP parser appears to ignore/skip them, so the expires doesn't get passed up to us.