Can't connect to Edge Server (Network Steve Forum)

Can't connect to Edge Server

I can't seem to get my Lync 2010 Edge server working correctly. I've followed the documentation as closely as I can.

I have: a single computer Edge Pool pointed to 2 front end servers using DNS load balancing.

The edge server has 2 network cards, one with an internal address with a persistent, static route to the network that the front end servers/clients live on.

The other interface has 3 external addresses bound to it, with a public IP address that uses NAT.

Using http://testexchangeconnectivity.com, it appears everything works up until the point that the endpoint needs to register to the internal FE pool. Here are the results:

July 11th, 2013 12:01pm

Can your edge servers resolve all of the names of your internal pool. It needs to be able to resolve both the Pool Name and Server Name FQDNs.

Thanks,

Richard

Free Windows Admin Tool Kit Click here and download it now

July 11th, 2013 12:07pm

Can your edge servers resolve all of the names of your internal pool. It needs to be able to resolve both the Pool Name and Server Name FQDNs.

Thanks,

R

July 11th, 2013 12:09pm

Confused by the "I forgot to add" part. If you added those to your host files after the services started, make sure to restart the services on Edge.

Otherwise, it might be time to look at a trace on the edge server and see what is happening when the tool/user attempts to login. Make sure you are seeing traffic in both directions, etc.

Thanks,

Richard

Free Windows Admin Tool Kit Click here and download it now

July 11th, 2013 12:13pm

Confused by the "I forgot to add" part. If you added those to your host files after the services started, make sure to restart the services on Edge.

Otherwise, it might be time to look at a trace on the edge server and see what is happening when the tool/user attempts to login. Make sure you are seeing traffic in both directions, etc.

Thanks,

R

July 11th, 2013 12:20pm

