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?
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)
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…
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.
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 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…
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?
Thanks.