Endpoint xxxxx is now Unreachable. Then goes to Reachable even through OPTIONS keepalive response is being received

I have been tracking an issue where some endpoints (PJSIP) go to Unreachable and immediately go Reachable when that endpoint re-registers. I have captured pcap logs (tcpdump) and verified that these endpoints do indeed immediately reply 200-OK to the OPTIONS message (keepalive) originating from Asterisk. NOTE: The tcpdump capture is on the asterisk machine itself.

I am running Asterisk 16.20.0 with the latest patches and updates as of this week.
Below is a section of a tcpdump for an endpoint. You can see the registration, followed by OPTIONS and NOTIFY request from asterisk to the endpoint and the 200-OK reply.

Then at 05:50:14 (30sec later) the OPTIONS request from asterisk to the endpoint, which replies immediately with the 200 OK. (this is the asterisk keepalive time set)

When the endpoint re-registers, is when asterisk immediately marks the endpoint as Unreachable, and then Reachable when the registration process completes.

What is really peculiar is not all endpoints behave this way.
The application on all my smartphones are Zoiper version 5. (latest patches/version).
All smartphones are the same make/model (samsung) v10 of android (I believe) and are sitting side-by-side and connected via WIFI.

Very perplexing. Any ideas or suggestions on where to look next?

Thanks in advance,
Andy


No. Time Source Destination Protocol Length Info
3293 2021-10-05 05:49:44.142764 98.235.72.157 10.247.97.4 SIP 930 Request: REGISTER sip:20.185.41.115;transport=UDP (1 binding) |
3294 2021-10-05 05:49:44.143824 10.247.97.4 98.235.72.157 SIP 537 Status: 200 OK (1 binding) |
3295 2021-10-05 05:49:44.144628 10.247.97.4 98.235.72.157 SIP 537 Request: OPTIONS sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3296 2021-10-05 05:49:44.144677 10.247.97.4 98.235.72.157 SIP 748 Request: NOTIFY sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3297 2021-10-05 05:49:44.183624 98.235.72.157 10.247.97.4 SIP 747 Status: 200 OK |
3298 2021-10-05 05:49:44.188859 98.235.72.157 10.247.97.4 SIP 472 Status: 200 OK |
3363 2021-10-05 05:50:14.144629 10.247.97.4 98.235.72.157 SIP 536 Request: OPTIONS sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3364 2021-10-05 05:50:14.378341 98.235.72.157 10.247.97.4 SIP 746 Status: 200 OK |
3365 2021-10-05 05:50:14.378363 98.235.72.157 10.247.97.4 UDP 60 41702 → 5060 Len=4
3417 2021-10-05 05:50:44.144815 10.247.97.4 98.235.72.157 SIP 537 Request: OPTIONS sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3418 2021-10-05 05:50:44.349700 98.235.72.157 10.247.97.4 SIP 747 Status: 200 OK |
3419 2021-10-05 05:50:44.363429 98.235.72.157 10.247.97.4 SIP 930 Request: REGISTER sip:20.185.41.115;transport=UDP (1 binding) |
3420 2021-10-05 05:50:44.363957 10.247.97.4 98.235.72.157 SIP 572 Status: 401 Unauthorized |
3421 2021-10-05 05:50:44.370082 98.235.72.157 10.247.97.4 UDP 60 41702 → 5060 Len=4
3422 2021-10-05 05:50:44.413599 98.235.72.157 10.247.97.4 SIP 930 Request: REGISTER sip:20.185.41.115;transport=UDP (1 binding) |
3423 2021-10-05 05:50:44.436371 10.247.97.4 98.235.72.157 SIP 537 Status: 200 OK (1 binding) |
3424 2021-10-05 05:50:44.436825 10.247.97.4 98.235.72.157 SIP 537 Request: OPTIONS sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3425 2021-10-05 05:50:44.437194 10.247.97.4 98.235.72.157 SIP 748 Request: NOTIFY sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf |
3426 2021-10-05 05:50:44.473712 98.235.72.157 10.247.97.4 SIP 747 Status: 200 OK |
3427 2021-10-05 05:50:44.478852 98.235.72.157 10.247.97.4 SIP 472 Status: 200 OK |

Ultimately you’d want Asterisk logging[1]. The OPTIONS code has debugging which states why it is doing what it is doing.

[1] Collecting Debug Information - Asterisk Project - Asterisk Project Wiki

Apparently, I can’t reply or post to a subject more than 2 times…I’m a new user…

So here is the response I was going to post under my original user name, only under this username…

I did turn on debug: core set debug 5.
I followed the debug for endpoint 0010104 through the qualify debug output and the reply processing from that endpoint. The pjsip_options.c seems to be happy with the 200-OK reply, and indicates no change in status. "status didn't change: Reachable, RTT: 174.285 msec**"

