Solved Yealink T48S - Intermittent No Service - Losing Registration

[robert788]

I have about 200 Yealink T48S phones and a number of them will randomly unregister and then re-register. It's hard to track down exactly how long they go unregistered but many times the user will go to make a phone call and everything is grey/says no service and they aren't able to make a call. Sometimes a user will receive a call and realize it rang to their phone app and their desk phone didn't ring (because it was unregistered). Some users will see a phone go No Service and then within 20-30 seconds it will come back/re-register and be fine.

I am starting to wonder if this issue is related to running the latest release of 3CX. The server was upgraded a couple months ago and that is around the same time this issue started happening. I am not sure what the process is to downgrade 3CX to test that? I did go through and downgrade the Yealink firmware to older releases that we were running before this started happening. I loaded several phones with 66.84.0.125 and 66.84.0.90 to see if that helped and it still occurs on these older releases of phone firmware. The majority of phones are running the 66.85.0.5 firmware and also have this same issue.

I have downloaded the Log Viewer and the support files to view the logs and I can't see any events that relate to phones registering and unregistering. I am not sure if I up the log level to Verbose if that will yield any results unless I let it run in that mode all day. Being that it is on AWS, I could up the resources just for one day. I can't really turn off the logging/restart services during normal business hours, so I would be leaving it in verbose mode all day.

As far as the network connection, the phones are on a separate VLAN locally and there is an IPSEC tunnel between our building and AWS. In 3CX, all the extensions are setup as local LAN and they've been working without this issue for over a year.

Any thoughts or tips on troubleshooting this issue would be greatly appreciated!


3CX Version - Annual Pro 16.0.7.1078
Server OS, Windows Server 2019
Is the 3CX Server Hosted and where? Yes on AWS
IP Phone Make/Model/Firmware - Yealink T48S - various firmware (in my notes)
Provisioning Method: Local
Trunk Provider - N/A
Has the Firewall Checker passed: YES
Are custom Phone Templates being used: NO

 

[cobaltit]

Are the phones provisioned via IP or DNS for the local provisioning? And what are they using for DNS?

 

[robert788]

Glad you asked, that is another interesting part of this. Initially I had all phones set to DNS provisioning and they are all using a DNS server that is local on the network. The DNS server is also used for AD and all internet traffic, so I feel confident that the DNS server is functioning 100% of the time. I did pull some logs from the phones that have the issue and here's a snippet of what I see when it fails. In this example I replaced my actual hostname with "my.3cx.server". The phone's ip is 10.96.20.153 and the 3CX server ip is 10.127.105.16. So at first glance it looks like DNS is failing, but I know the DNS server is working when these fail. In order to test, I changed several phones over to provision to the IP of 3CX instead of hostname and they still fail, they just don't complain about DNS failures. The second snippet is what I see on a phone provisioned by IP right after it tries to send a REGISTER to 3CX. I have other devices that register to 3CX, overhead paging gateways, ATA's, softphones, and to this point I haven't seen the same type of behavior. I am just trying to determine whether it has anything to do with 3CX or whether it's a Yealink issue, or possibly some strange network issue. I did have a user tell me that there phone was in No Service for 30 minutes recently, although I am not sure if that was one continuous outage or whether it was multiple instances of it failing like this.

