TL_VERBOSE(TF_COMPONENT) [3]1FF4.161C::02/26/2015-21:23:13.000.0000b0fd (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002B89EAA ) signal Time = 3499000
TL_VERBOSE(TF_COMPONENT) [3]1FF4.161C::02/26/2015-21:23:13.000.0000b0fe (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002B89EAA ) Expiring interval 66
TL_VERBOSE(TF_COMPONENT) [2]1FF4.1D34::02/26/2015-21:23:13.000.0000b0ff (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000283D742 ) signal Time = 3499000
TL_VERBOSE(TF_COMPONENT) [2]1FF4.1D34::02/26/2015-21:23:13.000.0000b100 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000283D742 ) Expiring interval 66
TL_VERBOSE(TF_COMPONENT) [3]16A4.25A4::02/26/2015-21:23:13.185.0000b101 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000008FFC9E ) signal Time = 3499187
TL_VERBOSE(TF_COMPONENT) [3]16A4.25A4::02/26/2015-21:23:13.185.0000b102 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000008FFC9E ) Expiring interval 15
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b103 (S4,TcpTransport.WinSockReceived:tcptransport.cs(587))(0000000003A9DA31)IOCompleted
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b104 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TcpTransport.OnReceived 0x3BAC2B8, arg=<OverlappedAsyncResult_35F813A>
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b105 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))(000000000155B0B3)Starting Dispatcher on current worker thread
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b106 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(000000000155B0B3)Started
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b107 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TcpTransport.OnReceived 0x3BAC2B8, arg=<OverlappedAsyncResult_35F813A>
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b108 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TcpTransport.OnReceived 0x3BAC2B8, arg=<OverlappedAsyncResult_35F813A> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b109 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(710))(0000000003A9DA31)Incoming TCP Buffer <TransportsDataBuffer_8E4AAA> Packet size=242

TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10a (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TlsTransport.OnReceived 0x3B61FB3, arg=<TransportsDataBuffer_8E4AAA>
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TcpTransport.OnReceived 0x3BAC2B8, arg=<OverlappedAsyncResult_35F813A> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TcpTransport.OnReceived 0x3BAC2B8, arg=<OverlappedAsyncResult_35F813A>
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TlsTransport.OnReceived 0x3B61FB3, arg=<TransportsDataBuffer_8E4AAA>
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TlsTransport.OnReceived 0x3B61FB3, arg=<TransportsDataBuffer_8E4AAA> was queued for 0 mseconds
TL_NOISE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b10f (S4,TlsTransport.OnReceived:tlstransport.cs(424))(000000000274114E)Enter - dataBuffer=<TransportsDataBuffer_8E4AAA>
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b110 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::NegotiateConnection:TlsTransportHelper.cpp(992))( 0000000003621481 ) Enter: NegotiateConnection()
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b111 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::OutgoingTlsNegotiation:TlsTransportHelper.cpp(770))( 0000000003621481 ) Enter: OutgoingTlsNegotiation()
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b112 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::OutgoingTlsNegotiation:TlsTransportHelper.cpp(891))( 0000000003621481 ) InitializeSecurityContext(); status = 0
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.204.0000b113 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetContextStreamSizes:TlsTransportHelper.cpp(446))( 0000000003621481 ) Successfully called GetContextStreamSizes()
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b114 (S4,Microsoft::Rtc::Internal::Sip::Interval::Remove:TimerWheel.cpp(149))( 000000000355C18B ) Removed item 3528656
TL_VERBOSE(TF_COMPONENT) [1]16A4.1738::02/26/2015-21:23:13.204.0000b115 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::Remove:TimerWheel.cpp(377))( 0000000001704D88 ) Removed timeout item for 3528656
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.205.0000b116 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::OutgoingTlsNegotiation:TlsTransportHelper.cpp(961))( 3621481 ) Exit: OutgoingTlsNegotiation(); status = Done
TL_VERBOSE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.205.0000b117 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::NegotiateConnection:TlsTransportHelper.cpp(1010))( 3621481 ) Exit: NegotiateConnection(); status = Done
TL_NOISE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.205.0000b118 (S4,NegotiateLogic.ProcessPeerCertificate:negotiatelogic.cs(812))(00000000009400B1)Enter
TL_NOISE(TF_NETWORK) [1]16A4.1738::02/26/2015-21:23:13.205.0000b119 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemotePeerIdentity:TlsTransportHelper.cpp(1520))( 0000000003621481 ) Enter
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11a (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemoteHostName:TlsTransportHelper.cpp(1607))( 0000000003621481 ) Enter
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11b (S4,Microsoft::Rtc::Internal::Sip::CertificateInfoNative::FormatNameFromCert:SSPI_mcpp.cpp(535))Enter
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11c (S4,Microsoft::Rtc::Internal::Sip::CertificateInfoNative::FormatNameFromCert:SSPI_mcpp.cpp(573))Exit: name = ferraribox.ask.loc
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11d (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemoteHostName:TlsTransportHelper.cpp(1638))( 3621481 ) ferraribox.ask.loc
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11e (S4,Microsoft::Rtc::Internal::Sip::TlsCredentials::VerifyRemoteCertificate:SSPI_mcpp.cpp(976))Enter
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b11f (S4,Microsoft::Rtc::Internal::Sip::TlsCredentials::VerifyRemoteCertificate:SSPI_mcpp.cpp(998))Using default EKU
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b120 (S4,Microsoft::Rtc::Internal::Sip::TlsCredentials::VerifyRemoteCertificate:SSPI_mcpp.cpp(1089))Exit
TL_INFO(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b121 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemotePeerIdentity:TlsTransportHelper.cpp(1575))( 0000000003621481 ) Exit - trusted root, wildCard=0
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.205.0000b122 (S4,Microsoft::Rtc::Internal::Sip::CertificateInfoNative::FormatNameFromCert:SSPI_mcpp.cpp(535))Enter
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b123 (S4,Microsoft::Rtc::Internal::Sip::CertificateInfoNative::FormatNameFromCert:SSPI_mcpp.cpp(573))Exit: name = ask-lync.ask.loc
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b124 (S4,Microsoft::Rtc::Internal::Sip::CertificateInfoNative::GetHostName:SSPI_mcpp.cpp(615))Exit: hostName = ask-lync.ask.loc
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b125 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemotePeerIdentity:TlsTransportHelper.cpp(1520))( 0000000003621481 ) Enter
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b126 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::GetRemotePeerIdentity:TlsTransportHelper.cpp(1535))( 0000000003621481 ) Exit - peer identity already determined
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b127 (S4,NegotiateLogic.ProcessPeerIdentity:negotiatelogic.cs(932))(00000000009400B1)Enter - PeerFQDN=[ferraribox.ask.loc], CertType=TrustedUnique
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b128 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::InvokeTlsCertificateValidationCallback:TlsTransportHelper.cpp(1657))( 3621481 ) Enter - peerFQDN= ferraribox.ask.loc
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b129 (S4,Microsoft::Rtc::Internal::Sip::TlsCredentials::ValidateClientSubjectName:SSPI_mcpp.cpp(1269))( 0000000001EEA771 ) Exit - no allowed domains list specified
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12a (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::InvokeTlsCertificateValidationCallback:TlsTransportHelper.cpp(1687))( 0000000003621481 ) Exit. Returned S_OK
TL_INFO(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12b (S4,NegotiateLogic.ProcessPeerIdentity:negotiatelogic.cs(975))(00000000009400B1)Exit - peer identity with FQDN [ferraribox.ask.loc] is now defined and authorized
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12c (S4,NegotiateLogic.ProcessPeerCertificate:negotiatelogic.cs(896))(00000000009400B1)Exit - traditional OCS certificate
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12d (S4,NegotiateLogic.AdvanceOutboundNegotiation:negotiatelogic.cs(745))(00000000009400B1)Enter
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12e (S4,NegotiateLogic.StartCompression:negotiatelogic.cs(1458))(00000000009400B1)Enter
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b12f (S4,NegotiateLogic.StartCompression:negotiatelogic.cs(1471))(00000000009400B1)Exit - not configured to request compression
TL_INFO(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b130 (S4,NegotiateLogic.AdvanceOutboundNegotiation:negotiatelogic.cs(783))(00000000009400B1)Outbound negotiation sequence is complete
TL_INFO(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b131 (S4,TlsTransport.EnterConnectedState:tlstransport.cs(599))(000000000274114E)Advance to connected state
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b132 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem SipTlsConnection.OnConnected 0x626EB6, arg1=<IPEndPoint_4105D242>, arg2=<IPEndPoint_FC05036B>
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b133 (S4,TlsTransport.DelegateNegotiation:tlstransport.cs(719))(000000000274114E)S2S negotiation not needed
TL_NOISE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b134 (S4,TlsTransport.DelegateNegotiation:tlstransport.cs(754))(000000000274114E)Exit - state=Connected
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b135 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TlsTransport.OnReceived 0x3B61FB3, arg=<TransportsDataBuffer_8E4AAA> took 2,0018 mseconds
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b136 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TlsTransport.OnReceived 0x3B61FB3, arg=<TransportsDataBuffer_8E4AAA>
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b137 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem SipTlsConnection.OnConnected 0x626EB6, arg1=<IPEndPoint_4105D242>, arg2=<IPEndPoint_FC05036B>
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b138 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem SipTlsConnection.OnConnected 0x626EB6, arg1=<IPEndPoint_4105D242>, arg2=<IPEndPoint_FC05036B> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b139 (S4,SipConnection.OnConnected:sipconnection.cs(2641))(0000000001934880)state=Connecting->connected, local=NULL->172.16.5.65:49902, remote=NULL->172.16.5.252:5063, dir=Outgoing
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b13a (S4,SipConnection.OnConnected:sipconnection.cs(2648))(0000000001934880)Connection 26429568 connected
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b13b (S4,SipConnection.OnConnected:sipconnection.cs(2674))(0000000001934880)m_localEndPoint='172.16.5.65:49902', m_remoteEndPoint='172.16.5.252:5063', m_destinationEndPoint='172.16.5.252:5063'
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b13c (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TlsTransport.Receive 0x3715BBC
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b13d (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(0000000002098183)Queueing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b13e (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(0000000002098183)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b13f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(0000000002098183)Started
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b140 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(0000000002098183)Executing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b141 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(00000000001020BC)Queueing Workitem SipTlsConnection.FireConnectedEvent 0x265196C
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b142 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(92))(00000000001020BC)NULL maximum <unknown> queue length = 1}
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b143 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(00000000001020BC)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b144 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback SipTlsConnection.OnConnected 0x626EB6, arg1=<IPEndPoint_4105D242>, arg2=<IPEndPoint_FC05036B> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b145 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(0000000002098183)NULL workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b146 (S4,SipCoreManager.OnConnectionConnectedInternal:sipcorelayer.cs(4288))(000000000113F78C)Connection connected
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b147 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem SipTlsConnection.OnConnected 0x626EB6, arg1=<IPEndPoint_4105D242>, arg2=<IPEndPoint_FC05036B>
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b148 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TlsTransport.Receive 0x3715BBC
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b149 (S4,SipCoreManager.OnConnectionConnectedInternal:sipcorelayer.cs(4294))(000000000113F78C)Raising connection connected event for 26429568
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b14a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TlsTransport.Receive 0x3715BBC was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b14b (S4,SipConnection.get_ApplicationContext:sipconnection.cs(1508))(0000000001934880)Returning application context for 26429568=36988720
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b14c (S4,SipConnection.get_ApplicationContext:sipconnection.cs(1508))(0000000001934880)Returning application context for 26429568=36988720
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b14d (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TcpTransport.Receive 0x32962E9
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b14e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TlsTransport.Receive 0x3715BBC took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b14f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(00000000001020BC)Started
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b150 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TlsTransport.Receive 0x3715BBC
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b151 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TcpTransport.Receive 0x32962E9
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b152 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TcpTransport.Receive 0x32962E9 was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.206.0000b153 (S4,TcpTransport.ReceiveMore:tcptransport.cs(433))(0000000003A9DA31)IOStart: Receive
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b154 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(00000000001020BC)Executing Workitem SipTlsConnection.FireConnectedEvent 0x265196C
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b155 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(00000000001020BC)NULL workitem SipTlsConnection.FireConnectedEvent 0x265196C was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b156 (S4,SipConnection.FireConnectedEvent:sipconnection.cs(3124))(0000000001934880)FireConnected
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b157 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(00000000001020BC)NULL <unknown> queue workitem callback SipTlsConnection.FireConnectedEvent 0x265196C took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b158 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(00000000001020BC)Finished  Workitem SipTlsConnection.FireConnectedEvent 0x265196C
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.206.0000b159 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(00000000001020BC)Finished
TL_VERBOSE(TF_AUTH) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b15a (S4,SipMessage.set_EndpointAuthContext:sipmessage.cs(204))(00000000031E13B1)Updated end point authentication context with key: a01edfdc8e487ebe for OPTIONS message
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b15b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TcpTransport.Receive 0x32962E9 took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b15c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TcpTransport.Receive 0x32962E9
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.206.0000b15d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(000000000155B0B3)Finished
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b15e (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b15f (S4,SipConnection.get_ApplicationContext:sipconnection.cs(1508))(0000000001934880)Returning application context for 26429568=36988720
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b160 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b161 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b162 (S4,SipConnection.get_ApplicationContext:sipconnection.cs(1508))(0000000001934880)Returning application context for 26429568=36988720
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b163 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b164 (S4,SipConnection.get_ApplicationContext:sipconnection.cs(1508))(0000000001934880)Returning application context for 26429568=36988720
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b165 (S4,OutgoingNonInviteTransaction.SendRequest:sipcorelayer.cs(5272))(0000000003389A11)Sending OPTIONS request
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b166 (S4,SipStack.SendMessage:sipstack.cs(1286))(0000000001BF5E3F)controller=<MessageProcessingController_3B03433>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b167 (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))(0000000003B03433)message.from=sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b168 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(609))(0000000003B03433)Processing outgoing state manager. this.stateManagerModule=<StateManagerModule_351907>.
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b169 (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(212))(0000000000351907)Processing outgoing msg <SipRequest_31E13B1>, msg.Trans=<OutgoingOptionsTransaction_3389A11>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b16a (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(237))(0000000000351907)Processing outgoing request OPTIONS
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b16b (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(243))(0000000000351907)request.dialog=<null>, request.tran.dialogContext=<null>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b16c (S4,ClientNonInviteTransaction.ProcessRequest:sipclienttransactions.cs(591))(0000000003389A11)Transaction z9hG4bKae23c9e9 current state Starting
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b16d (S4,StateManagerModule.RegisterTransaction:statemanagermodule.cs(296))(0000000000351907)Registering transaction OPTIONS:z9hG4bKae23c9e9
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.206.0000b16e (S4,StateManagerModule.EnsureCallContext:statemanagermodule.cs(494))(0000000000351907)Attempting to create call context for d5a0b8536da24afca11253ee771daf96
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b16f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::Add:TimerWheel.cpp(325))( 0000000002164E94 ) Added timeout item for 3531203 interval 82
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b170 (S4,ClientNonInviteTransaction.ProcessRequest:sipclienttransactions.cs(616))(0000000003389A11)Transaction z9hG4bKae23c9e9 new state is Trying
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b171 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(626))(0000000003B03433)Processing outgoing routing.
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b172 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b173 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b174 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.2C24::02/26/2015-21:23:13.207.0000b175 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_NETWORK) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b176 (S4,SipConnection.MessageProcessingWorkitem.constructor:sipconnection.cs(1358))message=<SipRequest_31E13B1>, controller=<ConnectionControlModule_106E35E>
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b177 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000006572D)Queueing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b178 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(92))(000000000006572D)NULL maximum <unknown> queue length = 1}
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b179 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(000000000006572D)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_NETWORK) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b17a (S4,SipConnection.StartReceivingData:sipconnection.cs(2626))(0000000001934880)Posting receive
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b17b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(0000000002098183)NULL <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem took 1,0836 mseconds
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b17c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(0000000002098183)Finished  Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.2C24::02/26/2015-21:23:13.207.0000b17d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(0000000002098183)Finished
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b17e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(000000000006572D)Started
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b17f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000006572D)Executing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b180 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000006572D)NULL workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b181 (S4,ConnectionControlModule.HandlePostponedMessage:connectioncontrolmodule.cs(2878))(000000000106E35E)message.from=sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe, controller=<MessageProcessingController_3B03433>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b182 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b183 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b184 (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))(0000000003B03433)message.from=sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b185 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(724))(0000000003B03433)Processing outgoing routed.
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b186 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b187 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b188 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b189 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(741))(0000000003B03433)Processing outgoing authentication. authModule=<AuthenticationModule_1A21C4D>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18a (S4,AuthenticationModule.ProcessOutgoing:authenticationmodule.cs(164))(0000000001A21C4D)ProcessOutgoing
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18b (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(760))(0000000003B03433)Processing outgoing parser. msg.From=sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe
TL_VERBOSE(TF_NETWORK) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18c (S4,ParserModule.ProcessOutgoing:parsermodule.cs(541))(0000000000D4C399)controller=<MessageProcessingController_3B03433>, sipStack=<SipStack_1BF5E3F>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18d (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_NETWORK) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18e (S4,RawDataBuffer.set_Connection:rawdatabuffer.cs(50))(00000000031D1C19)set connection=<null>-><SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b18f (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_INFO(TF_PROTOCOL) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b190 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(774))[3253281231]
>>>>>>>>>>>>Outgoing SipMessage c=[<SipTlsConnection_1934880>], 172.16.5.65:49902->172.16.5.252:5063
OPTIONS sip:ferraribox.ask.loc SIP/2.0
FROM: <sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe>;epid=3010017029;tag=abd46962d4
TO: <sip:ferraribox.ask.loc>
CSEQ: 53 OPTIONS
CALL-ID: d5a0b8536da24afca11253ee771daf96
MAX-FORWARDS: 70
VIA: SIP/2.0/TLS 172.16.5.65:49902;branch=z9hG4bKae23c9e9
CONTACT: <sip:ask-lync.ask.loc:5067;transport=Tls>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/5.0.0.0 MediationServer

