Endpoint Registration/Dropoff Issues

FreePBX Networking
1

Hello all,
I am new to the forums so I apologize if this is a common issue or has already been answered.
I am having an issue where all of my phones (Fanvil X3SG) and VOIP.MS SIP trunk keep becoming unavailable then immediately available again. This hardly ever causes an issue, but the log file is driving me crazy. Does anyone have an idea what could be causing this?

My FreePBX is hosted in the cloud and has a public-facing IP, the phones are behind a PFSense firewall which has been set up to allow for the passage of traffic to and from the PBX. I did not set up any port forwarding or Siproxd as per instructions.

The fact that this is also occurring to the SIP trunk leads me to believe that the issue is with the FreePBX instance and not with my firewall, but I am not sure. Any insight would be really appreciated!

[2021-09-17 21:53:26] VERBOSE[14447] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:25760’ from AOR ‘106’ due to request

[2021-09-17 21:53:26] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 106/sip:[email protected]:25760 has been deleted

[2021-09-17 21:53:26] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 106 is now Unreachable

[2021-09-17 21:53:26] VERBOSE[9584] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:25760’ to AOR ‘106’ with expiration of 3600 seconds

[2021-09-17 21:53:26] VERBOSE[9584] res_pjsip/pjsip_configuration.c: Endpoint 106 is now Reachable

[2021-09-17 21:53:26] VERBOSE[9584] res_pjsip/pjsip_options.c: Contact 106/sip:[email protected]:25760 is now Reachable. RTT: 65.942 msec

[2021-09-17 21:53:31] VERBOSE[9584] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:55189’ from AOR ‘102’ due to request

[2021-09-17 21:53:31] VERBOSE[9584] res_pjsip/pjsip_options.c: Contact 102/sip:[email protected]:55189 has been deleted

[2021-09-17 21:53:31] VERBOSE[9584] res_pjsip/pjsip_configuration.c: Endpoint 102 is now Unreachable

[2021-09-17 21:53:31] VERBOSE[14447] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:55189’ to AOR ‘102’ with expiration of 3600 seconds

[2021-09-17 21:53:31] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 102 is now Reachable

[2021-09-17 21:53:31] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 102/sip:[email protected]:55189 is now Reachable. RTT: 67.929 msec

[2021-09-17 21:53:32] VERBOSE[14447] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:13889’ from AOR ‘110’ due to request

[2021-09-17 21:53:32] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 110/sip:[email protected]:13889 has been deleted

[2021-09-17 21:53:32] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 110 is now Unreachable

[2021-09-17 21:53:33] VERBOSE[9584] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:13889’ to AOR ‘110’ with expiration of 3600 seconds

[2021-09-17 21:53:33] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 110 is now Reachable

[2021-09-17 21:53:33] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 110/sip:[email protected]:13889 is now Reachable. RTT: 108.303 msec

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:19168’ from AOR ‘105’ due to request

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 105/sip:[email protected]:19168 has been deleted

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 105 is now Unreachable

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:19168’ to AOR ‘105’ with expiration of 3600 seconds

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 105 is now Reachable

[2021-09-17 21:53:34] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 105/sip:[email protected]:19168 is now Reachable. RTT: 90.514 msec

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:40385’ from AOR ‘101’ due to request

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip/pjsip_options.c: Contact 101/sip:[email protected]:40385 has been deleted

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip/pjsip_configuration.c: Endpoint 101 is now Unreachable

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:40385’ to AOR ‘101’ with expiration of 3600 seconds

[2021-09-17 21:53:35] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 101 is now Reachable

[2021-09-17 21:53:35] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 101/sip:[email protected]:40385 is now Reachable. RTT: 22.689 msec

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:20983’ from AOR ‘104’ due to request

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip/pjsip_options.c: Contact 104/sip:[email protected]:20983 has been deleted

[2021-09-17 21:53:35] VERBOSE[9584] res_pjsip/pjsip_configuration.c: Endpoint 104 is now Unreachable

[2021-09-17 21:53:36] VERBOSE[14447] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:20983’ to AOR ‘104’ with expiration of 3600 seconds

[2021-09-17 21:53:36] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 104 is now Reachable

[2021-09-17 21:53:36] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 104/sip:[email protected]:20983 is now Reachable. RTT: 66.316 msec

[2021-09-17 21:53:39] VERBOSE[9584] res_pjsip_registrar.c: Removed contact ‘sip:[email protected]:51620’ from AOR ‘100’ due to request

[2021-09-17 21:53:39] VERBOSE[9584] res_pjsip/pjsip_options.c: Contact 100/sip:[email protected]:51620 has been deleted

[2021-09-17 21:53:39] VERBOSE[9584] res_pjsip/pjsip_configuration.c: Endpoint 100 is now Unreachable

[2021-09-17 21:53:39] VERBOSE[14447] res_pjsip_registrar.c: Added contact ‘sip:[email protected]:51620’ to AOR ‘100’ with expiration of 3600 seconds

[2021-09-17 21:53:40] VERBOSE[14447] res_pjsip/pjsip_configuration.c: Endpoint 100 is now Reachable

[2021-09-17 21:53:40] VERBOSE[14447] res_pjsip/pjsip_options.c: Contact 100/sip:[email protected]:51620 is now Reachable. RTT: 73.343 msec

