Monday, September 29, 2014

SIPPROXY_E_CONNECTION_UNKNOWN_SERVER (TLS negotiation error)

Recently I encountered a very strange issue:

After installation another Lync Frontend Server, in this case a SBS. The Federation was broken.
Incoming via the Edge Server everything looked fine. Meaning, incoming Federation request, e.g. presence or IM, as well as remote access from users hosted on this SBS were working correctly.
But all outing communication to federated partners didn't work at all.
After using the OCSLogger and analyzing the logs in SNOOPER, I saw an error message: The peer is not a configured server on this network interface and SIPPROXY_E_CONNECTION_UNKNOWN_SERVER
coming along with another message: winsock-info="The peer forced closure of the connection"
I used the RUST tool internally verifying the SBS certificate, it was correct. Even requesting the certificate again didn't help at all. Even I imported the Topology on the Edge server again!
What this clearly explains was, if the SBS was presenting it's certificate, it didn't work. If the Edge Server was presenting it's internal certificate to the SBS, the SBS was accepting it.
This is because in the TLS NEGOTIATION message, I identified the peer:
Local-IP: 172.28.248.131:5061 (EDGE INTERNAL)
Peer-IP: 172.28.10.10:59238 (SBS)
Since the SBS had a high port, it must have been the sender.



Resolution:
I had to restart the SBS Frontend Service and the Edge Access Service. This solved the issue.

BUG:
I believe this is a bug, normally if the certificate is assigned, even during the service using it running, the service should query the certificate directly from the certificate store. but in whatever circumstance it is not doing so correctly. This is why you have to restart services, at least on the SBS, the server newly established in your environment.

Note:
A similar issue occurs, e.g. if you setup the Exchange OWA integration for presence and IM. IF the Exchange Server is not trusted server in the Topology, you will find a similar issue on the Frontend server.

---------------------------------------------------------------------------------------

For your better understanding, here are some traces of this case:
Starting with the EDGE Server first


TL_INFO(TF_CONNECTION) [0]0D14.06B4::09/29/2014-08:26:30.134.0007e9ae (SIPStack,SIPAdminLog::WriteConnectionEvent:SIPAdminLog.cpp(454))[2855934840] $$begin_recordSeverity: information
Text: TLS negotiation started
Local-IP: 172.28.248.131:5061
Peer-IP: 172.28.10.10:59238
Connection-ID: 0x38F1600
Transport: TLS
$$end_record
 
TL_INFO(TF_PROTOCOL) [1]0D14.06B4::09/29/2014-08:26:30.197.0007ea1e (SIPStack,SIPAdminLog::ProtocolRecord::Flush:ProtocolRecord.cpp(265))[2485748977] $$begin_recordTrace-Correlation-Id: 2485748977
Instance-Id: 591B48
Direction: incoming;source="internal edge";destination="external edge"
Peer: 172.28.10.10:59238
Message-Type: request
Start-Line:
NEGOTIATE sip:127.0.0.1:5061 SIP/2.0
From: sip:sbs01.domain.local;tag=8D4E6E25C6A1BCE8C0AA4EBC780ED3E6
To: sip:LYNCEDGE01.domain.local
Call-ID: A0405E94346142207A1C
CSeq: 1 NEGOTIATE
Via: SIP/2.0/TLS 172.28.10.10:59238;branch=z9hG4bK1B170C12.50835B4246C5B624;branched=FALSE
Max-Forwards: 0
Content-Length: 0
Require: ms-compression
ms-negotiate-data: LZ77-64K
Supported: NewNegotiate,OCSNative,ECC,IPv6,TlsRecordSplit
Server: RTC/5.0
 
$$end_record
 
TL_ERROR(TF_CONNECTION) [1]0D14.06B4::09/29/2014-08:26:30.197.0007ea45 (SIPStack,SIPAdminLog::WriteConnectionEvent:SIPAdminLog.cpp(389))[2855934840] $$begin_recordSeverity: error
Text: The peer is not a configured server on this network interface
Peer-IP: 172.28.10.10:59238
Transport: TLS
Result-Code: 0xc3e93d6a SIPPROXY_E_CONNECTION_UNKNOWN_SERVER
Data: fqdn="sbs01.domain.local"
$$end_record
 
 
Having a look into the SBS log here:
 