------------EndOfOutgoing SipMessage

TL_VERBOSE(TF_NETWORK) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b191 (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))(00000000031D1C19)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b192 (S4,MessageProcessingController.ProcessOutgoingBuffer:messageprocessingcontroller.cs(432))(0000000003B03433)connection=<SipTlsConnection_1934880>,buffer=<RawDataBuffer_31D1C19>
TL_VERBOSE(TF_NETWORK) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b193 (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))(00000000031D1C19)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b194 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TlsTransport.Send 0x24C2EF0, arg1=<TransportsDataBuffer_2A15135>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b195 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(000000000155B0B3)Starting Dispatcher on new thread pool thread
TL_INFO(TF_PROTOCOL) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b196 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(779))
>>>>>>>>>>>>Outgoing RawDataBuffer 172.16.5.65:49902->172.16.5.252:5063
OPTIONS sip:ferraribox.ask.loc SIP/2.0
FROM: <sip:ask-lync.ask.loc:5067;transport=Tls;ms-opaque=a01edfdc8e487ebe>;epid=3010017029;tag=abd46962d4
TO: <sip:ferraribox.ask.loc>
CSEQ: 53 OPTIONS
CALL-ID: d5a0b8536da24afca11253ee771daf96
MAX-FORWARDS: 70
VIA: SIP/2.0/TLS 172.16.5.65:49902;branch=z9hG4bKae23c9e9
CONTACT: <sip:ask-lync.ask.loc:5067;transport=Tls>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/5.0.0.0 MediationServer