Thank You!
-Ryan

2

I think you will find that everything VOIP.MS has been broken for the last couple days.

3

Yes - That was definitely a headache! It seems to be back online now fortunately. This is a new installation with all new SIP phones. The VOIP.MS trunk is actually a backup for an FXO gateway (we have to keep using PSTN lines we are locked into a contract on for another year…)

Anyway - the more pressing issue is these phones dropping off and coming back online. It almost looks like the phones are requesting to be de-registered but I can’t imagine why when the expiration is set to 3600s?

4

They also claimed to be back yesterday (not so much . . .) maybe wait a couple of days or move your numbers to someone else ?

5

I removed the trunk and added one from Twilio, which seemed to stay online just fine, but the phones are still going in and out of registration. :thinking:

6

Then that’s a different problem , probably Network/Firewall/NAT related

7

I thought so too- but what’s odd is I didn’t have this issue with a Polycom phone on the same network. It just began yesterday with these new devices. I did go from having 4 registered devices to about 15 but the server should be more than capable.

8

Practically, try use sngrep and tail the asterisk logs, that curtails the guessing .

9

I will give it a shot- thanks for the advice!

10

At the Asterisk command prompt, type
pjsip set logger on
which will include a SIP trace in the Asterisk log. This will show whether the device is actually unregistering. Beware that pjsip logger gets turned off by reloading or restarting Asterisk; turn it back on if you have made config changes.

Try changing the registration expiry in the phone from 3600 to e.g. 120 seconds. Assuming that this is shorter than the UDP timeout in the firewall, this will keep the NAT association open without depending on the incoming OPTIONS (qualify) requests.

Also, set Max Contacts for the extensions to e.g. 4, ensuring that a contact is not deleted because of a new registration request.

If you still have trouble, paste a segment of the Asterisk log at pastebin.freepbx.org and post the link here. The segment should be long enough to show two successive registrations for at least one of the Fanvil extensions. For example, paste 3 minutes of log, assuming a 120 second registration expiry.

11

Hi Stewart,
Thank you for the recommendations!
I changed all of my extensions to have:
Max Contacts - 5

I then set the registration expiration to 120 on each phone. Believe it or not this made the messages appear even more often in the log file.

I tried registration with plain UDP, STUN and now I have all phones set up with TLS/SRTP to try and get around UDP/NAT issues and it’s still happening. I am so confused.

I don’t have access to a computer right now, but will upload to pastebin later on today.

Thanks again!

12

Hi Stewart-
Here is that log - lots here in a few minutes. I think I captured at least 2 registrations. This is in TLS now, I will need to wait until Monday when I am back in the office to switch back to UDP if necessary, but like I said I saw the exact same result with UDP as with TLS.

Thanks again for the help!!

https://pastebin.freepbx.org/view/fefd97ca

13

See REGISTER request starting on line 196:

[2021-09-18 12:57:34] VERBOSE[2211] res_pjsip_logger.c: <--- Received SIP request (836 bytes) from TLS:XXX.XXX.XXX.XXX:8657 --->
REGISTER sip:pbx.distechnology.com SIP/2.0
Via: SIP/2.0/TLS XXX.XXX.XXX.XXX:2013;branch=z9hG4bK4797597001536929375;rport
From: Ryan - 103 <sip:[email protected]>;tag=5762133777
To: Ryan - 103 <sip:[email protected]>
Call-ID: [email protected]
CSeq: 6 REGISTER
Contact: <sip:[email protected]:2013;transport=tls>
Authorization: Digest username="103", realm="asterisk", nonce="1631984254/4e89ab6611f17f3f18574a60574210ae", uri="sip:pbx.distechnology.com", response="ed0951855d4f0994c9cb5fe5fa360aa0", algorithm=MD5, cnonce="ebcb82d2", opaque="68c51f9958af720d", qop=auth, nc=00001126
Max-Forwards: 70
Expires: 0
Supported: path
User-Agent: Fanvil X3SG 2.4.8 0c:38:3e:40:1e:5b
Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE
Content-Length: 0

The Expires: 0 on line 206 is an explicit unregister request from the phone, just before it re-registers I know nothing about Fanvil, but it is not normal for phones to do that. AFAIK (other than modifying the source code) there is no way to configure Asterisk to ignore the request. With luck, there is a setting in the phone to not send these, or you can avoid them by upgrading the phone’s firmware to current (or conceivably by downgrading to a version before this ‘feature’ was introduced).

Possibly, the unregister is triggered by unexpected content in a SIP response. If so, I would expect that the phone’s syslog (at maximum verbosity) will have some clue as to what caused it to unregister.

14

How odd… I will try to downgrade the firmware, I just upgraded them all to the latest which was just released a few weeks back.

Thank you

15

Just wanted to provide an update-
I registered the same phones to another PBX hosted on the same VPS and am not having the issue. I am trying to figure out what the difference is and I will report back if/when I figure it out. In the meantime I am working with Fanvil customer service to see if they can provide any insight.

16

Unexplainably, it is resolved. I restarted Asterisk for the third time, allowed all of the phones to register again, and the issue is no longer occurring. I will continue to monitor. Thanks again for the help.

17

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.