SIP Trunk outages " 408 Request Timeout/REGISTER from local"

[Tom Z]

Hi,

I have a 3cx instance running on a Intel NUC at a customer, that faces random outages of the SIP-Trunk.
For months I'm trying to find a reason for the completely random outages, that are not related to any other infrastructure issue whatsoever.

The Log tells me the same story every time:

07/17/2021 4:05:01 PM - [CM504005]: Registration failed for: Lc:10001(@PROVIDER[<sip:[email protected]:5060/TCP>]); Cause: Cause: 408 Request Timeout/REGISTER from local
07/17/2021 3:59:28 PM - [CM504005]: Registration failed for: Lc:10001(@PROVIDER[<sip:[email protected]:5060/TCP>]); Cause: Cause: 408 Request Timeout/REGISTER from local
07/17/2021 3:53:56 PM - [CM504005]: Registration failed for: Lc:10001(@PROVIDER[<sip:[email protected]:5060/TCP>]); Cause: Cause: 408 Request Timeout/REGISTER from local

After 7-10 Minutes the connection works again with no issues whatsoever.

Everything around and including the 3cx is monitored, there are no other problems inside the network.
DURING the outage when I connect to the 3cx appliance with ssh I can resolv the providers DNS-Name, ping both the DNS-Name and the IP-Adress and even telnet to port 5060 with success. Rebooting the box resolves the issue.

First I thought it might be some kind of block ist, but iptables is empty and the connection works as I mentioned before.
Next I thought the 3cx itself maybe blocks inside the application, but there is no entry in the ip blocklist either.

In the very begining I had the 3cx running inside a virtual machine, then I wanted to eliminate every possible source of failure and used dedicated hardware.
I checked layer 2-4 closely and monitored every network device on the way.

We even changed the SIP trunk provider to a 3cx certified provider.

Nothing really helped and I'm out of options at the moment.
In my opinion there seems to be a bug inside the pbx, but from my point of view 3cx offers no debugging except the logviewer.

The only thing I could find is the 3cxSystemService.log which states the following during this timeframe:

2021/07/17 15:54:11.881|637|0069|Excpt|System.Threading.Tasks.TaskCanceledException: A task was canceled.
at MailKit.Net.SocketUtils.ConnectAsync(String host, Int32 port, IPEndPoint localEndPoint, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.Net.SocketUtils.ConnectAsync(String host, Int32 port, IPEndPoint localEndPoint, Int32 timeout, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.MailService.ConnectSocket(String host, Int32 port, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.Net.Smtp.SmtpClient.ConnectAsync(String host, Int32 port, SecureSocketOptions options, Boolean doAsync, CancellationToken cancellationToken)
at TcxMail.MailTemplateSender.Send(MimeMessage email)
at TcxMail.MailTemplateSender.Send(XDocument template, Func`2 getParameter, String mailTo, IEnumerable`1 attachments, Func`2 needEncode)
at _3cxSystemService.EventNotifier.ErrorEventNotifier.SendPbxErrorCodeEmail(Int32 evtId, Int32 type, DateTime dt, String source, String message, String[] prms)

2021/07/17 15:56:11.889|637|0045|Excpt|System.Threading.Tasks.TaskCanceledException: The operation was canceled.
at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.DecompressionHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at InstanceManagerConnector.ServiceClient.ServiceClient.EventAsync(String minion_id, EventObject body, CancellationToken cancellationToken)
at _3cxSystemService.EventNotifier.ErrorEventNotifier.<>c.<<ProcessNewEvents>b__25_0>d.MoveNext()

2021/07/17 15:56:26.900|637|0045|Excpt|System.Threading.Tasks.TaskCanceledException: A task was canceled.
at MailKit.Net.SocketUtils.ConnectAsync(String host, Int32 port, IPEndPoint localEndPoint, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.Net.SocketUtils.ConnectAsync(String host, Int32 port, IPEndPoint localEndPoint, Int32 timeout, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.MailService.ConnectSocket(String host, Int32 port, Boolean doAsync, CancellationToken cancellationToken)
at MailKit.Net.Smtp.SmtpClient.ConnectAsync(String host, Int32 port, SecureSocketOptions options, Boolean doAsync, CancellationToken cancellationToken)
at TcxMail.MailTemplateSender.Send(MimeMessage email)
at TcxMail.MailTemplateSender.Send(XDocument template, Func`2 getParameter, String mailTo, IEnumerable`1 attachments, Func`2 needEncode)
at _3cxSystemService.EventNotifier.ErrorEventNotifier.SendPbxErrorCodeEmail(Int32 evtId, Int32 type, DateTime dt, String source, String message, String[] prms)

As far as I can read this it's just the error handling.
There is no log file in either the /var/lib/Instnace1 or /var/lib/Data/logs folder that holds any information for the timeframe of the outages.

No registers are leaving the 3cx box during the timeframe where the error occurs.
I checked this by monitoring with tcpdump on the box itself, the switch and the firewall.

After some time the 3cx starts retransmitting registers again, the trunk goes up and everything works perfectly fine.
From the providers side it looks like the box just silently died and suddenly came back.

I'm out of ideas.

 

[Evolute IT]

Alright, that's a big one.

Few questions:

1. Where is the PBX hosted? And are you on latest version?

2. What DNS servers are set on the machine?

3. What is your provider now, and the old one?

As for the log you see, it seems to be an error during sending of an email (maybe voicemail or missed call notifications.) It seems that error was also caused by a Request Timeout.

This all tells me you got an issue with the internet connection of that PBX.

 

[Tom Z]

Hi there,

thanks for your reply.

ad 1) pbx is "self-hosted" like I already stated - it's running on dedicated Hardware - an Intel NUC.
Latest stable version

ad 2) The DNS-Servers used are the Domain Controller of the network and the Firewalls DNS.
There are no DNS-Outages during the 3cx Outage.

ad 3) Previous: aicall - small non-certified provider from Austria for cable-internet providers
now: hostprofis: 3cx certified provider.