------------EndOfOutgoing RawDataBuffer

TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b197 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(000000000155B0B3)Started
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b198 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000006572D)NULL <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b199 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000006572D)Finished  Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
TL_VERBOSE(TF_COMPONENT) [3]16A4.16EC::02/26/2015-21:23:13.207.0000b19a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(000000000006572D)Finished
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b19b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TlsTransport.Send 0x24C2EF0, arg1=<TransportsDataBuffer_2A15135>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b19c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TlsTransport.Send 0x24C2EF0, arg1=<TransportsDataBuffer_2A15135>, arg2=<SipRequest_31E13B1> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b19d (S4,TlsTransport.TraceNetworkPacket:tlstransport.cs(844))(000000000274114E)Outgoing TLS Buffer <TransportsDataBuffer_2A15135> Packet size=430

TL_NOISE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b19e (S4,NegotiateLogic.CompressData:negotiatelogic.cs(1743))(00000000009400B1)Enter
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b19f (S4,NegotiateLogic.CompressData:negotiatelogic.cs(1751))(00000000009400B1)Exit - compression not enabled
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a0 (S4,TlsTransport.Send:tlstransport.cs(223))(000000000274114E)Sending 430 bytes with 0 bytes remaining
TL_NOISE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a1 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1217))( 0000000003621481 ) Enter - 430 bytes to encrypt
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a2 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1085))( 0000000003621481 ) Enter: PrepareDataAndEncrypt()
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a3 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSingleBuffer:TlsTransportHelper.cpp(1059))( 0000000003621481 ) EncryptSingleBuffer(); status = 0
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a4 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1195))( 0000000003621481 ) Exit: PrepareDataAndEncrypt()
TL_NOISE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a5 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1253))( 0000000003621481 ) Exit - returns 459 bytes
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a6 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TcpTransport.Send 0x6E1396, arg1=<TransportsDataBuffer_2BFE9B4>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TlsTransport.Send 0x24C2EF0, arg1=<TransportsDataBuffer_2A15135>, arg2=<SipRequest_31E13B1> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TlsTransport.Send 0x24C2EF0, arg1=<TransportsDataBuffer_2A15135>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1a9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TcpTransport.Send 0x6E1396, arg1=<TransportsDataBuffer_2BFE9B4>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1aa (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TcpTransport.Send 0x6E1396, arg1=<TransportsDataBuffer_2BFE9B4>, arg2=<SipRequest_31E13B1> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1ab (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(710))(0000000003A9DA31)Outgoing TCP Buffer <TransportsDataBuffer_2BFE9B4> Packet size=459

TL_VERBOSE(TF_NETWORK) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1ac (S4,TcpTransport.Send:tcptransport.cs(350))(0000000003A9DA31)SyncIO: Send
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1ad (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem TlsTransport.OnSent 0xBDD2A9, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1ae (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TcpTransport.Send 0x6E1396, arg1=<TransportsDataBuffer_2BFE9B4>, arg2=<SipRequest_31E13B1> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1af (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TcpTransport.Send 0x6E1396, arg1=<TransportsDataBuffer_2BFE9B4>, arg2=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.207.0000b1b0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem TlsTransport.OnSent 0xBDD2A9, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem TlsTransport.OnSent 0xBDD2A9, arg=<SipRequest_31E13B1> was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b2 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000155B0B3)Queueing Workitem SipTlsConnection.OnSent 0x289928D, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback TlsTransport.OnSent 0xBDD2A9, arg=<SipRequest_31E13B1> took 0,9122 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem TlsTransport.OnSent 0xBDD2A9, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000155B0B3)Executing Workitem SipTlsConnection.OnSent 0x289928D, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000155B0B3)NULL workitem SipTlsConnection.OnSent 0x289928D, arg=<SipRequest_31E13B1> was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b7 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b8 (S4,SipMessage.get_Connection:sipmessage.cs(371))(00000000031E13B1)return connection=<SipTlsConnection_1934880>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1b9 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(00000000001020BC)Queueing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1ba (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(00000000001020BC)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1bb (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000155B0B3)NULL <unknown> queue workitem callback SipTlsConnection.OnSent 0x289928D, arg=<SipRequest_31E13B1> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1bc (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000155B0B3)Finished  Workitem SipTlsConnection.OnSent 0x289928D, arg=<SipRequest_31E13B1>
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1bd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(000000000155B0B3)Finished
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1be (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(00000000001020BC)Started
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1bf (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(00000000001020BC)Executing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1c0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(00000000001020BC)NULL workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1c1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(00000000001020BC)NULL <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1c2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(00000000001020BC)Finished  Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
TL_VERBOSE(TF_COMPONENT) [0]16A4.16E8::02/26/2015-21:23:13.208.0000b1c3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(00000000001020BC)Finished
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c4 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2650))(000000000106E35E)Remove connection
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c5 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2654))(000000000106E35E)Removing connection 172.16.5.252:5063 (8587703) from connection table
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c6 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2669))(000000000106E35E)Connection 172.16.5.252:5063 removed. count=2
TL_VERBOSE(TF_NETWORK) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c7 (S4,SipConnection.Disconnect:sipconnection.cs(2255))(00000000008309B7)disconnect SipConnection=8587703 with state=Connected
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c8 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem SipTlsConnection.StopInactivityTimer 0x3802275
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1c9 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(000000000067BFD2)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1ca (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem SipTlsConnection.StopKeepAliveTimer 0x384711D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1cb (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(000000000067BFD2)Started
TL_VERBOSE(TF_COMPONENT) [2]16A4.16F0::02/26/2015-21:23:13.219.0000b1cc (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem TlsTransport.Disconnect 0x1294D6, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1cd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem SipTlsConnection.StopInactivityTimer 0x3802275
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1ce (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem SipTlsConnection.StopInactivityTimer 0x3802275 was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1cf (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback SipTlsConnection.StopInactivityTimer 0x3802275 took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem SipTlsConnection.StopInactivityTimer 0x3802275
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem SipTlsConnection.StopKeepAliveTimer 0x384711D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem SipTlsConnection.StopKeepAliveTimer 0x384711D was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback SipTlsConnection.StopKeepAliveTimer 0x384711D took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem SipTlsConnection.StopKeepAliveTimer 0x384711D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem TlsTransport.Disconnect 0x1294D6, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem TlsTransport.Disconnect 0x1294D6, arg=<null> was queued for 0 mseconds
TL_INFO(TF_NETWORK) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d7 (S4,TlsTransport.Disconnect:tlstransport.cs(189))(00000000006676D9)Enter - disconnecting from remote server 172.16.5.252:5063, reason=NULL
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d8 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem TcpTransport.Disconnect 0x18230DF, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1d9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback TlsTransport.Disconnect 0x1294D6, arg=<null> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1da (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem TlsTransport.Disconnect 0x1294D6, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1db (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem TcpTransport.Disconnect 0x18230DF, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1dc (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem TcpTransport.Disconnect 0x18230DF, arg=<null> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1dd (S4,TcpTransport.DisconnectSocket:tcptransport.cs(302))(00000000015A1C9B)SyncIO: Shutdown socket; reason : NULL
TL_VERBOSE(TF_NETWORK) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1de (S4,TcpTransport.DisconnectSocket:tcptransport.cs(309))(00000000015A1C9B)SyncIO: Close socket
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1df (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem TlsTransport.OnDisconnected 0x3A3A1C, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback TcpTransport.Disconnect 0x18230DF, arg=<null> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem TcpTransport.Disconnect 0x18230DF, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem TlsTransport.OnDisconnected 0x3A3A1C, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem TlsTransport.OnDisconnected 0x3A3A1C, arg=<null> was queued for 0 mseconds
TL_VERBOSE(TF_NETWORK) [3]16A4.1738::02/26/2015-21:23:13.219.0000b1e4 (S4,TcpTransport.WinSockReceived:tcptransport.cs(587))(00000000015A1C9B)IOCompleted
TL_VERBOSE(TF_COMPONENT) [3]16A4.1738::02/26/2015-21:23:13.219.0000b1e5 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem TcpTransport.OnReceived 0x1ACC068, arg=<OverlappedAsyncResult_58033B>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e6 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem SipTlsConnection.OnDisconnected 0x3554B63, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback TlsTransport.OnDisconnected 0x3A3A1C, arg=<null> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem TlsTransport.OnDisconnected 0x3A3A1C, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1e9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem TcpTransport.OnReceived 0x1ACC068, arg=<OverlappedAsyncResult_58033B>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.219.0000b1ea (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem TcpTransport.OnReceived 0x1ACC068, arg=<OverlappedAsyncResult_58033B> was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1eb (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback TcpTransport.OnReceived 0x1ACC068, arg=<OverlappedAsyncResult_58033B> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1ec (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem TcpTransport.OnReceived 0x1ACC068, arg=<OverlappedAsyncResult_58033B>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1ed (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem SipTlsConnection.OnDisconnected 0x3554B63, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1ee (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(226))(000000000067BFD2)maximum <unknown> queued time = 1,026
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1ef (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem SipTlsConnection.OnDisconnected 0x3554B63, arg=<null> was queued for 1,026 mseconds
TL_VERBOSE(TF_NETWORK) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f0 (S4,SipConnection.OnDisconnected:sipconnection.cs(2737))(00000000008309B7)Connection to 172.16.5.252:5063 disconnected
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f1 (S4,SipConnection.OnDisconnected:sipconnection.cs(2741))(00000000008309B7)Connection 8587703 disconnected
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f2 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem SipTlsConnection.StopInactivityTimer 0x352082D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f3 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(000000000067BFD2)Queueing Workitem SipTlsConnection.StopKeepAliveTimer 0x23CB710
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f4 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2650))(000000000106E35E)Remove connection
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f5 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2654))(000000000106E35E)Removing connection 172.16.5.252:5063 (8587703) from connection table
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f6 (S4,ConnectionControlModule.RemoveConnectionFromTable:connectioncontrolmodule.cs(2669))(000000000106E35E)Connection 172.16.5.252:5063 removed. count=2
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f7 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))(0000000000600D13)Queueing Workitem SipTlsConnection.FireDisconnectedEvent 0x228C89B, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f8 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))(0000000000600D13)Starting Dispatcher on new thread pool thread
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1f9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback SipTlsConnection.OnDisconnected 0x3554B63, arg=<null> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1fa (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem SipTlsConnection.OnDisconnected 0x3554B63, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1fb (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem SipTlsConnection.StopInactivityTimer 0x352082D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1fc (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem SipTlsConnection.StopInactivityTimer 0x352082D was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1fd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback SipTlsConnection.StopInactivityTimer 0x352082D took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1fe (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem SipTlsConnection.StopInactivityTimer 0x352082D
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b1ff (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(000000000067BFD2)Executing Workitem SipTlsConnection.StopKeepAliveTimer 0x23CB710
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b200 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(000000000067BFD2)NULL workitem SipTlsConnection.StopKeepAliveTimer 0x23CB710 was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b201 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(000000000067BFD2)NULL <unknown> queue workitem callback SipTlsConnection.StopKeepAliveTimer 0x23CB710 took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b202 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(000000000067BFD2)Finished  Workitem SipTlsConnection.StopKeepAliveTimer 0x23CB710
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b203 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(000000000067BFD2)Finished
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b204 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(173))(0000000000600D13)Started
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b205 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(212))(0000000000600D13)Executing Workitem SipTlsConnection.FireDisconnectedEvent 0x228C89B, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b206 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(231))(0000000000600D13)NULL workitem SipTlsConnection.FireDisconnectedEvent 0x228C89B, arg=<null> was queued for 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b207 (S4,SipConnection.FireDisconnectedEvent:sipconnection.cs(3146))(00000000008309B7)FireDisconnected
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b208 (S4,SipConnection.FireDisconnectedEvent:sipconnection.cs(3152))(00000000008309B7)Raising disconnected event for 8587703
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b209 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(246))(0000000000600D13)NULL <unknown> queue workitem callback SipTlsConnection.FireDisconnectedEvent 0x228C89B, arg=<null> took 0 mseconds
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b20a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(284))(0000000000600D13)Finished  Workitem SipTlsConnection.FireDisconnectedEvent 0x228C89B, arg=<null>
TL_VERBOSE(TF_COMPONENT) [1]16A4.2808::02/26/2015-21:23:13.220.0000b20b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(316))(0000000000600D13)Finished
TL_VERBOSE(TF_COMPONENT) [2]1340.1178::02/26/2015-21:23:13.595.0000b20c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000032F8AB0 ) signal Time = 3499593
TL_VERBOSE(TF_COMPONENT) [3]1340.11DC::02/26/2015-21:23:13.595.0000b20d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000003FE06E ) signal Time = 3499593
TL_VERBOSE(TF_COMPONENT) [2]1340.1178::02/26/2015-21:23:13.595.0000b20e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000032F8AB0 ) Expiring interval 79
TL_VERBOSE(TF_COMPONENT) [3]1340.11DC::02/26/2015-21:23:13.595.0000b20f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000003FE06E ) Expiring interval 79
TL_VERBOSE(TF_COMPONENT) [1]1340.1100::02/26/2015-21:23:13.595.0000b210 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000010D5FB2 ) signal Time = 3499593
TL_VERBOSE(TF_COMPONENT) [1]1340.1100::02/26/2015-21:23:13.595.0000b211 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000010D5FB2 ) Expiring interval 79
TL_VERBOSE(TF_COMPONENT) [2]1340.1178::02/26/2015-21:23:13.595.0000b212 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000006FD2E2 ) signal Time = 3499593
TL_VERBOSE(TF_COMPONENT) [2]1340.1178::02/26/2015-21:23:13.595.0000b213 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000006FD2E2 ) Expiring interval 79
TL_VERBOSE(TF_COMPONENT) [2]16A4.16E0::02/26/2015-21:23:13.686.0000b214 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000008FFC9E ) signal Time = 3499687
TL_VERBOSE(TF_COMPONENT) [2]16A4.16E0::02/26/2015-21:23:13.686.0000b215 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000008FFC9E ) Expiring interval 16
TL_VERBOSE(TF_COMPONENT) [3]08D8.1480::02/26/2015-21:23:13.812.0000b216 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000787880 ) signal Time = 3499812
TL_VERBOSE(TF_COMPONENT) [3]08D8.1480::02/26/2015-21:23:13.812.0000b217 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000787880 ) Expiring interval 83
TL_VERBOSE(TF_COMPONENT) [0]08D8.117C::02/26/2015-21:23:13.812.0000b218 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000029A1235 ) signal Time = 3499812
TL_VERBOSE(TF_COMPONENT) [0]08D8.117C::02/26/2015-21:23:13.812.0000b219 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000029A1235 ) Expiring interval 83