Immediately following the response qualify + response is a re-registration from that endpoint.

The endpoint Authenticates fine, but during the registration process, the pjsip_options.c code marks the endpoint as unavailable. 
** See 2nd log output 
*Note: this all happens about at the same time in the logs.*

**1st LOG OUTPUT:     OPTIONS + 200 REPLY LOG**

2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR '0010104'
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_options.c: Qualifying contact '0010104;@f38824e202245a224e104c834f03b2c9' on AOR '0010104'
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip.c: 0x37db0a0: Wrapper created
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip.c: 0x37db0a0: Set timer to 15000 msec
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '98.235.72.157'
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_resolver.c: Transport type for target '98.235.72.157' is 'UDP transport'
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_resolver.c: Target '98.235.72.157' is an IP address, skipping resolution
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.247.97.4:5060 (this may be re-written again later)
[2021-10-05 07:52:34] DEBUG[21524] netsock2.c: Splitting '98.235.72.157' into...
[2021-10-05 07:52:34] DEBUG[21524] netsock2.c: ...host '98.235.72.157' and port ''.
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=21018 (rdata0x7fc284000968).  Using request transaction as basis.
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Found transaction tsx0x3f61048 for Response msg 200/OPTIONS/cseq=21018 (rdata0x7fc284000968).
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/0010104-00000250 on transaction tsx0x3f61048
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip.c: 0x37db0a0: PJSIP tsx response received
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip.c: 0x37db0a0: Cancelling timer
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip.c: 0x37db0a0: Timer cancelled
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip.c: 0x37db0a0: Callbacks executed
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip.c: 0x37db0a0: wrapper destroyed
[2021-10-05 07:52:34] DEBUG[28593] res_pjsip/pjsip_options.c: Contact **0010104/sip:0010104@98.235.72.157:41702;rinstance=1e345a19f7eea4cf status didn't change: Reachable, RTT: 174.285 msec**
**[2021-10-05 07:52:34] DEBUG[28593] res_pjsip/pjsip_options.c: AOR '0010104' now has 1 available contacts**

2nd LOG OUTPUT: Registration/Authentication successfull. pjsip_options.c marks endpoint as unavailable.

2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=333 (rdata0x7fc284000968)
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000014d to use for Request msg REGISTER/cseq=333 (rdata0x7fc284000968)
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[26121] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2021-10-05 07:52:34] DEBUG[26121] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username ‘0010104’ domain ‘20.185.41.115’
[2021-10-05 07:52:34] DEBUG[26121] res_pjsip_endpoint_identifier_user.c: Identified by From username ‘0010104’ domain ‘20.185.41.115’
[2021-10-05 07:52:34] DEBUG[26121] res_pjsip_authenticator_digest.c: Using default realm ‘asterisk’ on incoming auth ‘0010104-auth’.
[2021-10-05 07:52:34] DEBUG[26121] res_pjsip_authenticator_digest.c: Realm: asterisk Username: 0010104 Result: STALE
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: Splitting ‘10.247.97.4’ into…
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: …host ‘10.247.97.4’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[26121] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] SECURITY[19462] res_security_log.c: SecurityEvent=“ChallengeSent”,EventTV=“2021-10-05T07:52:34.442-0400”,Severity=“Informational”,Service=“PJSIP”,EventVersion=“1”,AccountID=“0010104”,SessionID=“zs1wbeo-dm00BPDJ_07SGw…”,LocalAddress=“IPV4/UDP/10.247.97.4/5060”,RemoteAddress=“IPV4/UDP/98.235.72.157/41702”,Challenge=""
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=334 (rdata0x7fc284000968)
[2021-10-05 07:52:34] DEBUG[19368] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000014d to use for Request msg REGISTER/cseq=334 (rdata0x7fc284000968)
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username ‘0010104’ domain ‘20.185.41.115’
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_endpoint_identifier_user.c: Identified by From username ‘0010104’ domain ‘20.185.41.115’
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_authenticator_digest.c: Using default realm ‘asterisk’ on incoming auth ‘0010104-auth’.
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_authenticator_digest.c: Calculated nonce 1633434754/b1d85842f48ab96fbaac6f0015a21517. Actual nonce is 1633434754/b1d85842f48ab96fbaac6f0015a21517
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_authenticator_digest.c: Realm: asterisk Username: 0010104 Result: SUCCESS
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: Splitting ‘10.247.97.4’ into…
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: …host ‘10.247.97.4’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_registrar.c: Matched id ‘0010104’ to aor ‘0010104’
[2021-10-05 07:52:34] DEBUG[27083] res_pjsip_registrar.c: Matched aor ‘0010104’ by To username
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract double from [3.0] in [-inf, inf] gives 3.000000
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract uint from [0] in [0, 4294967295] gives 0
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract double from [15.000000] in [-inf, inf] gives 15.000000
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract uint from [41702] in [0, 4294967295] gives 41702
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract uint from [30] in [0, 86400] gives 30
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract double from [3.0] in [-inf, inf] gives 3.000000
[2021-10-05 07:52:34] DEBUG[27083] config.c: extract uint from [0] in [0, 4294967295] gives 0
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: Splitting ‘98.235.72.157’ into…
[2021-10-05 07:52:34] DEBUG[27083] netsock2.c: …host ‘98.235.72.157’ and port ‘’.
[2021-10-05 07:52:34] SECURITY[19462] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2021-10-05T07:52:34.492-0400”,Severity=“Informational”,Service=“PJSIP”,EventVersion=“1”,AccountID=“0010104”,SessionID=“zs1wbeo-dm00BPDJ_07SGw…”,LocalAddress=“IPV4/UDP/10.247.97.4/5060”,RemoteAddress=“IPV4/UDP/98.235.72.157/41702”,UsingPassword=“1”
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_options.c: AOR ‘0010104’ now has 0 available contacts
[2021-10-05 07:52:34] DEBUG[21524] res_pjsip/pjsip_options.c: Terminating scheduled callback on AOR ‘0010104’ as there are no contacts to qualify
[2021-10-05 07:52:34] DEBUG[19347] devicestate.c: No provider found, checking channel drivers for PJSIP - 0010104
[2021-10-05 07:52:34] DEBUG[19347] devicestate.c: Changing state for PJSIP/0010104 - state 5 (Unavailable)