Regarding your feeling about the "internet connection problem":
I'm debuggin the problem via VPN connecting from the internet to the firewall and further down the path.
I can connect via VPN and SSH into the box on the local network and reach the webinterface of the 3cx via https during the outage of the sip-trunk.

I can ping the sip-trunk-provider on the DNS-name and IP-Adress during the outage.
I can even telnet on port 5060 (the configured port of the sip trunk) to the sip trunk provider and I get a response.

No other client on the network has internet connection problems while the 3cx has problems registering the trunk.
Even the 3cx dedicated hardware has no problems connecting to the sip trunk provider during the outage, but the registering fails.

This tells me that it's a application layer problem, since the layers 2, 3, and 4 work properly.
As I wrote before: the 3cx tells me 408 register LOCAL but no registrers are leaving the 3cx torwards the firewall or the provider.

So the 3cx thinks it lost the connection to the trunk but registers are not leaving the 3cx.
Are there any other logs where I can debug this?

 

[YiannisH_3CX]

Hi @Tom Z

I have a theory which might explain your issue and why you are not seeing any register messages leaving the PBX.
I see from your original post that your trunk registers via TCP. Is that on purpose or do you have the transport protocol inside the trunk settings set to ANY?

If the transport is set to ANY then I would recommend switching to UDP if your provider supports it. You can do so by navigating into your trunk settings, Options tab and find the "Transport Protocol" option. Switch it to UDP (if your provider supports it) and click the OK button on the top to save your settings.

What I suspect is happening is that the registration is initially happening using UDP. At some point registration fails and the PBX switch to TCP to try all options. When switching to TCP the PBX will first try to establish a TCP connection before sending a register message. If that fails then you will not see registration messages. Then the PBX will also try TLS will cause the same issue. When the PBX runs out of transports and IPs to try it will pause for 2 minutes (so it does not get blacklisted from the provider) and resume from the top after that. That is why it works again after a few minutes.

Try switching to one protocol based on what the provider supports and see if that resolves your issue.

Now regarding the error you are seeing in the system service log, it looks like an issue with the mailer trying to send out the notification email but fails. Check your email settings and see if there is an issue there.

Are there any other logs where I can debug this?

The PBX offers an Event log, An Activity log, an inbuild packet capture function and logs for all services which can be downloaded through the Activity log menu. You can also create a support info bundle with all information needed from the Support tab on the top right of the management console. Additionally you can also download the Bin Log Viewer for more details. You can also control the logging level of the PBX for maximum details. If that is not enough you can also contact a 3CX partner to assist with the troubleshooting.

 

[Tom Z]

Nice that helps a lot.
I will try to create the bundle and check the bin log viewer, to get any information supporting your explanation.

Since hostprofis is a certified provider the settings all come directly from 3cx and should be flawless.
Transport is set to TCP, I can in fact establish a successful TCP connection via telnet even thou 3cx tells me it fails.

That's why I still believe it's a issue inside the 3cx application, but I will look into the logs you told me about to dig deeper.

Thanks a lot I will try to come back to this thread with more information.

 

[YiannisH_3CX]

If the provider is Hostprofis then yet the transport should be set to TCP by default. They do also support UDP so you can still try it and see if that resolves your issue.

I can in fact establish a successful TCP connection via telnet even thou 3cx tells me it fails.