TL_INFO(TF_CONNECTION) [0]1DAC.056C::09/29/2014-08:47:01.986.000007a2 (SIPStack,SIPAdminLog::WriteConnectionEvent:SIPAdminLog.cpp(454))[1674556973] $$begin_recordSeverity: information
Text: TLS negotiation started
Local-IP: 172.28.10.10:60309
Peer-IP: 172.28.248.131:5061
Connection-ID: 0x13B00
Transport: TLS
$$end_record
 
 
TL_INFO(TF_DIAG) [1]1DAC.056C::09/29/2014-08:47:02.064.000007a9 (SIPStack,SIPAdminLog::WriteDiagnosticEvent:SIPAdminLog.cpp(802))[612839171] $$begin_recordSeverity: information
Text: Routed a locally generated request
SIP-Start-Line: NEGOTIATE sip:127.0.0.1:5061 SIP/2.0
SIP-Call-ID: 57883DA78E69E21BFB83
SIP-CSeq: 1 NEGOTIATE
Peer: LYNCEDGE01.domain.local:5061
$$end_record
 
 
TL_INFO(TF_PROTOCOL) [1]1DAC.056C::09/29/2014-08:47:02.064.000007aa (SIPStack,SIPAdminLog::ProtocolRecord::Flush:ProtocolRecord.cpp(265))[612839171] $$begin_recordTrace-Correlation-Id: 612839171
Instance-Id: 2835
Direction: outgoing;source="local"
Peer: LYNCEDGE01.domain.local:5061
Message-Type: request
Start-Line: NEGOTIATE sip:127.0.0.1:5061 SIP/2.0
From: sip:sbs01.domain.local;tag=A6CBF413214DBEF0CAE0CF071DBF904D
To: sip:LYNCEDGE01.domain.local
Call-ID: 57883DA78E69E21BFB83
CSeq: 1 NEGOTIATE
Via: SIP/2.0/TLS 172.28.10.10:60309;branch=z9hG4bK650D3356.5FCB69DE77B72B06;branched=FALSE
Max-Forwards: 0
Content-Length: 0
Require: ms-compression
ms-negotiate-data: LZ77-64K
Supported: NewNegotiate,OCSNative,ECC,IPv6,TlsRecordSplit
Server: RTC/5.0
$$end_record
 
 
TL_ERROR(TF_CONNECTION) [0]1DAC.056C::09/29/2014-08:47:02.095.000007ae (SIPStack,SIPAdminLog::WriteConnectionEvent:SIPAdminLog.cpp(460))[1674556973] $$begin_recordSeverity: error
Text: Receive operation on the connection failed
Local-IP: 172.28.10.10:60309
Peer-IP: 172.28.248.131:5061
Peer: LYNCEDGE01.domain.local:5061
Connection-ID: 0x13B00
Transport: M-TLS
Result-Code: 0x80072746
Data: fqdn="LYNCEDGE01.domain.local:5061";ip-address="172.28.248.131";peer-type="InternalServer";winsock-code="10054";winsock-info="The peer forced closure of the connection"
$$end_record
 
 
TL_INFO(TF_PROTOCOL) [0]1DAC.056C::09/29/2014-08:47:02.095.000007be (SIPStack,SIPAdminLog::ProtocolRecord::Flush:ProtocolRecord.cpp(265))[4039661650] $$begin_recordTrace-Correlation-Id: 4039661650
Instance-Id: 2838
Direction: outgoing;source="local"
Peer: 172.28.91.102:6861
Message-Type: response
Start-Line: SIP/2.0 504 Server time-out
From: "Pött Thomas"<sip:thomas.poett@domain.de>;tag=e08f10ad81;epid=1d691e13e1
To: <sip:xyz@microsoft.com>;tag=A6CBF413214DBEF0CAE0CF071DBF904D
Call-ID: 9ef08610a5054b66a1040bef20d1b564
CSeq: 1 SUBSCRIBE
Via: SIP/2.0/TLS 172.28.91.102:6861;ms-received-port=6861;ms-received-cid=1700
Content-Length: 0
ms-diagnostics: 1039;reason="Failed to complete TLS negotiation with a peer server";fqdn="LYNCEDGE01.domain.local:5061";ip-address="172.28.248.131";peer-type="InternalServer";winsock-code="10054";winsock-info="The peer forced closure of the connection";source="SBS02.domain.local"
$$end_record


No comments:

Post a Comment