<131>Dec 31 09:24:52 sua [578.649]: REG <3+error > [000] <AEM> code=0x04000000, rid=2, reason=-1,'Register request no response!'
<131>Dec 31 09:24:52 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:05 sua [578.649]: DNS <3+error > [SIP] <AEM> code=0x04030100, target=my.3cx.server, type=1, reason='Timeout while contacting DNS servers'
<131>Dec 31 09:25:05 sua [578.649]: SUA <3+error > [000] DNS resolver fail, unknown destination...
<131>Dec 31 09:25:05 sua [578.648]: DLG <3+error > [000] host invalid
<131>Dec 31 09:25:05 sua [578.648]: DLG <3+error > [000] <AEM> code=0x04030000, cb_transport_error (id=110), target=0.0.0.0:0
<131>Dec 31 09:25:05 sua [578.649]: SUB <3+error > [000] <AEM> code=0x04020000, sid=65540, type=49(blf), [email protected]
<131>Dec 31 09:25:05 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:05 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:05 sua [578.649]: DNS <3+error > [SIP] <AEM> code=0x04030100, target=my.3cx.server, type=1, reason='Timeout while contacting DNS servers'
<131>Dec 31 09:25:05 sua [578.649]: SUA <3+error > [000] DNS resolver fail, unknown destination...
<131>Dec 31 09:25:05 sua [578.648]: DLG <3+error > [000] host invalid
<131>Dec 31 09:25:05 sua [578.648]: DLG <3+error > [000] <AEM> code=0x04030000, cb_transport_error (id=108), target=0.0.0.0:0
<131>Dec 31 09:25:05 sua [578.649]: SUB <3+error > [000] <AEM> code=0x04020000, sid=65544, type=49(blf), [email protected]
<131>Dec 31 09:25:05 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:05 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:07 sua [578.649]: DNS <3+error > [SIP] <AEM> code=0x04030100, target=my.3cx.server, type=1, reason='Timeout while contacting DNS servers'
<131>Dec 31 09:25:07 sua [578.649]: SUA <3+error > [000] DNS resolver fail, unknown destination...
<131>Dec 31 09:25:07 sua [578.648]: DLG <3+error > [000] host invalid
<131>Dec 31 09:25:07 sua [578.648]: DLG <3+error > [000] <AEM> code=0x04030000, cb_transport_error (id=109), target=0.0.0.0:0
<131>Dec 31 09:25:07 sua [578.649]: SUB <3+error > [000] <AEM> code=0x04020000, sid=65542, type=49(blf), [email protected]
<131>Dec 31 09:25:07 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:07 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=2
<131>Dec 31 09:25:24 sua [578.649]: SUB <3+error > [000] <AEM> code=0x04020002, sid=65539, sub response handle, type=48(mwi), [email protected]
<131>Dec 31 09:25:36 sua [578.649]: DNS <3+error > [SIP] <AEM> code=0x04030100, target=my.3cx.server, type=1, reason='Timeout while contacting DNS servers'
<131>Dec 31 09:25:36 sua [578.649]: SUA <3+error > [000] DNS resolver fail, unknown destination...
<131>Dec 31 09:25:36 sua [578.648]: DLG <3+error > [000] host invalid
<131>Dec 31 09:25:36 sua [578.648]: DLG <3+error > [000] <AEM> code=0x04030000, cb_transport_error (id=113), target=0.0.0.0:0
<131>Dec 31 09:25:36 sua [578.649]: REG <3+error > [000] <AEM> code=0x04000000, rid=3, reason=-1,'Register request no response!'
<131>Dec 31 09:25:36 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=3
<131>Dec 31 09:26:21 sua [578.649]: DNS <3+error > [SIP] <AEM> code=0x04030100, target=my.3cx.server, type=1, reason='Timeout while contacting DNS servers'
<131>Dec 31 09:26:21 sua [578.649]: SUA <3+error > [000] DNS resolver fail, unknown destination...
<131>Dec 31 09:26:21 sua [578.648]: DLG <3+error > [000] host invalid
<131>Dec 31 09:26:21 sua [578.648]: DLG <3+error > [000] <AEM> code=0x04030000, cb_transport_error (id=115), target=0.0.0.0:0
<131>Dec 31 09:26:21 sua [578.649]: REG <3+error > [000] <AEM> code=0x04000000, rid=4, reason=-1,'Register request no response!'
<131>Dec 31 09:26:21 sua [578.649]: DLG <3+error > [255] <AEM> code=0x04030006, rid=4
<131>Dec 31 09:26:41 sua [578.648]: DLG <3+error > [255] <AEM> code=0x04030001, Incoming 10.127.105.16 is not the trust address, discard...
<131>Dec 31 09:26:45 sua [578.648]: DLG <3+error > [255] <AEM> code=0x04030001, Incoming 10.127.105.16 is not the trust address, discard...
<131>Dec 31 09:26:49 sua [578.648]: DLG <3+error > [255] <AEM> code=0x04030001, Incoming 10.127.105.16 is not the trust address, discard...