Here is a SIPSTACK log from the Edge server during a sign on with the testexchangeconnectivity.com site. Contoso.com = my external domain, Fabrikam.com = my internal domain. I've bolded some relevant information.

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:52.984.00000001 (SIPStack,CSocketContext::CSocketContext:SocketContext.cpp(134))( 0000000003A85130 ) New socket will have the same network type as its listening address socket: [EDGE_TYPE_EXTERNAL]
TL_INFO(TF_CONNECTION) [0]0714.0958::07/10/2013-16:19:52.984.00000002 (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.250.245:443 <-- External Edge SIP Access IP
Peer-IP: 207.46.14.62:55193
Connection-ID: 0xF00
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:52.984.00000003 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 0 bytes
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:52.984.00000004 (SIPStack,CTCPSocket::CompleteRecv:TCPSocket.cpp(1321))( 0000000003B57F10 ) Exit - peer has gracefully closed the connection. Returned 10101(WSAEDISCON)
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.052.00000005 (SIPStack,CSocketContext::CSocketContext:SocketContext.cpp(134))( 0000000003B57F10 ) New socket will have the same network type as its listening address socket: [EDGE_TYPE_EXTERNAL]
TL_INFO(TF_CONNECTION) [0]0714.0958::07/10/2013-16:19:53.052.00000006 (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.250.245:443
Peer-IP: 207.46.14.62:55194
Connection-ID: 0x1000
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.053.00000007 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 151 bytes
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.053.00000008 (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003A854B8 ) AcceptSecurityContext returned HRESULT=80090312
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.053.00000009 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003A85130 ) WSASend 0000000001765A60 completed non-blocking. Bytes sent: 145
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.101.0000000a (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 59 bytes
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.101.0000000b (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003A854B8 ) AcceptSecurityContext returned S_OK
TL_INFO(TF_CONNECTION) [0]0714.0270::07/10/2013-16:19:53.101.0000000c (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS connection closed
Local-IP: 192.168.250.245:443
Peer-IP: 207.46.14.62:55194
Connection-ID: 0x1000
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.101.0000000d (SIPStack,CTCPSocket::CompleteRecv:TCPSocket.cpp(1321))( 0000000003A85130 ) Exit - peer has gracefully closed the connection. Returned 10101(WSAEDISCON)
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.169.0000000e (SIPStack,CSocketContext::CSocketContext:SocketContext.cpp(134))( 0000000003A85130 ) New socket will have the same network type as its listening address socket: [EDGE_TYPE_EXTERNAL]
TL_INFO(TF_CONNECTION) [0]0714.0958::07/10/2013-16:19:53.169.0000000f (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.250.245:443
Peer-IP: 207.46.14.62:55195
Connection-ID: 0x1100
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.170.00000010 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 151 bytes
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.171.00000011 (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003B58298 ) AcceptSecurityContext returned HRESULT=80090312
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.171.00000012 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003B57F10 ) WSASend 0000000001765A60 completed non-blocking. Bytes sent: 145
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.223.00000013 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 59 bytes
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.224.00000014 (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003B58298 ) AcceptSecurityContext returned S_OK
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.473.00000015 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 341 bytes
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:19:53.473.00000016 (SIPStack,CSIPMessage::CacheConnectionFlags:SIPMessage.cpp(1677))[0]( 0000000003B552C0 ) From client connection, CID [0x1100]
TL_INFO(TF_PROTOCOL) [0]0714.0958::07/10/2013-16:19:53.473.00000017 (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 802292975
Instance-Id: 00000019
Direction: incoming;source="external edge";destination="internal edge"
Peer: 207.46.14.62:55195
Message-Type: request
Start-Line: NEGOTIATE sip:127.0.0.1:5061 SIP/2.0
From: <sip:CH1PQORCALWB03.phx.gbl>
To: <sip:sipexternal.contoso.com>
CSeq: 1 NEGOTIATE
Call-ID: 5f0653e1defb45b3a467e7de6ac63c71
MAX-FORWARDS: 0
VIA: SIP/2.0/TLS 207.46.14.62:55195
CONTENT-LENGTH: 0
SUPPORTED: NewNegotiate
SUPPORTED: ECC
REQUIRE: ms-feature-info
Message-Body:
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.474.00000018 (SIPStack,NegotiateLogic::ParseRequireHeader:NegotiateLogic.cpp(792))[0]( 0000000003B58350 ) Found [ms-feature-info] in Require header
TL_INFO(TF_DIAG) [0]0714.0958::07/10/2013-16:19:53.474.00000019 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(147))$$begin_record
LogType: diagnostic
Severity: information
Text: Response successfully routed
SIP-Start-Line: SIP/2.0 200 OK
SIP-Call-ID: 5f0653e1defb45b3a467e7de6ac63c71
SIP-CSeq: 1 NEGOTIATE
Peer: 207.46.14.62:55195
Data: destination="Unknown"
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:19:53.474.0000001a (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003B57F10 ) WSASend 0000000003AC4598 completed non-blocking. Bytes sent: 437
TL_INFO(TF_PROTOCOL) [0]0714.0958::07/10/2013-16:19:53.474.0000001b (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 802292975
Instance-Id: 0000001A
Direction: outgoing;source="local";destination="external edge"
Peer: 207.46.14.62:55195
Message-Type: response
Start-Line: SIP/2.0 200 OK
From: <sip:CH1PQORCALWB03.phx.gbl>
To: <sip:sipexternal.contoso.com>;tag=8C4F3D8CB75BC6F86A506BA122DC9F6A
CSeq: 1 NEGOTIATE
Call-ID: 5f0653e1defb45b3a467e7de6ac63c71
ms-user-logon-data: RemoteUser
Via: SIP/2.0/TLS 207.46.14.62:55195;ms-received-port=55195;ms-received-cid=1100
Require: ms-feature-info
Supported: NewNegotiate,OCSNative,ECC
Server: RTC/4.0
Content-Length: 0
Message-Body:
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.519.0000001c (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 709 bytes
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.0000001d (SIPStack,CSIPMessage::CacheConnectionFlags:SIPMessage.cpp(1677))[0]( 0000000003B552C0 ) From client connection, CID [0x1100]
TL_INFO(TF_PROTOCOL) [0]0714.0270::07/10/2013-16:19:53.519.0000001e (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 1075370227
Instance-Id: 0000001B
Direction: incoming;source="external edge";destination="internal edge"
Peer: 207.46.14.62:55195
Message-Type: request
Start-Line: REGISTER sip:contoso.com SIP/2.0
From: <sip:user@contoso.com>;epid=314C3632CA;tag=db9076d0c1
To: <sip:user@contoso.com>
CSeq: 1 REGISTER
Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
MAX-FORWARDS: 70
VIA: SIP/2.0/TLS 207.46.14.62:55195;branch=z9hG4bK2856b25e
CONTACT: <sip:CH1PQORCALWB03.phx.gbl;maddr=207.46.14.62;ms-opaque=5cadd19d35c4879a>;proxy=replace;methods="Service,Notify,Benotify,Message,Info,Options,Invite";+sip.instance="<urn:uuid:b9c8e50f-6578-5584-8873-4477e39db467>"
CONTENT-LENGTH: 0
EVENT: Registration
SUPPORTED: gruu-10
SUPPORTED: msrtc-event-categories
SUPPORTED: ms-forking
USER-AGENT: RTCC/5.0.0.0
ms-keep-alive: UAC;hop-hop=yes
Message-Body:
$$end_record

TL_INFO(TF_DIAG) [0]0714.0270::07/10/2013-16:19:53.519.0000001f (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(147))$$begin_record
LogType: diagnostic
Severity: information
Text: The message has an internally supported domain
SIP-Start-Line: REGISTER sip:contoso.com SIP/2.0
SIP-Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
SIP-CSeq: 1 REGISTER
Peer: 207.46.14.62:55195
Data: domain="contoso.com"
$$end_record

TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000020 (SIPStack,CSIPRequest::GetNextHopByRouteHeader:SIPRequest.cpp(2508))( 1075370227 )( 0000000003B552C0 ) Exit - there is no route header in the message, use request uri for routing
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000021 (SIPStack,CSIPRequest::IsTrustedForRouting:SIPRequest.cpp(94))[1075370227]( 0000000003B552C0 ) routedByApplication [0x00000000(false)], routeHeadersValidated [0x00000000(false)], sourceTrusted [0x00000000(false)]. TrustedForRouting = 0x00000000(false)
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000022 (SIPStack,CSIPRequest::RouteRequestUriAddr:SIPRequest.cpp(2986))( 1075370227 )( 0000000003B552C0 ) Exit - ok, not an IP address
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000023 (SIPStack,URTImpl::GetInternalPeerRoute:URTImpl.cpp(2029))( 1075370227 )( 000000000024D010 ) Exit - found the next hop [lync.fabrikam.com]. Returns S_OK
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000024 (SIPStack,CSIPRequest::SetEPRoute:SIPRequest.cpp(3341))( 1075370227 )( 0000000003B552C0 ) Exit - routed domain [contoso.com] to partner FQDN [lync.fabrikam.com]
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.519.00000025 (SIPStack,CSIPRequest::IsTrustedForRouting:SIPRequest.cpp(94))[1075370227]( 0000000003B552C0 ) routedByApplication [0x00000000(false)], routeHeadersValidated [0x00000000(false)], sourceTrusted [0x00000000(false)]. TrustedForRouting = 0x00000000(false)
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:19:53.524.00000026 ((Shared),ValidateCertChain:CertificateHelper.cpp(1680))TrustStatus.dwErrorStatus: 0(ERROR_SUCCESS), TrustStatus.dwInfoStatus: WINERROR= 100
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.526.00000027 (SIPStack,CTCPSocket::StartConnect:TCPSocket.cpp(1789))[0]( 0000000003B2C370 ) Binding the socket to the EDGE_TYPE_INTERNAL edge
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.527.00000028 (SIPStack,CTLSLogic::AdvanceOutboundTlsHlp:tlslogic.cpp(1143))[0]( 0000000003B2C6F8 ) InitializeSecurityContext returned HRESULT=80090312
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:19:53.527.00000029 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003B2C370 ) WSASend 0000000003B5C660 completed non-blocking. Bytes sent: 125
TL_INFO(TF_CONNECTION) [0]0714.0270::07/10/2013-16:19:53.527.0000002a (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.200.238:49171 <---Internal Edge Server (why is it usin 49171?)
Peer-IP: 10.254.6.64:5061 < --- Internal FE Pool
Peer-FQDN: lync.fabrikam.com
Connection-ID: 0x1201
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.398.0000002b (SIPStack,CSocketContext::CSocketContext:SocketContext.cpp(134))( 0000000003B7FD60 ) New socket will have the same network type as its listening address socket: [EDGE_TYPE_EXTERNAL]
TL_INFO(TF_CONNECTION) [0]0714.0958::07/10/2013-16:20:08.398.0000002c (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.250.245:443
Peer-IP: 99.179.127.242:53700
Connection-ID: 0x1300
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.401.0000002d (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76140 ) Received 132 bytes
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.402.0000002e (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003A854B8 ) AcceptSecurityContext returned HRESULT=80090312
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.402.0000002f (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003A85130 ) WSASend 0000000003A9AE80 completed non-blocking. Bytes sent: 4645
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.528.00000030 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76140 ) Received 326 bytes
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.535.00000031 (SIPStack,CTLSLogic::AdvanceInboundTlsHlp:tlslogic.cpp(745))[0]( 0000000003A854B8 ) AcceptSecurityContext returned S_OK
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.535.00000032 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003A85130 ) WSASend 0000000003A9AE80 completed non-blocking. Bytes sent: 59
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:08.597.00000033 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76140 ) Received 341 bytes
TL_INFO(TF_COMPONENT) [0]0714.0270::07/10/2013-16:20:08.597.00000034 (SIPStack,CSIPMessage::CacheConnectionFlags:SIPMessage.cpp(1677))[0]( 0000000003B817A0 ) From client connection, CID [0x1300]
TL_INFO(TF_PROTOCOL) [0]0714.0270::07/10/2013-16:20:08.597.00000035 (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 3742936020
Instance-Id: 0000001C
Direction: incoming;source="external edge";destination="internal edge"
Peer: 99.179.127.242:53700
Message-Type: request
Start-Line: NEGOTIATE sip:72.204.246.185:443 SIP/2.0 <--PUBLIC Address for SIP access
From: <sip:192.168.1.82:53700>;tag=902b6ecf923d4ff2af04708b6651407b
To: <sip:72.204.246.185:443>
CSeq: 1 NEGOTIATE
Call-ID: b4ccd47811b3440eb247f80b85001750
Via: SIP/2.0/TLS 192.168.1.82:53700
Compression: LZ77-8K
Max-Forwards: 0
Content-Length: 0
Message-Body:
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:08.598.00000036 (SIPStack,NegotiateLogic::ParseRequireHeader:NegotiateLogic.cpp(755))[0]( 0000000003A85570 ) Found legacy compression request
TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:08.598.00000037 (SIPStack,NegotiateLogic::ProcessPeerFeatureInfo:NegotiateLogic.cpp(1266))( 0 )( 0000000003A85570 ) Exit - legacy message doesn't have NewNegotiate feature tag
TL_INFO(TF_DIAG) [0]0714.0270::07/10/2013-16:20:08.598.00000038 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(147))$$begin_record
LogType: diagnostic
Severity: information
Text: Response successfully routed
SIP-Start-Line: SIP/2.0 200 OK
SIP-Call-ID: b4ccd47811b3440eb247f80b85001750
SIP-CSeq: 1 NEGOTIATE
Peer: 99.179.127.242:53700
Data: destination="Unknown"
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:08.598.00000039 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003A85130 ) WSASend 0000000003B5FD40 completed non-blocking. Bytes sent: 421
TL_INFO(TF_PROTOCOL) [0]0714.0270::07/10/2013-16:20:08.598.0000003a (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 3742936020
Instance-Id: 0000001D
Direction: outgoing;source="local";destination="external edge"
Peer: 99.179.127.242:53700
Message-Type: response
Start-Line: SIP/2.0 200 OK
From: <sip:192.168.1.82:53700>;tag=902b6ecf923d4ff2af04708b6651407b
To: <sip:72.204.246.185:443>;tag=8C4F3D8CB75BC6F86A506BA122DC9F6A
CSeq: 1 NEGOTIATE
Call-ID: b4ccd47811b3440eb247f80b85001750
ms-user-logon-data: RemoteUser
Via: SIP/2.0/TLS 192.168.1.82:53700;received=99.179.127.242;ms-received-port=53700;ms-received-cid=1300
Compression: LZ77-8K
Content-Length: 0
Message-Body:
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:08.598.0000003b (SIPStack,`NegotiateLogic::AcceptCompression'::`1'::catch$0:NegotiateLogic.cpp(2376))[0]( 0000000003A85570 ) Exit - compression type CompClientToServer enabled
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.659.0000003c (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76140 ) Received 821 bytes
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.659.0000003d (SIPStack,CSIPMessage::CacheConnectionFlags:SIPMessage.cpp(1677))[0]( 0000000003B81AC0 ) From client connection, CID [0x1300]
TL_INFO(TF_PROTOCOL) [0]0714.0958::07/10/2013-16:20:08.659.0000003e (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 1674527724
Instance-Id: 0000001E
Direction: incoming;source="external edge";destination="internal edge"
Peer: 99.179.127.242:53700
Message-Type: request
Start-Line: REGISTER sip:contoso.com SIP/2.0
From: <sip:user@contoso.com>;tag=162bd73a48;epid=c367e55f3b
To: <sip:user@contoso.com>
CSeq: 1 REGISTER
Call-ID: 89d851034c824c2ba23a0308ad0dee86
Via: SIP/2.0/TLS 192.168.1.82:53700
Max-Forwards: 70
Contact: <sip:192.168.1.82:53700;transport=tls;ms-opaque=215088cfbf>;methods="INVITE, MESSAGE, INFO, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace;+sip.instance="<urn:uuid:DDCCBDE1-06D9-5970-97FE-CB2AFFEF715F>"
User-Agent: UCCAPI/4.0.7577.4356 OC/4.0.7577.4388 (Microsoft Lync 2010)
Supported: gruu-10, adhoclist, msrtc-event-categories
Supported: ms-forking
Supported: ms-cluster-failover
Supported: ms-userservices-state-notification
ms-keep-alive: UAC;hop-hop=yes
Event: registration
Content-Length: 0
Message-Body:
$$end_record

TL_INFO(TF_DIAG) [0]0714.0958::07/10/2013-16:20:08.659.0000003f (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(147))$$begin_record
LogType: diagnostic
Severity: information
Text: The message has an internally supported domain
SIP-Start-Line: REGISTER sip:contoso.com SIP/2.0
SIP-Call-ID: 89d851034c824c2ba23a0308ad0dee86
SIP-CSeq: 1 REGISTER
Peer: 99.179.127.242:53700
Data: domain="contoso.com"
$$end_record

TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.659.00000040 (SIPStack,CSIPRequest::GetNextHopByRouteHeader:SIPRequest.cpp(2508))( 1674527724 )( 0000000003B81AC0 ) Exit - there is no route header in the message, use request uri for routing
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.659.00000041 (SIPStack,CSIPRequest::IsTrustedForRouting:SIPRequest.cpp(94))[1674527724]( 0000000003B81AC0 ) routedByApplication [0x00000000(false)], routeHeadersValidated [0x00000000(false)], sourceTrusted [0x00000000(false)]. TrustedForRouting = 0x00000000(false)
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.659.00000042 (SIPStack,CSIPRequest::RouteRequestUriAddr:SIPRequest.cpp(2986))( 1674527724 )( 0000000003B81AC0 ) Exit - ok, not an IP address
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.659.00000043 (SIPStack,URTImpl::GetInternalPeerRoute:URTImpl.cpp(2029))( 1674527724 )( 000000000024D010 ) Exit - found the next hop [lync.fabrikam.com]. Returns S_OK
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.660.00000044 (SIPStack,CSIPRequest::SetEPRoute:SIPRequest.cpp(3341))( 1674527724 )( 0000000003B81AC0 ) Exit - routed domain [contoso.com] to partner FQDN [lync.fabrikam.com]
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.660.00000045 (SIPStack,CSIPRequest::IsTrustedForRouting:SIPRequest.cpp(94))[1674527724]( 0000000003B81AC0 ) routedByApplication [0x00000000(false)], routeHeadersValidated [0x00000000(false)], sourceTrusted [0x00000000(false)]. TrustedForRouting = 0x00000000(false)
TL_INFO(TF_COMPONENT) [0]0714.0958::07/10/2013-16:20:08.664.00000046 ((Shared),ValidateCertChain:CertificateHelper.cpp(1680))TrustStatus.dwErrorStatus: 0(ERROR_SUCCESS), TrustStatus.dwInfoStatus: WINERROR= 100
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.667.00000047 (SIPStack,CTCPSocket::StartConnect:TCPSocket.cpp(1789))[0]( 0000000003B82BD0 ) Binding the socket to the EDGE_TYPE_INTERNAL edge
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.668.00000048 (SIPStack,CTLSLogic::AdvanceOutboundTlsHlp:tlslogic.cpp(1143))[0]( 0000000003B82F58 ) InitializeSecurityContext returned HRESULT=80090312
TL_INFO(TF_NETWORK) [0]0714.0958::07/10/2013-16:20:08.668.00000049 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003B82BD0 ) WSASend 0000000003A9AE80 completed non-blocking. Bytes sent: 125
TL_INFO(TF_CONNECTION) [0]0714.0958::07/10/2013-16:20:08.669.0000004a (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS negotiation started
Local-IP: 192.168.200.238:49172
Peer-IP: 10.254.6.64:5061
Peer-FQDN: lync.fabrikam.com
Connection-ID: 0x1400
Transport: TLS
$$end_record

TL_ERROR(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.947.0000004b (SIPStack,CTLSSocket::WT_OnNegotiationTimeOut:TLSSocket.cpp(668))[0] Closing socket
TL_INFO(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.947.0000004c (SIPStack,CSocketContext::InvokeConnectCallback:SocketContext.cpp(2440))[0]( 0000000003B2C370 ) Invoke 0000000000000001 connect completion callbacks with connectCompleted=0x00000000(false)
TL_ERROR(TF_COMPONENT) [0]0714.0270::07/10/2013-16:20:23.947.0000004d (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(147))( 0000000003A76290 ) Receive failed
TL_ERROR(TF_NETWORK) [0]0714.0270::07/10/2013-16:20:23.947.0000004e (SIPStack,CTCPSocket::OnSocketError:TCPSocket.cpp(694))( 0000000003B2C370 ) IoRecv operation failed, winsockErr=0(ERROR_SUCCESS), HRESULT=HRESULT=80004005
TL_WARN(TF_COMPONENT) [0]0714.0DB0::07/10/2013-16:20:23.947.0000004f (SIPStack,SendQueueProcessor::DropPendingSends:SendQueueProcessor.cpp(574))[0]( 0000000003B2C3D8 ) Cleaning up outstanding messages on a socket that is being closed
TL_ERROR(TF_DIAG) [0]0714.0DB0::07/10/2013-16:20:23.947.00000050 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(143))$$begin_record
LogType: diagnostic
Severity: error
Text: Message was not sent because the connection was closed
SIP-Start-Line: REGISTER sip:contoso.com SIP/2.0
SIP-Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
SIP-CSeq: 1 REGISTER
Peer: lync.fabrikam.com:5061
$$end_record

TL_WARN(TF_COMPONENT) [0]0714.0DB0::07/10/2013-16:20:23.947.00000051 (SIPStack,MsDiagHeaderFactory::CreateMsWarningInfo:MsDiagHeaderFactory.cpp(49))( 0000000003B55D18 ) Exit - diagnostics header already exists, cannot overwrite
TL_INFO(TF_DIAG) [0]0714.0DB0::07/10/2013-16:20:23.947.00000052 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(147))$$begin_record
LogType: diagnostic
Severity: information
Text: Response successfully routed
SIP-Start-Line: SIP/2.0 504 Server time-out
SIP-Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
SIP-CSeq: 1 REGISTER
Peer: 207.46.14.62:55195
Data: destination="Unknown"
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.947.00000053 (SIPStack,CSocketContext::ProcessHalfDuplexSend:SocketContext.cpp(1147))[0]( 0000000003B57F10 ) Switched to half-duplex receive, resume receive processing
TL_INFO(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.947.00000054 (SIPStack,CTCPSocket::Send:TCPSocket.cpp(1429))[0]( 0000000003B57F10 ) WSASend 0000000003B6D9A8 completed non-blocking. Bytes sent: 437
TL_INFO(TF_PROTOCOL) [0]0714.0DB0::07/10/2013-16:20:23.947.00000055 (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record
Trace-Correlation-Id: 1075370227
Instance-Id: 0000001F
Direction: outgoing;source="local";destination="external edge"
Peer: 207.46.14.62:55195
Message-Type: response
Start-Line: SIP/2.0 504 Server time-out
From: <sip:user@contoso.com>;epid=314C3632CA;tag=db9076d0c1
To: <sip:user@contoso.com>;tag=8C4F3D8CB75BC6F86A506BA122DC9F6A
CSeq: 1 REGISTER
Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
ms-user-logon-data: RemoteUser
Via: SIP/2.0/TLS 207.46.14.62:55195;branch=z9hG4bK2856b25e;ms-received-port=55195;ms-received-cid=1100
Server: RTC/4.0
Content-Length: 0
Message-Body:
$$end_record

TL_ERROR(TF_COMPONENT) [0]0714.0DB0::07/10/2013-16:20:23.947.00000056 (SIPStack,RichContextSipStack::ReportContextMsg:RichContextSipStack.cpp(199))( 0 )( 00000000042AF490 ) Response to REGISTER with cseq 1 was sent without ms-diagnostics header before Rich Result was reported
TL_WARN(TF_DIAG) [0]0714.0DB0::07/10/2013-16:20:23.965.00000057 (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(145))$$begin_record
LogType: diagnostic
Severity: warning
Text: Routing error occurred; check Result-Code field for more information
Result-Code: 0xc3e93c7f SIPPROXY_E_ROUTING_MSG_SEND_CLOSED
SIP-Start-Line: REGISTER sip:contoso.com SIP/2.0
SIP-Call-ID: 992bb63193fc4a79a4e3b45ca79eff9e
SIP-CSeq: 1 REGISTER
Peer: lync.fabrikam.com:5061
$$end_record

TL_WARN(TF_COMPONENT) [0]0714.0DB0::07/10/2013-16:20:23.965.00000058 (SIPStack,SIPRouterOutbound::ResumeInternal<SIPRouterOutRspEPInt>:SIPRouterOutbound.h(396))( 0 )( 0000000003AC3960 ) Exit - delete router on error 0xC3E93C7F(SIPPROXY_E_ROUTING_MSG_SEND_CLOSED) in sending phase
TL_INFO(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.992.00000059 (SIPStack,CRecvContext::ProcessCompletion:RecvContext.cpp(155))( 0000000003A76060 ) Received 0 bytes
TL_INFO(TF_CONNECTION) [0]0714.0DB0::07/10/2013-16:20:23.992.0000005a (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(164))$$begin_record
LogType: connection
Severity: information
Text: TLS connection closed
Local-IP: 192.168.250.245:443
Peer-IP: 207.46.14.62:55195
Connection-ID: 0x1100
Transport: TLS
$$end_record

TL_INFO(TF_NETWORK) [0]0714.0DB0::07/10/2013-16:20:23.992.0000005b (SIPStack,CTCPSocket::CompleteRecv:TCPSocket.cpp(1321))( 0000000003B57F10 ) Exit - peer has gracefully closed the connection. Returned 10101(WSAEDISCON)

Free Windows Admin Tool Kit Click here and download it now

July 11th, 2013 12:30pm

So the traffic is hitting the edge and attempting to go to the front-end and failing with a 504 timeout. These can be related to TLS or just routing.

Out of curiosity can you connect to the front-end server from the edge. So it would be:

telnet <front-end.fqdn> 5061

The telnet client should be able to connect. That will verify connectivity. If that works lets look at TLS then. Using a internal CA for both the front-end servers and the internal interface of the edge server. Both of those come from the CA (i.e. internal edge isn't public and front-end are private/internal CA).

Thanks,

Richard

July 11th, 2013 12:39pm

So the traffic is hitting the edge and attempting to go to the front-end and failing with a 504 timeout. These can be related to TLS or just routing.

Out of curiosity can you connect to the front-end server from the edge. So it would be:

telnet <front-end.fqdn> 5061

The telnet client should be able to connect. That will verify connectivity. If that works lets look at TLS then. Using a internal CA for both the front-end servers and the internal interface of the edge server. Both of those come from the CA (i.e. internal edge isn't public and front-end are private/internal CA).

Thanks,

R

Free Windows Admin Tool Kit Click here and download it now

July 11th, 2013 12:52pm

An oddity I noticed, from the FE pool I can telnet to my EDGE FQDN over 5061 regardless of whether the access edge service is started or not.

Heck, I can telnet successfully to 5061 even when the server is shut down. However, when it's shut down, I can't ping it.

July 11th, 2013 1:09pm

Wow, yeah that sounds really bad. There is definitely something up in terms of routing/traffic because you should never be able to do that. It should come back as a failure if the server/service is turned off. Something else is responding.

Thanks,

Richard

Free Windows Admin Tool Kit Click here and download it now

July 11th, 2013 1:16pm

Wow, yeah that sounds really bad. There is definitely something up in terms of routing/traffic because you should never be able to do that. It should come back as a failure if the server/service is turned off. Something else is responding.

Thanks,

R

July 11th, 2013 2:58pm

This topic is archived. No further replies will be accepted.