PBX throws 500 error - only one phone "registers" per service restart

[dhartley]

Has anyone else had issues with phones not "registering" as new devices are connected?
We have several clients running networks nearly identical to this one, but only this one has issues.
3CX PBX in Azure, SBC on prem. Phones in the same network as the SBC.

Phone powers on, is detected by the SBC, is registered in 3CX & the SBC throws a 500 internal server error. Everything appears to continue working as normal.
However, any new phone connected to the network is not detected and not registered. Restarting the 3CXSBC service fixes the issue - but after one more phone is registered, the issue happens again.
Long story short, I have to restart the SBC service every time a new phone is connected if I want the phones to show up as 'new' in the phone list in 3CX. This particular project has 60+ handsets, so that's not really an option. Has anyone seen this happen before?

Testing with Yealink T57W phones, SBC running Debian 9 (SBCs with a vanilla debian install as well as the 3CX ISO have the same issue on this network). PBX running debian 9, not created with pbxexpress. I suspect the PBX is the issue as some of the logs show the error is happening there and being propagated back down to the SBC.

Relevant log entries (IP addresses have been obscured as well as the PBX fqdn):
SBC:

STACK | 20200701-114117.503 | 3CX | SBC | 140266088777472 | security.cpp:851 | Packet of size 616 is at pos 1, immediate send!
STACK | 20200701-114117.503 | 3CX | SBC | 140266088777472 | security.cpp:183 | TLS PROT: TX version=0, content=0x100 (SSL3_RT_HEADER), msg=0x17 (Unknown), len=5
STACK | 20200701-114117.503 | 3CX | SBC | 140266088777472 | security.cpp:383 | TLS DATA: TX 616 bytes
INFO | 20200701-114117.504 | 3CX | SBC | 140266088777472 | BridgeTunSip.cpp:152 | TX tun:
SUBSCRIBE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP x.x.x.12:5059;branch=z9hG4bK1554681625
Max-Forwards: 69
Record-Route: <sip:[email protected]:5060;user=proxy;tnlid=sbc.bc1d2852>
Contact: <sip:[email protected]:5059>
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=1554681625
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Expires: 0
Accept: application/url
User-Agent: Yealink SIP-T57W 97.84.0.35
Event: ua-profile;profile-type="device";vendor="yealink";model="SIP-T57W";version="97.84.0.35"
Content-Length: 0


STACK | 20200701-114117.622 | 3CX | SBC | 140266154735808 | security.cpp:423 | TLS (state=3) reading, qsize=0
STACK | 20200701-114117.622 | 3CX | SBC | 140266154735808 | security.cpp:183 | TLS PROT: RX version=0, content=0x100 (SSL3_RT_HEADER), msg=0x17 (Unknown), len=5
STACK | 20200701-114117.622 | 3CX | SBC | 140266154735808 | security.cpp:434 | TLS DATA: RX 4 bytes of header
STACK | 20200701-114117.622 | 3CX | SBC | 140266154735808 | security.cpp:453 | TLS DATA: RX 467/467 bytes of frame
STACK | 20200701-114117.623 | 3CX | SBC | 140266154735808 | security.cpp:1057 | TCP Enqueued packet of 467 bytes, qsize=1
DEBUG | 20200701-114117.623 | 3CX | SBC | 140266154735808 | TunnelTcp.cpp:549 | RX TCP Sip0
INFO | 20200701-114117.623 | 3CX | SBC | 140266154735808 | BridgeTunSip.cpp:28 | RX tun:
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/UDP [::ffff:y.y.y.142]:55444;branch=z9hG4bK-524287-1---tunneltid;rport;tnlid=sbc.bc1d2852
Via: SIP/2.0/UDP x.x.x.12:5059;branch=z9hG4bK1554681625
Record-Route: <sip:[email protected]:5060;user=proxy;tnlid=sbc.bc1d2852>
To: <sip:[email protected]>;tag=13e30818
From: <sip:[email protected]>;tag=1554681625
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Content-Length: 0


INFO | 20200701-114117.623 | 3CX | SBC | 140266154735808 | BridgeSip.cpp:61 | TX loc:
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/UDP x.x.x.12:5059;branch=z9hG4bK1554681625
Record-Route: <sip:[email protected]:5060;user=proxy;tnlid=sbc.bc1d2852>
To: <sip:[email protected]>;tag=13e30818
From: <sip:[email protected]>;tag=1554681625
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Content-Length: 0

PBX: (3CXTunnel log)

11:41:17.525|7f43b0433700|Trace|Bridge.cpp(381): Processing SIP message (tid=1554681625) from SIP stack 127.0.0.1:5080
11:41:17.525|7f43b0433700|Messg|Bridge.cpp(382): Msg:
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/UDP 127.0.0.1:5080;branch=z9hG4bK-524287-2---1554681625;rport=5080
Via: SIP/2.0/UDP [::ffff:y.y.y.142]:55444;branch=z9hG4bK-524287-1---tunneltid;rport;tnlid=sbc.bc1d2852
Via: SIP/2.0/UDP x.x.x.12:5059;branch=z9hG4bK1554681625
Record-Route: <sip:[email protected]:5080;user=proxy;uri=sbc.bc1d2852>
Record-Route: <sip:[email protected]:5060;user=proxy;tnlid=sbc.bc1d2852>
To: <sip:[email protected]>;tag=13e30818
From: <sip:[email protected]>;tag=1554681625
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Content-Length: 0

11:41:17.525|7f43b0433700|Trace|Bridge.cpp(734): Process local response: 500 Server Internal Error / SUBSCRIBE
11:41:17.525|7f43b0433700|Trace|Bridge.cpp(435): Tunnel to sbc.bc1d2852 is selected for SIP message (tid=1554681625)
11:41:17.525|7f43b0433700|Debug|ConnMgr.cpp(1584): 6<-::ffff:y.y.y.142:55444:22: deliver REL 30706953 [471]
11:41:17.526|7f43b2437700|Debug|Multiplexer.cpp(829): 6<-::ffff:y.y.y.142:55444:22: sent Sip0(471)
11:41:17.664|7f43b1c36700|Debug|ConnMgr.cpp(1584): 6<-::ffff:y.y.y.142:55444:22: deliver UNR 474e4950 [8]

 

[cobaltit]

Haven't seen that issue before. Please confirm 3CX version and SBC version. Also the latest Yealink firmware (assuming you are current with 3CX) is 96.85.0.5 so you'd want to get on that firmware as well. Just to rule it out as an issue.

 

[dhartley]

PBX on 16.0.619, SBC was on the latest stable earlier, and have upgraded to the current beta (16.1.152) to test, same issue.
Deployed a new VM for the PBX and restored a 3cx backup - the new PBX VM has the same issue. So, not having much luck.

I downloaded the latest "supported" firmware for the phones this afternoon, only to find that the phone's already running that. I'll give the later version a go just to see what happens.