<133>Dec 31 10:37:43 sua [1582]: DLG <5+notice> [000] End of Sending Packet :msglen = 614
<133>Dec 31 10:37:43 sua [1582]: NET <5+notice> [000] ===>>>> UDP socket 10.127.105.16:5060: send 614 bytes
<134>Dec 31 10:37:43 sua [1582]: DLG <6+info > [000] cb_nict_kill_transaction (id=44)
<134>Dec 31 10:37:43 sua [1582]: SUA <6+info > [000] ****eCore event0x0002)ECORE_REGISTRATION_FAILURE ****
<133>Dec 31 10:37:43 sua [1582]: DLG <5+notice> [000] Clear service route!
<132>Dec 31 10:37:43 sua [1582]: REG <4+warnin> [000] Register: no responser, server id:0
<133>Dec 31 10:37:43 sua [1582]: DLG <5+notice> [000] Clear service route!
<133>Dec 31 10:37:43 sua [1582]: DLG <5+notice> [000] Clear service route!
<133>Dec 31 10:37:43 sua [1582]: DLG <5+notice> [000] Release a terminated transaction
<133>Dec 31 10:37:43 sua [1582]: APP <5+notice> [SIP] linestatus lid:0, enable=1, tick=0, old_status:1, new_status:3
<134>Dec 31 10:37:43 sua [1582]: APP <6+info > [SIP] <IPC_p2my>:msg=0x00042103, wparam=0, lparam=0, id=Undefined recv msg string
<134>Dec 31 10:37:43 sua [1582]: APP <6+info > [SIP] <IPC_rcv >:msg:0x00042103, wparam:0x00000000, lparam:0x00000000, id:Undefined recv msg string
<134>Dec 31 10:37:43 sua [1582]: APP <6+info > [SIP] <IPC_broa>:msg=0x00040001, wparam=0, lparam=3, id=Undefined post msg string
<133>Dec 31 10:37:43 ipvp[1423.1423]: IPVP<5+notice> 663.835.642:Message=0x00040001(0x00000000+0x00000003+136)
<134>Dec 31 10:37:43 ipvp[1423.1423]: IPVP<6+info > 663.836.059:unknown msg,0x00040001,from 0xc801c860 0x00000000, 0x00000003
<134>Dec 31 10:37:43 GUI [1572:1572]: EMSG<6+info > 663.838.295:CEtlMsgHandler::OnETLMessage beg msg[262145] size[2] depth[0]
<134>Dec 31 10:37:43 GUI [1572:1572]: ACCU<6+info > 663.838.799:Line State Change AccountId:0, State:3
<134>Dec 31 10:37:43 GUI [1572:1572]: ACCU<6+info > 663.843.732:SetSyncSubscribeResult enable[0]

 

[cobaltit]

What upgrade was done a few minutes ago? Update 7 didn't come out till December so are you referring to Update 6 or was there some other upgrade?

This is looking like a network issue (it almost always is). Was anything on the switches or firewalls/VPN devices handling the VPN changed? If you have one phone that is problematic or has a helpful user try accessing the phone web interface and removing the provisioning URL. Then try changing the SIP account from UDP to TCP.

And I would upgrade all phones back to the latest supported release.

 

[robert788]

I checked the dates and SP6 was installed the end of September, and SP7 was installed December 10th. I believe the SP6 date more closely matches up with when the issue started. The network switches and firewall have had new updates installed in the same time period, and at least for the switches, I did roll them back to the older release just to try and rule out that was the cause. I can roll back the firewall firmware, but I would like to try other things first.

I will remove the provisioning url from one of the phones and change to TCP, but I do have DHCP handing out the provisioning url (option 66) so it might creep back in.

 

[robert788]

SOLVED: After additional network troubleshooting, I found the issue related to a Ubiquiti 16-XG in Layer 3 mode that was performing routing functions. Moved those functions to an Edgerouter and all is well.