I’d suggest showing the REGISTER then. Are you using realtime?

Could you please elaborate a bit on what I should collect? Sorry.
FYI: I am now looking at comparison of an endpoint that shows this behavior and one that doesn’t using debug in the meantime. Just started…

A protocol level trace[1].

[1] Collecting Debug Information - Asterisk Project - Asterisk Project Wiki

This will look really messy, but here is a capture from one of many endpoints that keeps going from unreachable to reachable. I have broken up the capture (w/timetags) into Requests/Responses with a small header explaining what is going on in each section. Sorry for taking so long to get back to you, but so busy with a dozen other things.

The attached upload contains a txt file with this information.

Summary of that is in file:

  • It looks like on every REGISTER operation, the contact is added to the AOR for extension 0010104, and then when Asterisk sends the 200 OK response, that contact is deleted and 0010104 is marked unreachable.
  • the 1st qualify message (OPTIONS) + response from 0010104, right after the REGISTER sequence, marks 0010104 are ‘reachable’
  • The Asterisk sends the periodic qualify messages (OPTIONS) w/immediate response received, every 20 secs, with an immediate response from 0010104
  • This happens until 0010104 begins the next REGISTER sequence, which marks 0101004 as ‘unreachable’.

Hope this info helps clarify what I am seeing. Let me know if there is anything else I can collect.

Andy

0010104 Not Staying Connected.txt (25.4 KB)

It appears as though Zoiper is not re-registering early with overlap, it’s re-registering exactly every 60 seconds which is when the old registration is no longer valid. The old registration is removed because it’s no longer valid, the new registration is added, and there’s a slight period of time in between where it goes unreachable as a result.

It should re-register BEFORE the expiration. This could be due to the 60 second expiration time, its logic may not account for such a low value.

I thought the same thing as well, and will change the minimum expiration timeout to 70.
You know, as soon as I posted this, I came to this revelation as well :slight_smile: Thanks.

Additionally, I have another hardware based unit, that also has this same issue, but its re-registering time is ~every 31 secs. Its been very difficult to get info from this unit, since it is installed on a pilot vehicle that doesn’t run very often and for more that 15 min at a time, at best. By the time I see it on-line and get data captures started, its powered off again…

Anyhow, I am gaining great insight into the nuances of Asterisk and all the timers, etc…

Thanks for you and your staff for all the great support you all give in these forums…

Andy

Seem to have another issue.
I bulk import my extensions and have set the column ==> minimum_expiration = 70.
However, when I bulk import my extensions, the value stays at 60.
I can manually go into each extension and set minimum_expiration to 70 and it sticks.
It seems the csv bulk import for minimum_expiration no longer works.

In fact, I just did a bulk export of extensions, and the column minimum_expiration no longer exists. I know it was there a couple months ago, because I had merged in values from a previous extensions.csv file.

The column maximum_expiration exists, and is set to 7200.

This sucks. I have a couple hundred extensions where I don’t want to hand edit each extension.
Any suggestions?

Andy.

If you’re referring to FreePBX, I have no idea about that stuff.

You’re right. My bad…

I added minimum_expiration = 70 to the pjsip.endpoint_custom_post.conf with other parameters there.
That worked…

Thanks Again!!!