Run a packet capture when the issue occurs and filter via the providers IP. You should be able to see all traffic between the PBX and the provider. If the PBX is trying to establish a TCP connection and fails you should see that also.

 

[Tom Z]

I am dumping the traffic to tcp/5060 on a mirrorport on the switch. We will see.
Switching from provider default-settings is my last resort, since I already had problems getting support with a non-certified sip-trunk-provider in the past. To be honest I fully understand, but don't like the 3cx policy regarding support for non-certified trunk providers.

As I googled around about 3cx I found lots of german people with problems regarding sip trunk stability.
One guy solved it by rebooting the 3cx every day, which I will do as well starting off today.

 

[YiannisH_3CX]

Switching from provider default-settings is my last resort, since I already had problems getting support with a non-certified sip-trunk-provider in the past. To be honest I fully understand, but don't like the 3cx policy regarding support for non-certified trunk providers.

The point of the switch to UDP is to test and see if that is causing the issue and not to run a non supported setup. If the issue is identified then we can narrow down the cause and propose a solution. This may very well be a firewall issue. The trick is to identify it.

 

[Tom Z]

No problem establishing a TCP connection during the outage.
I can in fact manually register on the trunk, while 3cx thinks it's not reachable. From the same box, 3cx is running on.
It's a problem inside the application. Somehow 3cx thinks the trunk is unreachable, but everything is perfectly fine.

Layer 1: no problem - nothing changed
Layer 2: no problem - dump indicates no problems
Layer 3: no problem - dump indicates no problems, monitoring indicates no problems, tracerouting the trunk is possible with no errors.
Layer 4: no problem - dump and monitoring as well as manual testing with telnet indicate no problems
Layer 7: 3cx no infos inside the logs except "unreachable"

Rebooting 3cx every day seems to have resolved the problem.
So it's some kind of runtime problem inside the application.

I will leave it like that till the new version is out.
In case this problem is stillt here in V18 I would appreciate some dev support.

 

[Scot Busby]

I have a similar issue with my SIP trunks randomly dropping and re-registering with the SIP provider (certified 3CX SIP provider). They have been running flawlessly for a long time and this happened about 5 days ago (give or take) that they suddenly started dropping calls and re-registering. Over the past 5 days, I have reached out to our SIP provider - who indicates they see nothing wrong, our ISP (who monitored the line for noise and even came out on two occasions to replace and add connections and cables). I have rebooted ALL infrastructure. and ensured we are running on the latest version of firmware on all our data switches (Cisco). Our 3CX is on-premise and is v16.0.8.9 (although under Product details page, it shows 16.0.9) running and is running on Windows Server 2016.
I removed and re-added all my trunks using the templates in the system and followed the guide from the SIP provider precisely (again, this was all working well before, but grasping at straws). The logs show a DNS error, so I made some changes to the DNS configured on the server and even tried the DNS servers recommended by the SIP provider, however, I still get DNS errors in 3CX. See the sample below. I am not having any other network or connectivity issues when this happens of which I'm aware. I thought I might ask here - on this thread, since it was similar (not exactly, but similar) to my issue.

 

[Scot Busby]

I have a similar issue with my SIP trunks randomly dropping and re-registering with the SIP provider (certified 3CX SIP provider). They have been running flawlessly for a long time and this happened about 5 days ago (give or take) that they suddenly started dropping calls and re-registering. Over the past 5 days, I have reached out to our SIP provider - who indicates they see nothing wrong, our ISP (who monitored the line for noise and even came out on two occasions to replace and add connections and cables). I have rebooted ALL infrastructure. and ensured we are running on the latest version of firmware on all our data switches (Cisco). Our 3CX is on-premise and is v16.0.8.9 (although under Product details page, it shows 16.0.9) running and is running on Windows Server 2016.
I removed and re-added all my trunks using the templates in the system and followed the guide from the SIP provider precisely (again, this was all working well before, but grasping at straws). The logs show a DNS error, so I made some changes to the DNS configured on the server and even tried the DNS servers recommended by the SIP provider, however, I still get DNS errors in 3CX. See the sample below. I am not having any other network or connectivity issues when this happens of which I'm aware. I thought I might ask here - on this thread, since it was similar (not exactly, but similar) to my issue.
View attachment 23106

Just to close the loop here, this has been resolved. The firewall update setting had UPD Flood Protection enabled and my SIP provider uses UDP, so this caused occasional packet drops and the random nature of the disconnects. All seems good now.

 

[YiannisH_3CX]

@Tom Z

If the issue persists then I would recommend creating a ticket with our support department so they can take a look at the system and determine what the issue is.

@Scot Busby

Glad to see that everything is fine now