locked
OCS 2007 R2 SIP/2.0 480 Temporarily Unavailable RRS feed

  • Question

  • Hi All,

     

    I have an issue with OCS 2007 R2 telephony feature

    The system is working fine except for one user. We can all make inbound and outbound calls except for this user that does not receive inbound calls as they are immediately redirected to his/her voice mail service.

     

    Please find below the error log form OCS server:

     

    TL_INFO(TF_PROTOCOL) [2]0E48.1814::06/28/2010-10:52:35.463.000056ec (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(122))$$begin_record

    Instance-Id: 0000F6C3

    Direction: incoming

    Peer: mediation_server:2020

    Message-Type: response

    Start-Line: SIP/2.0 480 Temporarily Unavailable

    From: <sip:12345678;phone-context=umdial.mydomain.com@mydomain.com;user=phone>;epid=A362C5045C;tag=7692ebb899

    To: <sip:1234;phone-context=umdial.mydomain.com@mydomain.com;user=phone>;tag=90fba553dc

    CSeq: 2322 INVITE

    Call-ID: 2eedc232-76b5-4335-9762-47e2b627cdd8

    Via: SIP/2.0/TLS 192.168.1.227:5061;branch=z9hG4bK5BBC1ABE.00EDEE6994841C51;branched=TRUE;ms-internal-info="dcp4g7rN6vX55Ng8_2KVeGQ8xaB5pp7u0A6KfjBQAA"

    Via: SIP/2.0/TLS 192.168.1.234:4142;branch=z9hG4bK7fabd97c;ms-received-port=4142;ms-received-cid=55600

    Record-Route: <sip:****ocs01.mydomain.com:5061;transport=tls;opaque=state:F:Ci.R51e00:Ieh.KyskuqvWQUCx1kFAaci6hTmIvG9kSHaTcMAJBna0E3L2Zp7u0AF99jvAAA;lr;ms-route-sig=actxHJb_QFR4ocbEjFZ-IV_dbaqtJp7u0AF99jvAAA>;tag=29B156A5C616EB3AA47AFC67E3F090F2

    Proxy-Authorization: Kerberos qop="auth", realm="SIP Communications Service", opaque="5FBCEC42", targetname="sip/****ocs01.mydomain.com", crand="7a0b304c", cnum="180", response="602306092a864886f71201020201011100ffffffff42dc7cddd94378494f0c22968f0c2f5a"

    Content-Length: 0

    Message-Body: –

    $$end_record 

     

    Any help would be appreciated

     

    Thanks

     

    Monday, June 28, 2010 11:23 AM

Answers

  • Hi,

    Can you try a couple things:

    1) change the user's "call forwarding settings" to forward all calls to their cell (or some other destination) and see if the call is able to ring out

    2) try assigning a new line uri to the problem user; logout log back in  & try again

    3) if the problem user is remote (off network) try having them log in from inside the firewall

    Regards,

    Matt


    Matt McGillen, PointBridge - https://blogs.pointbridge.com/Blogs/mcgillen_matt/default.aspx
    Tuesday, June 29, 2010 1:58 PM
  • The issue is resolved.

     

    I have changed the forwarding settings to specifically "Ring me and my delegates", adding a delegate, apply, then remove the delegate

    This fixed the issue and the users were able to receive external calls.

    I don't know why that specific setting would fix an issue like that but then again I didn't know what the problem was to start with

    Thursday, July 1, 2010 9:30 AM

All replies

  • Is there any difference in the configuration between users? 

    Can you post the Line URI (generalized) for the users and the location profiles?

    Thanks

     


    Mark King | MCTS:UC Voice | MCSE: Messaging | MCITP:Enterprise Messaging | CCNA | www.unplugthepbx.com
    Monday, June 28, 2010 12:43 PM
  • The configuration is the same for all users and we have only one location profile

    Affected user config:

    Line URI: tel:+441234567890

    Location profile: umdial.mydomain.com

    I found out that the same problem affects more than one user, but for the majority of users the system works perfectly.

    Also the system works fine internally for the affected users

     

    Thanks

     

    Monday, June 28, 2010 2:19 PM
  • Can you create a new debug session on the Front End server and capture all flags for S4.  Select view log files and paste the text here.
    Mark King | MCTS:UC Voice | MCSE: Messaging | MCITP:Enterprise Messaging | CCNA | www.unplugthepbx.com
    Monday, June 28, 2010 4:34 PM
  • Hi Mark,

    The site does not allow me to post the whole logs together (I am not sure why)

    I had to attach it in chunks

    Thanks

     

     

    Tuesday, June 29, 2010 10:25 AM
  • TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:07.205.0000c65f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000CBC1E4 ) signal Time = 326711171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:07.205.0000c660 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002640A84 ) signal Time = 326711171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:07.205.0000c661 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002640A84 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:07.205.0000c662 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000CBC1E4 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0E4C::06/29/2010-09:53:07.205.0000c663 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000037DA6B3 ) signal Time = 326711171
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0E4C::06/29/2010-09:53:07.205.0000c664 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000037DA6B3 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [2]0C80.11C4::06/29/2010-09:53:07.961.0000c665 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000427C3B ) signal Time = 326711921
    TL_VERBOSE(TF_COMPONENT) [2]0C80.11C4::06/29/2010-09:53:07.961.0000c666 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000427C3B ) Expiring interval 79
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:08.335.0000c667 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000000BE074 ) signal Time = 326712296
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:08.335.0000c668 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000000BE074 ) Expiring interval 30
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0DCC::06/29/2010-09:53:08.705.0000c669 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000307528E ) signal Time = 326712671
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0DCC::06/29/2010-09:53:08.705.0000c66a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000307528E ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:08.830.0000c66b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F8B095 ) signal Time = 326712796
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:08.830.0000c66c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F8B095 ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:08.830.0000c66d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F1A45C ) signal Time = 326712796
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:08.830.0000c66e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F1A45C ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:08.961.0000c66f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002D95FF7 ) signal Time = 326712921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:08.961.0000c670 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002D95FF7 ) Expiring interval 3
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:08.961.0000c671 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000344F434 ) signal Time = 326712921
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:08.961.0000c672 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002407BD4 ) signal Time = 326712921
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:08.961.0000c673 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002407BD4 ) Expiring interval 3
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:08.961.0000c674 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000344F434 ) Expiring interval 3
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:09.080.0000c675 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000034BEA32 ) signal Time = 326713046
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:09.080.0000c676 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000034BEA32 ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:09.080.0000c677 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326713046
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:09.080.0000c678 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [3]0910.0B74::06/29/2010-09:53:09.080.0000c679 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000325C76A ) signal Time = 326713046
    TL_VERBOSE(TF_COMPONENT) [3]0910.0B74::06/29/2010-09:53:09.080.0000c67a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000325C76A ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:09.455.0000c67b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001038339 ) signal Time = 326713421
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0F70::06/29/2010-09:53:09.455.0000c67c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002E55B17 ) signal Time = 326713421
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:09.455.0000c67d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001038339 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0F70::06/29/2010-09:53:09.455.0000c67e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002E55B17 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0DE8::06/29/2010-09:53:09.455.0000c67f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002EB4292 ) signal Time = 326713421
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0DE8::06/29/2010-09:53:09.455.0000c680 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002EB4292 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0DE8::06/29/2010-09:53:10.330.0000c681 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F38432 ) signal Time = 326714296
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0DE8::06/29/2010-09:53:10.330.0000c682 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F38432 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [2]0A38.0D68::06/29/2010-09:53:10.836.0000c683 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001C996DB ) signal Time = 326714796
    TL_VERBOSE(TF_COMPONENT) [2]0A38.0D68::06/29/2010-09:53:10.836.0000c684 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001C996DB ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:10.836.0000c685 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001D21280 ) signal Time = 326714796
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:10.836.0000c686 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000006216E0 ) signal Time = 326714796
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:10.836.0000c687 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001D21280 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:10.836.0000c688 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000006216E0 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.10AC::06/29/2010-09:53:10.955.0000c689 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003106CA3 ) signal Time = 326714921
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:10.955.0000c68a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000564474 ) signal Time = 326714921
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.10AC::06/29/2010-09:53:10.955.0000c68b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003106CA3 ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:10.955.0000c68c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000564474 ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:10.955.0000c68d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000136B561 ) signal Time = 326714921
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:10.955.0000c68e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000136B561 ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:11.206.0000c68f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003793BEF ) signal Time = 326715171
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:11.206.0000c690 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003793BEF ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [1]01AC.160C::06/29/2010-09:53:11.206.0000c691 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000B049CF ) signal Time = 326715171
    TL_VERBOSE(TF_COMPONENT) [1]01AC.160C::06/29/2010-09:53:11.206.0000c692 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000B049CF ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:11.220.0000c693 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001FE585E ) signal Time = 326715187
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:11.220.0000c694 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001FE585E ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:13.705.0000c695 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003D5670C ) signal Time = 326717671
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0CB8::06/29/2010-09:53:13.705.0000c696 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002BF483A ) signal Time = 326717671
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0CB8::06/29/2010-09:53:13.705.0000c697 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002BF483A ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:13.705.0000c698 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003D5670C ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [0]0E0C.0C48::06/29/2010-09:53:13.705.0000c699 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000ADBA65 ) signal Time = 326717671
    TL_VERBOSE(TF_COMPONENT) [0]0E0C.0C48::06/29/2010-09:53:13.705.0000c69a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000ADBA65 ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:14.206.0000c69b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000FF8392 ) signal Time = 326718171
    TL_VERBOSE(TF_COMPONENT) [3]01AC.1088::06/29/2010-09:53:14.206.0000c69c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000FF8392 ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [1]0E0C.0CB8::06/29/2010-09:53:14.330.0000c69d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002A84F86 ) signal Time = 326718296
    TL_VERBOSE(TF_COMPONENT) [1]0E0C.0CB8::06/29/2010-09:53:14.330.0000c69e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002A84F86 ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:14.830.0000c69f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001CB3A6F ) signal Time = 326718796
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:14.830.0000c6a0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326718796
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:14.830.0000c6a1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001CB3A6F ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:14.830.0000c6a2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:14.830.0000c6a3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000058E960 ) signal Time = 326718796
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:14.830.0000c6a4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000058E960 ) Expiring interval 104
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:14.830.0000c6a5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000DAEE87 ) signal Time = 326718796
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:14.830.0000c6a6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000DAEE87 ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08B0::06/29/2010-09:53:15.207.0000c6a7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001F61227 ) signal Time = 326719171
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08B0::06/29/2010-09:53:15.207.0000c6a8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001F61227 ) Expiring interval 33
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:15.455.0000c6a9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000310339F ) signal Time = 326719421
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:15.455.0000c6aa (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000310339F ) Expiring interval 33
    TL_VERBOSE(TF_COMPONENT) [3]0A58.08CC::06/29/2010-09:53:15.707.0000c6ab (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000197980 ) signal Time = 326719671
    TL_VERBOSE(TF_COMPONENT) [3]0A58.08CC::06/29/2010-09:53:15.707.0000c6ac (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000197980 ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [0]0A58.0C2C::06/29/2010-09:53:15.707.0000c6ad (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000017A0C23 ) signal Time = 326719671
    TL_VERBOSE(TF_COMPONENT) [1]0A58.0C24::06/29/2010-09:53:15.707.0000c6ae (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000389E0CB ) signal Time = 326719671
    TL_VERBOSE(TF_COMPONENT) [1]0A58.0C24::06/29/2010-09:53:15.707.0000c6af (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000389E0CB ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [0]0A58.0C2C::06/29/2010-09:53:15.707.0000c6b0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000017A0C23 ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:17.205.0000c6b1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002640A84 ) signal Time = 326721171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:17.205.0000c6b2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002640A84 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:17.205.0000c6b3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000037DA6B3 ) signal Time = 326721171
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:17.205.0000c6b4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000CBC1E4 ) signal Time = 326721171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:17.205.0000c6b5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000037DA6B3 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:17.205.0000c6b6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000CBC1E4 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:17.962.0000c6b7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000427C3B ) signal Time = 326721921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:17.962.0000c6b8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000427C3B ) Expiring interval 80
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:18.336.0000c6b9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000000BE074 ) signal Time = 326722296
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:18.336.0000c6ba (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000000BE074 ) Expiring interval 31
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:18.705.0000c6bb (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000307528E ) signal Time = 326722671
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:18.705.0000c6bc (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000307528E ) Expiring interval 12
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:18.830.0000c6bd (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F8B095 ) signal Time = 326722796
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:18.830.0000c6be (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F8B095 ) Expiring interval 12
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:18.830.0000c6bf (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F1A45C ) signal Time = 326722796
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:18.830.0000c6c0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F1A45C ) Expiring interval 12
    TL_VERBOSE(TF_COMPONENT) [1]0C80.12B8::06/29/2010-09:53:18.962.0000c6c1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002407BD4 ) signal Time = 326722921
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:18.962.0000c6c2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002D95FF7 ) signal Time = 326722921
    TL_VERBOSE(TF_COMPONENT) [1]0C80.12B8::06/29/2010-09:53:18.962.0000c6c3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002407BD4 ) Expiring interval 4
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:18.962.0000c6c4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002D95FF7 ) Expiring interval 4
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:18.962.0000c6c5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000344F434 ) signal Time = 326722921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:18.962.0000c6c6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000344F434 ) Expiring interval 4
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:19.080.0000c6c7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326723046
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:19.080.0000c6c8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 21
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:19.080.0000c6c9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000325C76A ) signal Time = 326723046
    TL_VERBOSE(TF_COMPONENT) [3]0910.0584::06/29/2010-09:53:19.080.0000c6ca (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000034BEA32 ) signal Time = 326723046
    TL_VERBOSE(TF_COMPONENT) [3]0910.0584::06/29/2010-09:53:19.080.0000c6cb (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000034BEA32 ) Expiring interval 21
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:19.080.0000c6cc (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000325C76A ) Expiring interval 21
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:19.455.0000c6cd (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001038339 ) signal Time = 326723421
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0DE8::06/29/2010-09:53:19.455.0000c6ce (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002EB4292 ) signal Time = 326723421
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0DE8::06/29/2010-09:53:19.455.0000c6cf (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002EB4292 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:19.455.0000c6d0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001038339 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:19.455.0000c6d1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002E55B17 ) signal Time = 326723421
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:19.455.0000c6d2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002E55B17 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:20.330.0000c6d3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F38432 ) signal Time = 326724296
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:20.330.0000c6d4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F38432 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:20.836.0000c6d5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001D21280 ) signal Time = 326724796
    TL_VERBOSE(TF_COMPONENT) [2]0A38.0D2C::06/29/2010-09:53:20.836.0000c6d6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000006216E0 ) signal Time = 326724796
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:20.836.0000c6d7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001D21280 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [2]0A38.0D2C::06/29/2010-09:53:20.836.0000c6d8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000006216E0 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:20.836.0000c6d9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001C996DB ) signal Time = 326724796
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:20.836.0000c6da (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001C996DB ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.10AC::06/29/2010-09:53:20.955.0000c6db (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003106CA3 ) signal Time = 326724921
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:20.955.0000c6dc (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000564474 ) signal Time = 326724921
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.10AC::06/29/2010-09:53:20.955.0000c6dd (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003106CA3 ) Expiring interval 8
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:20.955.0000c6de (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000564474 ) Expiring interval 8
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:20.955.0000c6df (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000136B561 ) signal Time = 326724921
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:20.955.0000c6e0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000136B561 ) Expiring interval 8
    TL_VERBOSE(TF_COMPONENT) [2]01AC.160C::06/29/2010-09:53:21.205.0000c6e1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003793BEF ) signal Time = 326725171
    TL_VERBOSE(TF_COMPONENT) [2]01AC.160C::06/29/2010-09:53:21.205.0000c6e2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003793BEF ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:21.205.0000c6e3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000B049CF ) signal Time = 326725171
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:21.205.0000c6e4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000B049CF ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:21.223.0000c6e5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001FE585E ) signal Time = 326725187
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:21.223.0000c6e6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001FE585E ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0F90::06/29/2010-09:53:23.705.0000c6e7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002BF483A ) signal Time = 326727671
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:23.705.0000c6e8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000ADBA65 ) signal Time = 326727671
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0F90::06/29/2010-09:53:23.705.0000c6e9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002BF483A ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:23.705.0000c6ea (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000ADBA65 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [1]0E0C.0C48::06/29/2010-09:53:23.705.0000c6eb (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003D5670C ) signal Time = 326727671
    TL_VERBOSE(TF_COMPONENT) [1]0E0C.0C48::06/29/2010-09:53:23.705.0000c6ec (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003D5670C ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]01AC.1088::06/29/2010-09:53:24.205.0000c6ed (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000FF8392 ) signal Time = 326728171
    TL_VERBOSE(TF_COMPONENT) [0]01AC.1088::06/29/2010-09:53:24.205.0000c6ee (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000FF8392 ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:24.330.0000c6ef (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002A84F86 ) signal Time = 326728296
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:24.330.0000c6f0 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002A84F86 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:24.830.0000c6f1 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000058E960 ) signal Time = 326728796
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:24.830.0000c6f2 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000058E960 ) Expiring interval 105
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:24.830.0000c6f3 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326728796
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:24.830.0000c6f4 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:24.830.0000c6f5 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001CB3A6F ) signal Time = 326728796
    TL_VERBOSE(TF_COMPONENT) [3]0A48.0A40::06/29/2010-09:53:24.830.0000c6f6 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000DAEE87 ) signal Time = 326728796
    TL_VERBOSE(TF_COMPONENT) [3]0A48.0A40::06/29/2010-09:53:24.830.0000c6f7 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000DAEE87 ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:24.830.0000c6f8 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001CB3A6F ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [1]0A58.0C24::06/29/2010-09:53:25.207.0000c6f9 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001F61227 ) signal Time = 326729171
    TL_VERBOSE(TF_COMPONENT) [1]0A58.0C24::06/29/2010-09:53:25.207.0000c6fa (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001F61227 ) Expiring interval 34
    TL_VERBOSE(TF_COMPONENT) [0]0A48.0A40::06/29/2010-09:53:25.455.0000c6fb (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000310339F ) signal Time = 326729421
    TL_VERBOSE(TF_COMPONENT) [0]0A48.0A40::06/29/2010-09:53:25.455.0000c6fc (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000310339F ) Expiring interval 34
    TL_VERBOSE(TF_COMPONENT) [3]0A58.0C2C::06/29/2010-09:53:25.707.0000c6fd (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000389E0CB ) signal Time = 326729671
    TL_VERBOSE(TF_COMPONENT) [3]0A58.0C2C::06/29/2010-09:53:25.707.0000c6fe (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000389E0CB ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [1]0A58.08B0::06/29/2010-09:53:25.707.0000c6ff (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000197980 ) signal Time = 326729671
    TL_VERBOSE(TF_COMPONENT) [0]0A58.0C24::06/29/2010-09:53:25.707.0000c700 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000017A0C23 ) signal Time = 326729671
    TL_VERBOSE(TF_COMPONENT) [0]0A58.0C24::06/29/2010-09:53:25.707.0000c701 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000017A0C23 ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [1]0A58.08B0::06/29/2010-09:53:25.707.0000c702 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000197980 ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0F70::06/29/2010-09:53:27.205.0000c703 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000CBC1E4 ) signal Time = 326731171
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:27.205.0000c704 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000037DA6B3 ) signal Time = 326731171
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:27.205.0000c705 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002640A84 ) signal Time = 326731171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0F70::06/29/2010-09:53:27.205.0000c706 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000CBC1E4 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0E4C::06/29/2010-09:53:27.205.0000c707 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000037DA6B3 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:27.205.0000c708 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002640A84 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:27.962.0000c709 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000427C3B ) signal Time = 326731921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:27.962.0000c70a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000427C3B ) Expiring interval 81
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:28.336.0000c70b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000000BE074 ) signal Time = 326732296
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:28.336.0000c70c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000000BE074 ) Expiring interval 32
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:28.705.0000c70d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000307528E ) signal Time = 326732671
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:28.705.0000c70e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000307528E ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:28.830.0000c70f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F8B095 ) signal Time = 326732796
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0A54::06/29/2010-09:53:28.830.0000c710 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F8B095 ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:28.830.0000c711 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F1A45C ) signal Time = 326732796
    TL_VERBOSE(TF_COMPONENT) [1]0FC0.0DD4::06/29/2010-09:53:28.830.0000c712 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F1A45C ) Expiring interval 13
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:28.962.0000c713 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002D95FF7 ) signal Time = 326732921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:28.962.0000c714 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002D95FF7 ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:28.962.0000c715 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000344F434 ) signal Time = 326732921
    TL_VERBOSE(TF_COMPONENT) [0]0C80.12B8::06/29/2010-09:53:28.962.0000c716 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002407BD4 ) signal Time = 326732921
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:28.962.0000c717 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000344F434 ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [0]0C80.12B8::06/29/2010-09:53:28.962.0000c718 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002407BD4 ) Expiring interval 5
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:29.080.0000c719 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326733046
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:29.080.0000c71a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 22
    TL_VERBOSE(TF_COMPONENT) [3]0910.0B74::06/29/2010-09:53:29.080.0000c71b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000034BEA32 ) signal Time = 326733046
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:29.080.0000c71c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000325C76A ) signal Time = 326733046
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:29.080.0000c71d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000325C76A ) Expiring interval 22
    TL_VERBOSE(TF_COMPONENT) [3]0910.0B74::06/29/2010-09:53:29.080.0000c71e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000034BEA32 ) Expiring interval 22
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:29.455.0000c71f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001038339 ) signal Time = 326733421
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:29.455.0000c720 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001038339 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0E4C::06/29/2010-09:53:29.455.0000c721 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002EB4292 ) signal Time = 326733421
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0DE8::06/29/2010-09:53:29.455.0000c722 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002E55B17 ) signal Time = 326733421
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0DE8::06/29/2010-09:53:29.455.0000c723 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002E55B17 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0E4C::06/29/2010-09:53:29.455.0000c724 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002EB4292 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:30.330.0000c725 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F38432 ) signal Time = 326734296
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:30.330.0000c726 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F38432 ) Expiring interval 16
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:30.836.0000c727 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001D21280 ) signal Time = 326734796
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:30.836.0000c728 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001D21280 ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:30.836.0000c729 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000006216E0 ) signal Time = 326734796
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:30.836.0000c72a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001C996DB ) signal Time = 326734796
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:30.836.0000c72b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001C996DB ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:30.836.0000c72c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000006216E0 ) Expiring interval 18
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:30.955.0000c72d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003106CA3 ) signal Time = 326734921
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:30.955.0000c72e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003106CA3 ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:30.955.0000c72f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000564474 ) signal Time = 326734921
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:30.955.0000c730 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000136B561 ) signal Time = 326734921
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:30.955.0000c731 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000136B561 ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:30.955.0000c732 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000564474 ) Expiring interval 9
    TL_VERBOSE(TF_COMPONENT) [2]01AC.1064::06/29/2010-09:53:31.207.0000c733 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003793BEF ) signal Time = 326735171
    TL_VERBOSE(TF_COMPONENT) [2]01AC.1064::06/29/2010-09:53:31.207.0000c734 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003793BEF ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [0]01AC.1088::06/29/2010-09:53:31.207.0000c735 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000B049CF ) signal Time = 326735171
    TL_VERBOSE(TF_COMPONENT) [0]01AC.1088::06/29/2010-09:53:31.207.0000c736 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000B049CF ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [3]01AC.160C::06/29/2010-09:53:31.222.0000c737 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001FE585E ) signal Time = 326735187
    TL_VERBOSE(TF_COMPONENT) [3]01AC.160C::06/29/2010-09:53:31.222.0000c738 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001FE585E ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0CB8::06/29/2010-09:53:33.706.0000c739 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002BF483A ) signal Time = 326737671
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:33.706.0000c73a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000ADBA65 ) signal Time = 326737671
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0CB8::06/29/2010-09:53:33.706.0000c73b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002BF483A ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [3]0E0C.0FFC::06/29/2010-09:53:33.706.0000c73c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000ADBA65 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0C48::06/29/2010-09:53:33.706.0000c73d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003D5670C ) signal Time = 326737671
    TL_VERBOSE(TF_COMPONENT) [2]0E0C.0C48::06/29/2010-09:53:33.706.0000c73e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003D5670C ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [3]01AC.103C::06/29/2010-09:53:34.208.0000c73f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000FF8392 ) signal Time = 326738171
    TL_VERBOSE(TF_COMPONENT) [3]01AC.103C::06/29/2010-09:53:34.208.0000c740 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000FF8392 ) Expiring interval 7
    TL_VERBOSE(TF_COMPONENT) [0]0E0C.0C48::06/29/2010-09:53:34.331.0000c741 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002A84F86 ) signal Time = 326738296
    TL_VERBOSE(TF_COMPONENT) [0]0E0C.0C48::06/29/2010-09:53:34.331.0000c742 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002A84F86 ) Expiring interval 15
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:34.831.0000c743 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000058E960 ) signal Time = 326738796
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:34.831.0000c744 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001CB3A6F ) signal Time = 326738796
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:34.831.0000c745 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000058E960 ) Expiring interval 106
    TL_VERBOSE(TF_COMPONENT) [1]0A48.08DC::06/29/2010-09:53:34.831.0000c746 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001CB3A6F ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:34.831.0000c747 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326738796
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:34.831.0000c748 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [3]0A48.0A40::06/29/2010-09:53:34.831.0000c749 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000DAEE87 ) signal Time = 326738796
    TL_VERBOSE(TF_COMPONENT) [3]0A48.0A40::06/29/2010-09:53:34.831.0000c74a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000DAEE87 ) Expiring interval 11
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08CC::06/29/2010-09:53:35.208.0000c74b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001F61227 ) signal Time = 326739171
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08CC::06/29/2010-09:53:35.208.0000c74c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001F61227 ) Expiring interval 35
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:35.456.0000c74d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000310339F ) signal Time = 326739421
    TL_VERBOSE(TF_COMPONENT) [2]0A48.0FB0::06/29/2010-09:53:35.456.0000c74e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000310339F ) Expiring interval 35
    TL_VERBOSE(TF_COMPONENT) [3]0A58.0C2C::06/29/2010-09:53:35.708.0000c74f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000197980 ) signal Time = 326739671
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08CC::06/29/2010-09:53:35.708.0000c750 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000389E0CB ) signal Time = 326739671
    TL_VERBOSE(TF_COMPONENT) [3]0A58.0C2C::06/29/2010-09:53:35.708.0000c751 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000197980 ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [2]0A58.08CC::06/29/2010-09:53:35.708.0000c752 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000389E0CB ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [0]0A58.08B0::06/29/2010-09:53:35.708.0000c753 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000017A0C23 ) signal Time = 326739671
    TL_VERBOSE(TF_COMPONENT) [0]0A58.08B0::06/29/2010-09:53:35.708.0000c754 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000017A0C23 ) Expiring interval 20
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:37.206.0000c755 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002640A84 ) signal Time = 326741171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:37.206.0000c756 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000CBC1E4 ) signal Time = 326741171
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0ED4::06/29/2010-09:53:37.206.0000c757 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000CBC1E4 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:37.206.0000c758 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002640A84 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:37.206.0000c759 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000037DA6B3 ) signal Time = 326741171
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0F70::06/29/2010-09:53:37.206.0000c75a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000037DA6B3 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:37.961.0000c75b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000427C3B ) signal Time = 326741921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:37.961.0000c75c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000427C3B ) Expiring interval 82
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:38.337.0000c75d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000000BE074 ) signal Time = 326742296
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:38.337.0000c75e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000000BE074 ) Expiring interval 33
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0DCC::06/29/2010-09:53:38.706.0000c75f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000307528E ) signal Time = 326742671
    TL_VERBOSE(TF_COMPONENT) [3]0FC0.0DCC::06/29/2010-09:53:38.706.0000c760 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000307528E ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:38.831.0000c761 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F8B095 ) signal Time = 326742796
    TL_VERBOSE(TF_COMPONENT) [2]0FC0.0DD4::06/29/2010-09:53:38.831.0000c762 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F8B095 ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0FC0.0DCC::06/29/2010-09:53:38.831.0000c763 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F1A45C ) signal Time = 326742796
    TL_VERBOSE(TF_COMPONENT) [0]0FC0.0DCC::06/29/2010-09:53:38.831.0000c764 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F1A45C ) Expiring interval 14
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:38.961.0000c765 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002D95FF7 ) signal Time = 326742921
    TL_VERBOSE(TF_COMPONENT) [0]0C80.11C4::06/29/2010-09:53:38.961.0000c766 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002D95FF7 ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:38.961.0000c767 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002407BD4 ) signal Time = 326742921
    TL_VERBOSE(TF_COMPONENT) [1]0C80.11F8::06/29/2010-09:53:38.961.0000c768 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002407BD4 ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:38.961.0000c769 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000344F434 ) signal Time = 326742921
    TL_VERBOSE(TF_COMPONENT) [3]0C80.12CC::06/29/2010-09:53:38.961.0000c76a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000344F434 ) Expiring interval 6
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:39.081.0000c76b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000325C76A ) signal Time = 326743046
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:39.081.0000c76c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000034BEA32 ) signal Time = 326743046
    TL_VERBOSE(TF_COMPONENT) [1]0910.0BB8::06/29/2010-09:53:39.081.0000c76d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000325C76A ) Expiring interval 23
    TL_VERBOSE(TF_COMPONENT) [3]0910.0584::06/29/2010-09:53:39.081.0000c76e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000021AF1A5 ) signal Time = 326743046
    TL_VERBOSE(TF_COMPONENT) [3]0910.0584::06/29/2010-09:53:39.081.0000c76f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000021AF1A5 ) Expiring interval 23
    TL_VERBOSE(TF_COMPONENT) [2]0910.0370::06/29/2010-09:53:39.081.0000c770 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000034BEA32 ) Expiring interval 23
    Tuesday, June 29, 2010 10:29 AM
  • TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c771 (S4,TcpTransport.WinSockReceived:tcptransport.cs(400))( 00000000022826EA )IOCompleted
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c772 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.OnReceived 0x1981234, arg=<OverlappedAsyncResult_3BB3330>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c773 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))( 00000000010ED731 )Starting Dispatcher on current worker thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c774 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c775 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.OnReceived 0x1981234, arg=<OverlappedAsyncResult_3BB3330>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c776 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.OnReceived 0x1981234, arg=<OverlappedAsyncResult_3BB3330> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c777 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=1841
    >>> Incoming TCP packet BEGIN
    \0x17\0x03\0x01\0x11\0xc0\0xa3@[\0x0c\0xbdH\0x94[Px2 \0x11\0x18\0xb7:\0xf0\0xf6\0xcd\0x01\0xd9B\0x97/zH\0xbd\0xdd\0xac\0x81\0xbc\0x02\0x17\0x15\0xf3e'\0xf6\0xcf2\0xa6\0x14<x4\0xfcd-\0xd9\0xf0\0xfa@\0x89\0xe7\0xf2-\0xe8P\0x82n/\0xad\0x12\0x80?"r\0xfb\0x88p\0xc3\0xf9\0xb1\0xf5?\0xc2y\0xb7\0xa3\0x1c\0xbb\0xe93/\0x82\0xe2\0xe9x\0x99\0xd7F\0xb9P\0xe7\0xef\0xc2\0x00i\0xc1\0xbdC\0x13{_\0x8e\0xd2\0xb0\0x00\0xdb\0x8b\0xddK\0xd5\0x14\0xb7\0xcdu\0x13\0xde\0xe9\0x8f\0x9c\0xeb\0x8a\0x0f\0x02\0x94\0xafy\0x00\0x02\0x9a\0x82\0xe2\0x848\tJ7\0xfcx[\0xad\0xfd\0x98H\0xe4e6\0x93\0xdfF\0x12\0xf3\0x18dqv\0xb4i\0xb2O\0x06I\0x1dt\0x84IK\0x88f\0x16\0x127&\0x1f\0xc4)\0x11\0xe8x\0xbf\0xf3I7\n
    \\0xd6\0xa1\0xb3\0xc5\0xdf\0x9f\0xcc\0x916\0xa4\0xc0\0xe7\0xd3\0x85b\0x9dx\0x00\0x06\0xa6\0x8c\0x92\0xb1\0x04G\0xdf\0xe0D\0xef\0xcf\0x8b\0x8a\n
    2\0xccU\0xd3;J\0x1bC@\0x08\0xebR\0xc5\0x9d\0xeaTH\0xa5>(\0x0f\0xc3,-\0xcbV\0x8f\0x130\0xbeb\0xcd\0x0ce\0x02\0x94)5l\0x95\0x7f\0xcd\0x9d\0xfc\0xa9\0xbb\0xee\0xe3\0xa6\0xb14\0x01F/\0xb3\0xff\0xca\0xe7\0x0c\0x01\0xe2... the rest is skipped (non-printable data)
    <<< Incoming TCP packet END
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c778 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnReceived 0x3E7FF8E, arg=<TransportsDataBuffer_3C7EC01>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c779 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.OnReceived 0x1981234, arg=<OverlappedAsyncResult_3BB3330> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.OnReceived 0x1981234, arg=<OverlappedAsyncResult_3BB3330>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnReceived 0x3E7FF8E, arg=<TransportsDataBuffer_3C7EC01>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnReceived 0x3E7FF8E, arg=<TransportsDataBuffer_3C7EC01> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77d (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1245))( 0000000001636F30 ) Enter: DecryptReceiveBuffer()
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77e (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1349))( 0000000001636F30 ) Exit: DecryptReceiveBuffer(); status = MoreData
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c77f (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.ReceiveMore 0x2247C38, arg=<TransportsDataBuffer_3C7EC01>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c780 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnReceived 0x3E7FF8E, arg=<TransportsDataBuffer_3C7EC01> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c781 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnReceived 0x3E7FF8E, arg=<TransportsDataBuffer_3C7EC01>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c782 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.ReceiveMore 0x2247C38, arg=<TransportsDataBuffer_3C7EC01>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c783 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.ReceiveMore 0x2247C38, arg=<TransportsDataBuffer_3C7EC01> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c784 (S4,TcpTransport.ReceiveMore:tcptransport.cs(332))( 00000000022826EA )IOStart: Receive (block)
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c785 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.ReceiveMore 0x2247C38, arg=<TransportsDataBuffer_3C7EC01> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c786 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.ReceiveMore 0x2247C38, arg=<TransportsDataBuffer_3C7EC01>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c787 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c788 (S4,TcpTransport.WinSockReceived:tcptransport.cs(400))( 00000000022826EA )IOCompleted
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c789 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.OnReceived 0x69D603, arg=<OverlappedAsyncResult_29A9EA2>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78a (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))( 00000000010ED731 )Starting Dispatcher on current worker thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.OnReceived 0x69D603, arg=<OverlappedAsyncResult_29A9EA2>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.OnReceived 0x69D603, arg=<OverlappedAsyncResult_29A9EA2> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78e (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=4096
    >>> Incoming TCP packet BEGIN
    \0x17\0x03\0x01\0x11\0xc0\0xa3@[\0x0c\0xbdH\0x94[Px2 \0x11\0x18\0xb7:\0xf0\0xf6\0xcd\0x01\0xd9B\0x97/zH\0xbd\0xdd\0xac\0x81\0xbc\0x02\0x17\0x15\0xf3e'\0xf6\0xcf2\0xa6\0x14<x4\0xfcd-\0xd9\0xf0\0xfa@\0x89\0xe7\0xf2-\0xe8P\0x82n/\0xad\0x12\0x80?"r\0xfb\0x88p\0xc3\0xf9\0xb1\0xf5?\0xc2y\0xb7\0xa3\0x1c\0xbb\0xe93/\0x82\0xe2\0xe9x\0x99\0xd7F\0xb9P\0xe7\0xef\0xc2\0x00i\0xc1\0xbdC\0x13{_\0x8e\0xd2\0xb0\0x00\0xdb\0x8b\0xddK\0xd5\0x14\0xb7\0xcdu\0x13\0xde\0xe9\0x8f\0x9c\0xeb\0x8a\0x0f\0x02\0x94\0xafy\0x00\0x02\0x9a\0x82\0xe2\0x848\tJ7\0xfcx[\0xad\0xfd\0x98H\0xe4e6\0x93\0xdfF\0x12\0xf3\0x18dqv\0xb4i\0xb2O\0x06I\0x1dt\0x84IK\0x88f\0x16\0x127&\0x1f\0xc4)\0x11\0xe8x\0xbf\0xf3I7\n
    \\0xd6\0xa1\0xb3\0xc5\0xdf\0x9f\0xcc\0x916\0xa4\0xc0\0xe7\0xd3\0x85b\0x9dx\0x00\0x06\0xa6\0x8c\0x92\0xb1\0x04G\0xdf\0xe0D\0xef\0xcf\0x8b\0x8a\n
    2\0xccU\0xd3;J\0x1bC@\0x08\0xebR\0xc5\0x9d\0xeaTH\0xa5>(\0x0f\0xc3,-\0xcbV\0x8f\0x130\0xbeb\0xcd\0x0ce\0x02\0x94)5l\0x95\0x7f\0xcd\0x9d\0xfc\0xa9\0xbb\0xee\0xe3\0xa6\0xb14\0x01F/\0xb3\0xff\0xca\0xe7\0x0c\0x01\0xe2\0xcb\0x91\n
    \0xff\0xb5\0xd9\0x86\0x1a\0xb2vC\0x16\0x0f\0x87\0xe7\0xb6ua8\0xaaJ\0xdfE\0xfbs-v\0xff\0xadl\0x0elE\0x00\0x18%;\0x88\0xe4D`N7\0x9a\0xf2\0x01\0xa6\0x8c\0x9b\0xac\0xb5\0xb3@\0x11(\0xa7\0x86\0xa9*w\0xf4T\0x0fa\0xef\0xef/9\0xf1Y\0x06F\0xfb\0x19\0x88D+y|Z\0xfb\0xba\0x03\0xa3\0xe02%\0xa3\0xde\0x08\0x8c\0x08\tu\0x10\0xaeM\0xc4\0x1a\0x00\0x14R\0x11\0xba\0x86\0xd2m\0x8d\0xa8\0xecZ=\0x14R\0x8c]\0x9b\0xbc\0xdaH\0xb7\0x1d\0x00;q6g|\0x13(\0x93O\0x8f\0x08\0x9c\0xcc\0xec\0xeb\0xea\0xbe\0xca\0xf6\0xdf%\0xe5\0xa2\0xf4>\0xa5\0x17]\0xdc=\0x81\0x7fK\0x00v@\0xb8.\0xf1\0xde8m\0xcc\0xdf\0x12=\0xda\0xd2\0x1b\0x9d\0x9a`h\0xf9P\0xfc\0x15\0x81\0x11`\0xa2\0xeb\0x12+\0xc2h\0x19\0xd5\0xd63+\0xfd\0xf9\0xec\0x06\0x05zb\0xed\\0xa7\0x14\0xba:k&>\0xa8p\0xba\0x1f\0x13\0x18\0xba&\0x9f\0xc8'}m\0x95\0xdb\0x076\0xcaC\0xddi\0xc0\0xe0\r\0x01\0x8c*\0xb0\0xab\0xc2Y\0xd9*48\0xb4\0x15\0xcc\0xf2\0x85\0xb5I\0xea\0xc8\0xa2\0xe8$\0xe8%\0x8d5K\0xcbb\0xca4\0xe8\0xe2_\r\0x95\0xbd\0xbb\0xbf|\0xe2g0\0x98\0x99\0xf1\0xd3\0xad\0x9a\0xa3\0x84\0x8d\0x9cVJ\0xa3\0xc2\0xbdR\0x8a\0x9as\0xa4'\0x05\0xb7\0x16"\0xe8k\0xa9\0xe3\0xd7{Z4\0xf6m\0xb6\0x8c\0x14\0xb2-=\0xd5\0x0cH\0x89\0xceG\0x94\0xe2x{\r<("\0x8fP\0x06\0x81\0xe9J\0xcc-\0x047<Q\0xb9_\0xa5O\0xf3\0xfb\0x98LEpM\0x9fm\0xaf\0xdd\0x83\0xf0\0xd5\0x11:Ac\0x84... the rest is skipped (non-printable data)
    <<< Incoming TCP packet END
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c78f (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnReceived 0x12DE28D, arg=<TransportsDataBuffer_110D2E8>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c790 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.OnReceived 0x69D603, arg=<OverlappedAsyncResult_29A9EA2> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c791 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.OnReceived 0x69D603, arg=<OverlappedAsyncResult_29A9EA2>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c792 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnReceived 0x12DE28D, arg=<TransportsDataBuffer_110D2E8>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c793 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnReceived 0x12DE28D, arg=<TransportsDataBuffer_110D2E8> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c794 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1245))( 0000000001636F30 ) Enter: DecryptReceiveBuffer()
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c795 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1349))( 0000000001636F30 ) Exit: DecryptReceiveBuffer(); status = MoreData
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c796 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.ReceiveMore 0x3F512E5, arg=<TransportsDataBuffer_110D2E8>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c797 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnReceived 0x12DE28D, arg=<TransportsDataBuffer_110D2E8> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c798 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnReceived 0x12DE28D, arg=<TransportsDataBuffer_110D2E8>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c799 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.ReceiveMore 0x3F512E5, arg=<TransportsDataBuffer_110D2E8>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.ReceiveMore 0x3F512E5, arg=<TransportsDataBuffer_110D2E8> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79b (S4,TcpTransport.ReceiveMore:tcptransport.cs(332))( 00000000022826EA )IOStart: Receive (block)
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.ReceiveMore 0x3F512E5, arg=<TransportsDataBuffer_110D2E8> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.ReceiveMore 0x3F512E5, arg=<TransportsDataBuffer_110D2E8>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c79f (S4,TcpTransport.WinSockReceived:tcptransport.cs(400))( 00000000022826EA )IOCompleted
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c7a0 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.OnReceived 0x2145259, arg=<OverlappedAsyncResult_19279C1>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c7a1 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))( 00000000010ED731 )Starting Dispatcher on current worker thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c7a2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c7a3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.OnReceived 0x2145259, arg=<OverlappedAsyncResult_19279C1>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.208.0000c7a4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.OnReceived 0x2145259, arg=<OverlappedAsyncResult_19279C1> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7a5 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=4549
    >>> Incoming TCP packet BEGIN
    \0x17\0x03\0x01\0x11\0xc0\0xa3@[\0x0c\0xbdH\0x94[Px2 \0x11\0x18\0xb7:\0xf0\0xf6\0xcd\0x01\0xd9B\0x97/zH\0xbd\0xdd\0xac\0x81\0xbc\0x02\0x17\0x15\0xf3e'\0xf6\0xcf2\0xa6\0x14<x4\0xfcd-\0xd9\0xf0\0xfa@\0x89\0xe7\0xf2-\0xe8P\0x82n/\0xad\0x12\0x80?"r\0xfb\0x88p\0xc3\0xf9\0xb1\0xf5?\0xc2y\0xb7\0xa3\0x1c\0xbb\0xe93/\0x82\0xe2\0xe9x\0x99\0xd7F\0xb9P\0xe7\0xef\0xc2\0x00i\0xc1\0xbdC\0x13{_\0x8e\0xd2\0xb0\0x00\0xdb\0x8b\0xddK\0xd5\0x14\0xb7\0xcdu\0x13\0xde\0xe9\0x8f\0x9c\0xeb\0x8a\0x0f\0x02\0x94\0xafy\0x00\0x02\0x9a\0x82\0xe2\0x848\tJ7\0xfcx[\0xad\0xfd\0x98H\0xe4e6\0x93\0xdfF\0x12\0xf3\0x18dqv\0xb4i\0xb2O\0x06I\0x1dt\0x84IK\0x88f\0x16\0x127&\0x1f\0xc4)\0x11\0xe8x\0xbf\0xf3I7\n
    \\0xd6\0xa1\0xb3\0xc5\0xdf\0x9f\0xcc\0x916\0xa4\0xc0\0xe7\0xd3\0x85b\0x9dx\0x00\0x06\0xa6\0x8c\0x92\0xb1\0x04G\0xdf\0xe0D\0xef\0xcf\0x8b\0x8a\n
    2\0xccU\0xd3;J\0x1bC@\0x08\0xebR\0xc5\0x9d\0xeaTH\0xa5>(\0x0f\0xc3,-\0xcbV\0x8f\0x130\0xbeb\0xcd\0x0ce\0x02\0x94)5l\0x95\0x7f\0xcd\0x9d\0xfc\0xa9\0xbb\0xee\0xe3\0xa6\0xb14\0x01F/\0xb3\0xff\0xca\0xe7\0x0c\0x01\0xe2\0xcb\0x91\n
    \0xff\0xb5\0xd9\0x86\0x1a\0xb2vC\0x16\0x0f\0x87\0xe7\0xb6ua8\0xaaJ\0xdfE\0xfbs-v\0xff\0xadl\0x0elE\0x00\0x18%;\0x88\0xe4D`N7\0x9a\0xf2\0x01\0xa6\0x8c\0x9b\0xac\0xb5\0xb3@\0x11(\0xa7\0x86\0xa9*w\0xf4T\0x0fa\0xef\0xef/9\0xf1Y\0x06F\0xfb\0x19\0x88D+y|Z\0xfb\0xba\0x03\0xa3\0xe02%\0xa3\0xde\0x08\0x8c\0x08\tu\0x10\0xaeM\0xc4\0x1a\0x00\0x14R\0x11\0xba\0x86\0xd2m\0x8d\0xa8\0xecZ=\0x14R\0x8c]\0x9b\0xbc\0xdaH\0xb7\0x1d\0x00;q6g|\0x13(\0x93O\0x8f\0x08\0x9c\0xcc\0xec\0xeb\0xea\0xbe\0xca\0xf6\0xdf%\0xe5\0xa2\0xf4>\0xa5\0x17]\0xdc=\0x81\0x7fK\0x00v@\0xb8.\0xf1\0xde8m\0xcc\0xdf\0x12=\0xda\0xd2\0x1b\0x9d\0x9a`h\0xf9P\0xfc\0x15\0x81\0x11`\0xa2\0xeb\0x12+\0xc2h\0x19\0xd5\0xd63+\0xfd\0xf9\0xec\0x06\0x05zb\0xed\\0xa7\0x14\0xba:k&>\0xa8p\0xba\0x1f\0x13\0x18\0xba&\0x9f\0xc8'}m\0x95\0xdb\0x076\0xcaC\0xddi\0xc0\0xe0\r\0x01\0x8c*\0xb0\0xab\0xc2Y\0xd9*48\0xb4\0x15\0xcc\0xf2\0x85\0xb5I\0xea\0xc8\0xa2\0xe8$\0xe8%\0x8d5K\0xcbb\0xca4\0xe8\0xe2_\r\0x95\0xbd\0xbb\0xbf|\0xe2g0\0x98\0x99\0xf1\0xd3\0xad\0x9a\0xa3\0x84\0x8d\0x9cVJ\0xa3\0xc2\0xbdR\0x8a\0x9as\0xa4'\0x05\0xb7\0x16"\0xe8k\0xa9\0xe3\0xd7{Z4\0xf6m\0xb6\0x8c\0x14\0xb2-=\0xd5\0x0cH\0x89\0xceG\0x94\0xe2x{\r<("\0x8fP\0x06\0x81\0xe9J\0xcc-\0x047<Q\0xb9_\0xa5O\0xf3\0xfb\0x98LEpM\0x9fm\0xaf\0xdd\0x83\0xf0\0xd5\0x11:Ac\0x84\0xb4\0xb6\0xdf\0xee\0xf2\0xabVO\0x8c \0x19\r\0x1c\0xafUv=\0xd6D\0xaab\0xdc\0xc0tK\0xcb\0x93\0xd1\0xc1\n
    \0xc2\0x03S\0x91\0xdcvM\0x95\0x14\0xf0\0xc3\0x85\0x00\0xc2\0xe0\0x7f\0xa4\0xbf\0x9aL\0xd2k\0xa6\0xe6\0x0b\0xf5\0xec\0x8b\0x10\0x10s>\0x82\0xf2... the rest is skipped (non-printable data)
    <<< Incoming TCP packet END
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7a6 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnReceived 0x2BF66F3, arg=<TransportsDataBuffer_3A518C6>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7a7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.OnReceived 0x2145259, arg=<OverlappedAsyncResult_19279C1> took 0.9766 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7a8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.OnReceived 0x2145259, arg=<OverlappedAsyncResult_19279C1>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7a9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnReceived 0x2BF66F3, arg=<TransportsDataBuffer_3A518C6>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7aa (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnReceived 0x2BF66F3, arg=<TransportsDataBuffer_3A518C6> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ab (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1245))( 0000000001636F30 ) Enter: DecryptReceiveBuffer()
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ac (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.OnReceived 0x55AE3, arg=<TransportsDataBuffer_F0FA0B>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ad (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnReceived 0x2BF66F3, arg=<TransportsDataBuffer_3A518C6> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ae (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnReceived 0x2BF66F3, arg=<TransportsDataBuffer_3A518C6>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7af (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.OnReceived 0x55AE3, arg=<TransportsDataBuffer_F0FA0B>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.OnReceived 0x55AE3, arg=<TransportsDataBuffer_F0FA0B> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b1 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem SipTlsConnection.OnReceived 0x25BF409, arg=<TransportsDataBuffer_F0FA0B>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.OnReceived 0x55AE3, arg=<TransportsDataBuffer_F0FA0B> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.OnReceived 0x55AE3, arg=<TransportsDataBuffer_F0FA0B>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem SipTlsConnection.OnReceived 0x25BF409, arg=<TransportsDataBuffer_F0FA0B>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem SipTlsConnection.OnReceived 0x25BF409, arg=<TransportsDataBuffer_F0FA0B> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b6 (S4,RawDataBuffer.set_Connection:rawdatabuffer.cs(50))( 000000000229E596 )set connection=<null>-><SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b7 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(564))
    <<<<<<<<<<<<Incoming RawDataBuffer 192.168.1.227:5069<-192.168.1.227:50059
    Tuesday, June 29, 2010 10:30 AM
  • TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b8 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(581))$$$SplitMessageSegmentBegin$$$ <OutboundStream Id="3154745999" Start="2010-06-29T10:53:28.3240603+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter />
              <PacketLoss />
              <Delay />
              <Utilization>
                <Packets>157</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio>
                <PayloadType>8</PayloadType>
                <PayloadDescription>PCMA</PayloadDescription>
                <SampleRate>8000</SampleRate>
              </Audio>
            </Payload>
          </OutboundStream>
        </MediaLine>
      </VQSessionReport>
    </VQReportE------------EndOfIncoming RawDataBuffer

    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7b9 (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 000000000229E596 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ba (S4,SipMessage.set_Connection:sipmessage.cs(211))( 00000000015D5B71 )connection set <null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7bb (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7bc (S4,SipMessage.DataLoggingHelper:sipmessage.cs(564))
    <<<<<<<<<<<<Incoming SipMessage c=[<SipTlsConnection_376BB23>], 192.168.1.227:5069<-192.168.1.227:50059
    SERVICE sip:mydomainocs01.mydomain.com:5069;grid SIP/2.0
    FROM: <sip:8230@192.168.1.234;user=phone>;epid=A362C5045C;tag=168a81ddc9
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>
    CSEQ: 3004 SERVICE
    CALL-ID: 2badf9f71c3f4bb2820f3ae3eb16cc9b
    MAX-FORWARDS: 69
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bKAAACC777.8187929C9B483C93;branched=FALSE
    VIA: SIP/2.0/TLS 192.168.1.234:3542;branch=z9hG4bK47f24b59;ms-received-port=3542;ms-received-cid=A2D00
    CONTENT-LENGTH: 3907
    USER-AGENT: RTCC/3.5.0.0 MediationServer
    CONTENT-TYPE: application/vq-rtcpxr+xml

    <?xml version="1.0"?>
    <VQReportEvent xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" Version="1.1" xmlns="ms-rtcp-metrics">
      <VQSessionReport SessionId="4030528181222000191622@192.168.1.231;from-tag=1c403053637;to-tag=8a1e3c2c5">
        <LocationProfile>mydomainumdial.mydomain.com</LocationProfile>
        <Endpoint Name="mydomainmed01.mydomain.com" />
        <DialogInfo CallId="4030528181222000191622@192.168.1.231" FromTag="8a1e3c2c5" ToTag="1c403053637" Start="2010-06-29T10:53:36.2147863+01:00" End="2010-06-29T10:53:39.6679555+01:00">
          <DialogCategory>TRUNK</DialogCategory>
          <CorrelationID>16972244-c3d4-4324-91f7-46f2db483a2d;from-tag=8df75297b0;to-tag=e7839fdff4</CorrelationID>
          <FromURI>sip:8230@192.168.1.234;user=phone</FromURI>
          <ToURI>sip:1234567890@192.168.1.231</ToURI>
          <Caller>false</Caller>
          <LocalContactURI>sip:mydomainmed01.mydomain.com:5060;transport=Tcp</LocalContactURI>
          <RemoteContactURI>sip:1234567890@192.168.1.231;transport=tcp</RemoteContactURI>
          <LocalUserAgent>RTCC/3.5.0.0 MediationServer/3.5.6907.0</LocalUserAgent>
          <RemoteUserAgent>Audiocodes-Sip-Gateway-Mediant 1000/v.5.60A.013.005</RemoteUserAgent>
        </DialogInfo>
        <MediaLine Label="main-audio">
          <Description>
            <Connectivity>
              <Ice>DIRECT</Ice>
            </Connectivity>
            <Security>None</Security>
            <Offerer>false</Offerer>
            <Transport>UDP</Transport>
            <LocalAddr>
              <IPAddr>192.168.1.234</IPAddr>
              <Port>62806</Port>
              <Inside>true</Inside>
              <SubnetMask>255.255.255.0</SubnetMask>
            </LocalAddr>
            <RemoteAddr>
              <IPAddr>192.168.1.231</IPAddr>
              <Port>6310</Port>
            </RemoteAddr>
          </Description>
          <InboundStream Id="502731248" Start="2010-06-29T10:53:28.3240603+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter>
                <InterArrival>0</InterArrival>
                <InterArrivalMax>0</InterArrivalMax>
              </Jitter>
              <PacketLoss>
                <LossRate>0</LossRate>
                <LossRateMax>0</LossRateMax>
              </PacketLoss>
              <BurstGapLoss>
                <BurstDensity>0</BurstDensity>
                <BurstDuration>0</BurstDuration>
                <GapDensity>0</GapDensity>
                <GapDuration>9980</GapDuration>
              </BurstGapLoss>
              <Utilization>
                <Packets>565</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio>
                <Signal>
                  <RxAGCSignalLevel>0</RxAGCSignalLevel>
                  <RxAGCNoiseLevel>7049</RxAGCNoiseLevel>
                </Signal>
              </Audio>
            </Payload>
            <QualityEstimates>
              <Audio>
                <NetworkMOS>
                  <OverallAvg>3.61</OverallAvg>
                  <OverallMin>3.61</OverallMin>
                  <DegradationAvg>0</DegradationAvg>
                  <DegradationMax>0</DegradationMax>
                  <DegradationJitterAvg>0</DegradationJitterAvg>
                  <DegradationPacketLossAvg>0</DegradationPacketLossAvg>
                </NetworkMOS>
              </Audio>
            </QualityEstimates>
          </InboundStream>
          <Out$$$SplitMessageSegmentEnd$$$
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7bd (S4,SipMessage.DataLoggingHelper:sipmessage.cs(581))$$$SplitMessageSegmentBegin$$$boundStream Id="3154745999" Start="2010-06-29T10:53:28.3240603+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter />
              <PacketLoss />
              <Delay />
              <Utilization>
                <Packets>157</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio>
                <PayloadType>8</PayloadType>
                <PayloadDescription>PCMA</PayloadDescription>
                <SampleRate>8000</SampleRate>
              </Audio>
            </Payload>
          </OutboundStream>
        </MediaLine>
      </VQSessionReport>
    </VQReportEvent>------------EndOfIncoming SipMessage

    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7be (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(449))( 0000000003DF8A91 )Processing routing.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7bf (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(457))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c0 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(467))( 0000000003DF8A91 )Processing authentication.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c1 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(475))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c2 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(485))( 0000000003DF8A91 )Processing state manager.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c3 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(493))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c4 (S4,MessageProcessingController.OnMessageReceived:messageprocessingcontroller.cs(288))( 0000000003DF8A91 )Indicating message received to sip stack
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c5 (S4,SipStack.OnMessageReceived:sipstack.cs(1492))( 00000000024B5BA0 )Indicating message received to core layer
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c6 (S4,SipCoreManager.OnMessageReceived:sipcorelayer.cs(3992))( 00000000033F1B47 )Calling ProcessIncomingRequest
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c7 (S4,SipCoreManager.ProcessIncomingRequest:sipcorelayer.cs(3808))( 00000000033F1B47 )Invoking request received event handler
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c8 (S4,SipCoreManager.ProcessIncomingServiceRequest:sipcorelayer.cs(3261))( 00000000033F1B47 )Incoming Service Request
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7c9 (S4,StateManagerModule.RegisterTransaction:statemanagermodule.cs(281))( 000000000217CB8C )Registering transaction SERVICE:z9hG4bKAAACC777.8187929C9B483C93
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ca (S4,StateManagerModule.EnsureCallContext:statemanagermodule.cs(505))( 000000000217CB8C )Attempting to create call context for 2badf9f71c3f4bb2820f3ae3eb16cc9b
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7cb (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000022EC7B6 )Queueing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7cc (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 00000000022EC7B6 )Starting Dispatcher on new thread pool thread
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7cd (S4,MessageProcessingController.OnMessageReceived:messageprocessingcontroller.cs(290))( 0000000003DF8A91 )OnMessageReceived returned
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7ce (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7cf (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.Receive 0x16912DD
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.209.0000c7d0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000022EC7B6 )Started
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback SipTlsConnection.OnReceived 0x25BF409, arg=<TransportsDataBuffer_F0FA0B> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.209.0000c7d2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000022EC7B6 )Executing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem SipTlsConnection.OnReceived 0x25BF409, arg=<TransportsDataBuffer_F0FA0B>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.Receive 0x16912DD
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.Receive 0x16912DD was queued for 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.209.0000c7d6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000022EC7B6 ) workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d7 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.Receive 0x37850D9
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.Receive 0x16912DD took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7d9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.Receive 0x16912DD
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7da (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.Receive 0x37850D9
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7db (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.Receive 0x37850D9 was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7dc (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.Receive 0x263645
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7dd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.Receive 0x37850D9 took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7de (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.Receive 0x37850D9
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7df (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.Receive 0x263645
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7e0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.Receive 0x263645 was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7e1 (S4,TcpTransport.ReceiveMore:tcptransport.cs(315))( 00000000022826EA )IOStart: Receive
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.209.0000c7e2 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.209.0000c7e3 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7e4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.Receive 0x263645 took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7e5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.Receive 0x263645
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.209.0000c7e6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.210.0000c7e7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000022EC7B6 ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem took 0.9766 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.210.0000c7e8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000022EC7B6 )Finished  Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.210.0000c7e9 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000022EC7B6 )Finished
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.210.0000c7ea (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.210.0000c7eb (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.210.0000c7ec (S4,SipMessage.set_Connection:sipmessage.cs(211))( 00000000022A6ED1 )connection set <null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7ed (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7ee (S4,SipStack.SendMessage:sipstack.cs(1151))( 00000000024B5BA0 )controller=<MessageProcessingController_3DF8A91>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7ef (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))( 0000000003DF8A91 )message.from=sip:8230@192.168.1.234;user=phone
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f0 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(585))( 0000000003DF8A91 )Processing outgoing state manager. this.stateManagerModule=<StateManagerModule_217CB8C>.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f1 (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(197))( 000000000217CB8C )Processing outgoing msg <SipResponse_22A6ED1>, msg.Trans=<IncomingServiceTransaction_17B172F>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f2 (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(248))( 000000000217CB8C )response.dialog=<null>, response.tran.dialogContext=<null>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f3 (S4,StateManagerModule.UnregisterTransaction:statemanagermodule.cs(335))( 000000000217CB8C )Unregistering transaction SERVICE:z9hG4bKAAACC777.8187929C9B483C93
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f4 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000015D5B71 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f5 (S4,StateManagerModule.CheckCallContextReferences:statemanagermodule.cs(565))( 000000000217CB8C )<Dictionary`2_1A10B6F>.Remove(2badf9f71c3f4bb2820f3ae3eb16cc9b);
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f6 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(602))( 0000000003DF8A91 )Processing outgoing routing.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f7 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f8 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7f9 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7fa (S4,SipConnection.MessageProcessingWorkitem.constructor:sipconnection.cs(1225))message=<SipResponse_22A6ED1>, controller=<ConnectionControlModule_2CAD4C9>
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7fb (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 0000000002396DB9 )Queueing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.211.0000c7fc (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 0000000002396DB9 )Starting Dispatcher on new thread pool thread
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c7fd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 0000000002396DB9 )Started
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c7fe (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 0000000002396DB9 )Executing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c7ff (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 0000000002396DB9 ) workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c800 (S4,ConnectionControlModule.HandlePostponedMessage:connectioncontrolmodule.cs(1610))( 0000000002CAD4C9 )message.from=sip:8230@192.168.1.234;user=phone, controller=<MessageProcessingController_3DF8A91>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c801 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c802 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c803 (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))( 0000000003DF8A91 )message.from=sip:8230@192.168.1.234;user=phone
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c804 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(700))( 0000000003DF8A91 )Processing outgoing routed.
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c805 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c806 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c807 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(717))( 0000000003DF8A91 )Processing outgoing authentication. authModule=<AuthenticationModule_209383C>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c808 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(736))( 0000000003DF8A91 )Processing outgoing parser. msg.From=sip:8230@192.168.1.234;user=phone
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c809 (S4,ParserModule.ProcessOutgoing:parsermodule.cs(513))( 0000000000326668 )controller=<MessageProcessingController_3DF8A91>, sipStack=<SipStack_24B5BA0>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80a (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80b (S4,RawDataBuffer.set_Connection:rawdatabuffer.cs(50))( 0000000003BE1CB6 )set connection=<null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80c (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 0000000003BE1CB6 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80d (S4,SipMessage.DataLoggingHelper:sipmessage.cs(531))
    >>>>>>>>>>>>Outgoing SipMessage c=[<SipTlsConnection_376BB23>], 192.168.1.227:5069->192.168.1.227:50059
    SIP/2.0 202 Accepted
    FROM: <sip:8230@192.168.1.234;user=phone>;tag=168a81ddc9;epid=A362C5045C
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>;tag=ec8bbfcf11
    CSEQ: 3004 SERVICE
    CALL-ID: 2badf9f71c3f4bb2820f3ae3eb16cc9b
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bKAAACC777.8187929C9B483C93;branched=FALSE,SIP/2.0/TLS 192.168.1.234:3542;branch=z9hG4bK47f24b59;ms-received-port=3542;ms-received-cid=A2D00
    CONTENT-LENGTH: 0
    SERVER: RTCC/3.5.0.0
    Tuesday, June 29, 2010 10:32 AM


  • ------------EndOfOutgoing SipMessage

    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80e (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 0000000003BE1CB6 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c80f (S4,MessageProcessingController.ProcessOutgoingBuffer:messageprocessingcontroller.cs(420))( 0000000003DF8A91 )connection=<SipTlsConnection_376BB23>,buffer=<RawDataBuffer_3BE1CB6>
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c810 (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 0000000003BE1CB6 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c811 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.Send 0x190CDD5, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c812 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 00000000010ED731 )Starting Dispatcher on new thread pool thread
    TL_INFO(TF_PROTOCOL) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c813 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(531))
    >>>>>>>>>>>>Outgoing RawDataBuffer 192.168.1.227:5069->192.168.1.227:50059
    SIP/2.0 202 Accepted
    FROM: <sip:8230@192.168.1.234;user=phone>;tag=168a81ddc9;epid=A362C5045C
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>;tag=ec8bbfcf11
    CSEQ: 3004 SERVICE
    CALL-ID: 2badf9f71c3f4bb2820f3ae3eb16cc9b
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bKAAACC777.8187929C9B483C93;branched=FALSE,SIP/2.0/TLS 192.168.1.234:3542;branch=z9hG4bK47f24b59;ms-received-port=3542;ms-received-cid=A2D00
    CONTENT-LENGTH: 0
    SERVER: RTCC/3.5.0.0

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

    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c814 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c815 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 0000000002396DB9 ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c816 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 0000000002396DB9 )Finished  Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c817 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 0000000002396DB9 )Finished
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c818 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.Send 0x190CDD5, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c819 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.Send 0x190CDD5, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81a (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.Send 0x334136C, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.Send 0x190CDD5, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.Send 0x190CDD5, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.Send 0x334136C, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.Send 0x334136C, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c81f (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1186))( 0000000001636F30 ) Enter: EncryptSendBuffer()
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c820 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1068))( 0000000001636F30 ) Enter: PrepareDataAndEncrypt()
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c821 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSingleBuffer:TlsTransportHelper.cpp(1043))( 0000000001636F30 ) EncryptSingleBuffer(); status = 0
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c822 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1164))( 0000000001636F30 ) Exit: PrepareDataAndEncrypt()
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c823 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1222))( 0000000001636F30 ) Exit: EncryptSendBuffer()
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c824 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.Send 0x3571C70, arg1=<TransportsDataBuffer_F38E05>, arg2=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c825 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.Send 0x334136C, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c826 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.Send 0x334136C, arg1=<TransportsDataBuffer_32419D3>, arg2=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c827 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.Send 0x3571C70, arg1=<TransportsDataBuffer_F38E05>, arg2=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c828 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.Send 0x3571C70, arg1=<TransportsDataBuffer_F38E05>, arg2=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c829 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=533
    >>> Outgoing TCP packet BEGIN
    \0x17\0x03\0x01\0x02\0x10\0x92\0xe2\0xc8\0x03F`\0xf2\0xd2\0x12l\0xdb=v5X\0xc7>V\0x85\0xc7#\0xdc^\0xa8D\0xc4\0xff\0xf7Ie\0xea\0xcc\0x11\0xedN\0x18}\0xfc\0xee\0xb7\0xea\0xd6z\0x008\0x14\0xaf\0x96\0x89\0xc1\0x08\0xa9\0x9f\0xe5\0xbdW~*+\0xe8\0x1a\0xa4\0x93\0xa7t\0x0f\0xce\tE(\0xb85Mw^Y-3\0xc7#\0x94!&Tsu\0xee\0xe0... the rest is skipped (non-printable data)
    <<< Outgoing TCP packet END
    TL_VERBOSE(TF_NETWORK) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82a (S4,TcpTransport.Send:tcptransport.cs(243))( 00000000022826EA )SyncIO: Send
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82b (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnSent 0x301BEED, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.Send 0x3571C70, arg1=<TransportsDataBuffer_F38E05>, arg2=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.Send 0x3571C70, arg1=<TransportsDataBuffer_F38E05>, arg2=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnSent 0x301BEED, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c82f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnSent 0x301BEED, arg=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c830 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.OnSent 0x3479411, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c831 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnSent 0x301BEED, arg=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c832 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnSent 0x301BEED, arg=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c833 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.OnSent 0x3479411, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c834 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.OnSent 0x3479411, arg=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c835 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem SipTlsConnection.OnSent 0x276B6C1, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c836 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.OnSent 0x3479411, arg=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c837 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.OnSent 0x3479411, arg=<SipResponse_22A6ED1>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c838 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem SipTlsConnection.OnSent 0x276B6C1, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c839 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem SipTlsConnection.OnSent 0x276B6C1, arg=<SipResponse_22A6ED1> was queued for 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c83a (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c83b (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000022A6ED1 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c83c (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 0000000003AA2E7F )Queueing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c83d (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 0000000003AA2E7F )Starting Dispatcher on new thread pool thread
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c83e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 0000000003AA2E7F )Started
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c83f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback SipTlsConnection.OnSent 0x276B6C1, arg=<SipResponse_22A6ED1> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c840 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 0000000003AA2E7F )Executing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c841 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem SipTlsConnection.OnSent 0x276B6C1, arg=<SipResponse_22A6ED1>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c842 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 0000000003AA2E7F ) workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0CEC::06/29/2010-09:53:39.211.0000c843 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c844 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 0000000003AA2E7F ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c845 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 0000000003AA2E7F )Finished  Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.211.0000c846 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 0000000003AA2E7F )Finished
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c847 (S4,TcpTransport.WinSockReceived:tcptransport.cs(400))( 00000000022826EA )IOCompleted
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c848 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.OnReceived 0x2B78A31, arg=<OverlappedAsyncResult_2434AA5>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c849 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))( 00000000010ED731 )Starting Dispatcher on current worker thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.OnReceived 0x2B78A31, arg=<OverlappedAsyncResult_2434AA5>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.OnReceived 0x2B78A31, arg=<OverlappedAsyncResult_2434AA5> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84d (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=3643
    >>> Incoming TCP packet BEGIN
    \0x17\0x03\0x01\0x12\0x90\0xc5\0x95\0xe5\0xd7\0xba\0xd6GN;wV\0xef\0x90\0xf4\0xedAXe\r\0x1c\0xe0\0xcc\0xfdQ\0xfb\0xc5\0x80`\0x11\tty\0x07\0xdfR\0xec\0xe3Q\0xd2\0x05*\0xaf\0x003\0x1d\0x9e\0xfc\0x98\\0xcbkI\0x90\0x1a\0xb0\0xcc\0xc7\0x0b\0xe2\0xdeF\0xe0\0x10\0x8c\0x92\0xde\0x0e\0x8f'\0x07\0xd2\0xfa\0x91\0x08\0xc1\r;R\0x1b\0x03J\0x0c\0x93(8\0xab'\0x0fN\0x1b\0x04_\0x8d\0x80\0x1d\0xcfi\0xcc-\0x00T\0xfd\0xfd\0x831l&\0xe9\0xb6j\0xa5\0x12F\0xf3\0xdf\0x8f\0x97\0x1f\0xcd\0x88\0xa8\0x8ag\0xf3\0xc9\0x9cE5\0x025=h`=\0xfc\0x10\0x80\0xaau*\0xf8\0xeag\0xe9\0xad\0x10\0xd6\0xc82\0xc5\0xe7\0xf8=\0xd8lr`.Xk?r\0xb3NqwH\0x95*\0xc6,\0x0f\0x15g\0x83(\0x9b\0xb3\0xff\0x018\0xf5\0xcc\0x9f5\0xe0\0xd8\0xce\0xae\0x90q\0x7f\0xc6<?\0xb3G\0xb8\0x129\0xbeln\0xb2iY\0x91\0xdc\0xde.\0x85*\0x83\0xc1\0xd5\0x085\0x0e\0x07\0xdd\0xc3\0xdc\0x91w7\0x86\0x9b\0x84\0x02\0xad\0xf0\0x07\0x9b1\0xaf\0xa4$\0x1b<\0xd8+\0xb0\0x07\0x815\0xfeJ\0xba\0xdeU\0x1a\0xfe\0x82\0xb2/\0x9a\0xf1\0x07\0x9f\0xd0\0x90\0xefzr\0x98\0xb1=\0x91\0x15\0xba\0xbcS^f\0xe27\0x0bS\0xac\0xdd\0x8c`m\0xccBR\0x9d\0x04\0xec\0x82>t\0xe8\0x18\0xc5\0xd9j\0x91\0x92\0xc0*"\0x12a\0xaa\0x86\0xdeT\0xb7\0xb4\0xea$*8\0xd0\0xd4\0xf6\0xd0f\0xb9\0x8a\0xf1\0xd8\0xa3Z\0x1e\0xcd\0xa4\0x10\0x95\0xe8\0xc8r\0x9f\0xe4\0xf1\0x9e\0xa3\0xdf'i\0xceUb\0xd4f\0x81}\0x90\0xd5\0xbfB\0x802J\0x9f\0xc6Q\0xbb\0x9b3\0x0bI\0xaf\0x87W\0x9aE\0x1c\0x92\0xf5\0x11\0xd5\0xe3t\0xf9n\0xa0\0xd5\0xc4\0xdb\0x1a\0xef\0x98\0x07\0x80l\0xfb\0x08\0xa3^\0x955\0xee\0x00\0xc2\0x99pg;q\0xb70(\0xb5\0x1b\0x1a\0x1f\0xa9\0x07\0x01\0xb8ch\0xd4?PBqUx\0xba\0xae\0x85\0x83\0xf7&?=\0xeb\0xe0\0xd0\0x07\0xdeP\0xe0}\0x18\0xca\0xadoo\0xe8K\0xa1\0x00\0x1c'\0xb8\0xa9\0xa6\0x14\0xe7"a\0xb8\0xf0\0x8e\0xcdV\0x9b:\0x94\0x99\0xcb\0xc96\0xe6a\0xfc@\0xe5x\0xd4\0x9d\0xaf\0xf4\0x19\0x92\0xb0\0xd5\0xafw\0xab\0x16\0x8d\0xeb\0xb6\0xd05\0xfd\0xf4\0xf9v\0xbf\0x98_\0x9e\0x12OD\0xfa\0x10\0x06\0x01~\0xf9\0x98\0xefk\0x97K\0x96\0x00\0xed#\0x15\0x91\0xd0B\0xe1\0xe4\0xbf\0x08;j\0xe0X^\0x9b{\0x017\0xc1\0xa4y\0xbc\0x0cjn\0xa9N\0xfb(G\0x18dy\0xf9\0xa5\0xe8j\0xb49\0x1b... the rest is skipped (non-printable data)
    <<< Incoming TCP packet END
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84e (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnReceived 0x1D41F15, arg=<TransportsDataBuffer_24976C3>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c84f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.OnReceived 0x2B78A31, arg=<OverlappedAsyncResult_2434AA5> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c850 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.OnReceived 0x2B78A31, arg=<OverlappedAsyncResult_2434AA5>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c851 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnReceived 0x1D41F15, arg=<TransportsDataBuffer_24976C3>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c852 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnReceived 0x1D41F15, arg=<TransportsDataBuffer_24976C3> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c853 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1245))( 0000000001636F30 ) Enter: DecryptReceiveBuffer()
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c854 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1349))( 0000000001636F30 ) Exit: DecryptReceiveBuffer(); status = MoreData
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c855 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.ReceiveMore 0x2E9E054, arg=<TransportsDataBuffer_24976C3>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c856 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnReceived 0x1D41F15, arg=<TransportsDataBuffer_24976C3> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c857 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnReceived 0x1D41F15, arg=<TransportsDataBuffer_24976C3>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c858 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.ReceiveMore 0x2E9E054, arg=<TransportsDataBuffer_24976C3>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c859 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.ReceiveMore 0x2E9E054, arg=<TransportsDataBuffer_24976C3> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85a (S4,TcpTransport.ReceiveMore:tcptransport.cs(332))( 00000000022826EA )IOStart: Receive (block)
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.ReceiveMore 0x2E9E054, arg=<TransportsDataBuffer_24976C3> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.ReceiveMore 0x2E9E054, arg=<TransportsDataBuffer_24976C3>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85e (S4,TcpTransport.WinSockReceived:tcptransport.cs(400))( 00000000022826EA )IOCompleted
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c85f (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.OnReceived 0x31C6ED4, arg=<OverlappedAsyncResult_3FF7B6C>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c860 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(133))( 00000000010ED731 )Starting Dispatcher on current worker thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c861 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c862 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.OnReceived 0x31C6ED4, arg=<OverlappedAsyncResult_3FF7B6C>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c863 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.OnReceived 0x31C6ED4, arg=<OverlappedAsyncResult_3FF7B6C> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c864 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=4757
    >>> Incoming TCP packet BEGIN
    \0x17\0x03\0x01\0x12\0x90\0xc5\0x95\0xe5\0xd7\0xba\0xd6GN;wV\0xef\0x90\0xf4\0xedAXe\r\0x1c\0xe0\0xcc\0xfdQ\0xfb\0xc5\0x80`\0x11\tty\0x07\0xdfR\0xec\0xe3Q\0xd2\0x05*\0xaf\0x003\0x1d\0x9e\0xfc\0x98\\0xcbkI\0x90\0x1a\0xb0\0xcc\0xc7\0x0b\0xe2\0xdeF\0xe0\0x10\0x8c\0x92\0xde\0x0e\0x8f'\0x07\0xd2\0xfa\0x91\0x08\0xc1\r;R\0x1b\0x03J\0x0c\0x93(8\0xab'\0x0fN\0x1b\0x04_\0x8d\0x80\0x1d\0xcfi\0xcc-\0x00T\0xfd\0xfd\0x831l&\0xe9\0xb6j\0xa5\0x12F\0xf3\0xdf\0x8f\0x97\0x1f\0xcd\0x88\0xa8\0x8ag\0xf3\0xc9\0x9cE5\0x025=h`=\0xfc\0x10\0x80\0xaau*\0xf8\0xeag\0xe9\0xad\0x10\0xd6\0xc82\0xc5\0xe7\0xf8=\0xd8lr`.Xk?r\0xb3NqwH\0x95*\0xc6,\0x0f\0x15g\0x83(\0x9b\0xb3\0xff\0x018\0xf5\0xcc\0x9f5\0xe0\0xd8\0xce\0xae\0x90q\0x7f\0xc6<?\0xb3G\0xb8\0x129\0xbeln\0xb2iY\0x91\0xdc\0xde.\0x85*\0x83\0xc1\0xd5\0x085\0x0e\0x07\0xdd\0xc3\0xdc\0x91w7\0x86\0x9b\0x84\0x02\0xad\0xf0\0x07\0x9b1\0xaf\0xa4$\0x1b<\0xd8+\0xb0\0x07\0x815\0xfeJ\0xba\0xdeU\0x1a\0xfe\0x82\0xb2/\0x9a\0xf1\0x07\0x9f\0xd0\0x90\0xefzr\0x98\0xb1=\0x91\0x15\0xba\0xbcS^f\0xe27\0x0bS\0xac\0xdd\0x8c`m\0xccBR\0x9d\0x04\0xec\0x82>t\0xe8\0x18\0xc5\0xd9j\0x91\0x92\0xc0*"\0x12a\0xaa\0x86\0xdeT\0xb7\0xb4\0xea$*8\0xd0\0xd4\0xf6\0xd0f\0xb9\0x8a\0xf1\0xd8\0xa3Z\0x1e\0xcd\0xa4\0x10\0x95\0xe8\0xc8r\0x9f\0xe4\0xf1\0x9e\0xa3\0xdf'i\0xceUb\0xd4f\0x81}\0x90\0xd5\0xbfB\0x802J\0x9f\0xc6Q\0xbb\0x9b3\0x0bI\0xaf\0x87W\0x9aE\0x1c\0x92\0xf5\0x11\0xd5\0xe3t\0xf9n\0xa0\0xd5\0xc4\0xdb\0x1a\0xef\0x98\0x07\0x80l\0xfb\0x08\0xa3^\0x955\0xee\0x00\0xc2\0x99pg;q\0xb70(\0xb5\0x1b\0x1a\0x1f\0xa9\0x07\0x01\0xb8ch\0xd4?PBqUx\0xba\0xae\0x85\0x83\0xf7&?=\0xeb\0xe0\0xd0\0x07\0xdeP\0xe0}\0x18\0xca\0xadoo\0xe8K\0xa1\0x00\0x1c'\0xb8\0xa9\0xa6\0x14\0xe7"a\0xb8\0xf0\0x8e\0xcdV\0x9b:\0x94\0x99\0xcb\0xc96\0xe6a\0xfc@\0xe5x\0xd4\0x9d\0xaf\0xf4\0x19\0x92\0xb0\0xd5\0xafw\0xab\0x16\0x8d\0xeb\0xb6\0xd05\0xfd\0xf4\0xf9v\0xbf\0x98_\0x9e\0x12OD\0xfa\0x10\0x06\0x01~\0xf9\0x98\0xefk\0x97K\0x96\0x00\0xed#\0x15\0x91\0xd0B\0xe1\0xe4\0xbf\0x08;j\0xe0X^\0x9b{\0x017\0xc1\0xa4y\0xbc\0x0cjn\0xa9N\0xfb(G\0x18dy\0xf9\0xa5\0xe8j\0xb49\0x1bw\0xc4\0x08`y\0xa7\0x82l\0xb4\0xc9\0x0c@\0xd0\0xb4m\0x0fe\0xfeN\0x8cjw\0xbfBi\0x19`D\0xb8\0x12L\0xc0bs\0xearp\0x18\0x89/\0xf7\0xc2=\0xa9q/*:c\0xd9,\0xc3C<\0xfb\0xcd\0x16d\0xae\0x0c\0xca\0x0bw\0xab\0x18\0x91\0x07\0xbf\0xa3?\0xf1\0xea\0xb9\0xc8\0x1d=a\0x1c\0x1a\0xd7h\0xdb\k'g_\0xaf\0x8a\0x9c\0xb1\0xdfU\0x99j\0xd3`B\0x18\0xa8\0xc5a\0xc0M\0x91\0xe0\0x7f\0x10\0xd6\0xd20\0x00-\0x01D\0xde\0x98\0x98\0x1f-\0x0f\0xe1e\0x02k\0xb2\0xb2\0x81\0xab\0x9e\0x1a\0xf8=\0xdd\0xbd#&A\0xd1\0xb4\0x1d&SE\0xda\0x86\0x03\0xde\0xe6r\0xac\0x7fv\0xf7\0x08|\0xe1\0x07\0xa6\0xe8\0x92\0xa0\0x1e\0x9b!\0xe0\0xe8\0x0ec\0x0c$\0x0e\0x8a5\0xdf\0xa1j\0xd0... the rest is skipped (non-printable data)
    <<< Incoming TCP packet END
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c865 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnReceived 0x3E8B200, arg=<TransportsDataBuffer_3E74A0A>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c866 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.OnReceived 0x31C6ED4, arg=<OverlappedAsyncResult_3FF7B6C> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c867 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.OnReceived 0x31C6ED4, arg=<OverlappedAsyncResult_3FF7B6C>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c868 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnReceived 0x3E8B200, arg=<TransportsDataBuffer_3E74A0A>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c869 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnReceived 0x3E8B200, arg=<TransportsDataBuffer_3E74A0A> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.264.0000c86a (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::DecryptReceiveBuffer:TlsTransportHelper.cpp(1245))( 0000000001636F30 ) Enter: DecryptReceiveBuffer()
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c86b (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.OnReceived 0x3A803DB, arg=<TransportsDataBuffer_88AD8D>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c86c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnReceived 0x3E8B200, arg=<TransportsDataBuffer_3E74A0A> took 0.9766 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c86d (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnReceived 0x3E8B200, arg=<TransportsDataBuffer_3E74A0A>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c86e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.OnReceived 0x3A803DB, arg=<TransportsDataBuffer_88AD8D>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c86f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.OnReceived 0x3A803DB, arg=<TransportsDataBuffer_88AD8D> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c870 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem SipTlsConnection.OnReceived 0x681EC, arg=<TransportsDataBuffer_88AD8D>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c871 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.OnReceived 0x3A803DB, arg=<TransportsDataBuffer_88AD8D> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c872 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.OnReceived 0x3A803DB, arg=<TransportsDataBuffer_88AD8D>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c873 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem SipTlsConnection.OnReceived 0x681EC, arg=<TransportsDataBuffer_88AD8D>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c874 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem SipTlsConnection.OnReceived 0x681EC, arg=<TransportsDataBuffer_88AD8D> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c875 (S4,RawDataBuffer.set_Connection:rawdatabuffer.cs(50))( 000000000124D683 )set connection=<null>-><SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c876 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(564))
    <<<<<<<<<<<<Incoming RawDataBuffer 192.168.1.227:5069<-192.168.1.227:50059
    
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c877 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(581))$$$SplitMessageSegmentBegin$$$ <OutboundStream Id="4214722080" Start="2010-06-29T10:53:28.3396855+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter>
                <InterArrival>2</InterArrival>
                <InterArrivalMax>2</InterArrivalMax>
              </Jitter>
              <PacketLoss />
              <Delay>
                <RoundTrip>0</RoundTrip>
                <RoundTripMax>0</RoundTripMax>
              </Delay>
              <Utilization>
                <Packets>174</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio>
                <PayloadType>115</PayloadType>
                <PayloadDescription>x-msrta</PayloadDescription>
                <SampleRate>8000</SampleRate>
              </Audio>
            </Payload>
          </OutboundStream>
        </MediaLine>
      </VQSessionReport>
    </VQReportE------------EndOfIncoming RawDataBuffer

    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c878 (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 000000000124D683 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c879 (S4,SipMessage.set_Connection:sipmessage.cs(211))( 000000000379B528 )connection set <null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87a (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87b (S4,SipMessage.DataLoggingHelper:sipmessage.cs(564))
    <<<<<<<<<<<<Incoming SipMessage c=[<SipTlsConnection_376BB23>], 192.168.1.227:5069<-192.168.1.227:50059
    SERVICE sip:mydomainocs01.mydomain.com:5069;grid SIP/2.0
    FROM: <sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone>;epid=A362C5045C;tag=f230354b92
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>
    CSEQ: 3005 SERVICE
    CALL-ID: 97e5a0c5927a4c978f20e1b486ab8b29
    MAX-FORWARDS: 69
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bK44DE37D4.F53DFAEB9B4B2C93;branched=FALSE
    VIA: SIP/2.0/TLS 192.168.1.234:3557;branch=z9hG4bK86c905d;ms-received-port=3557;ms-received-cid=A3100
    CONTENT-LENGTH: 4085
    USER-AGENT: RTCC/3.5.0.0 MediationServer
    CONTENT-TYPE: application/vq-rtcpxr+xml

    <?xml version="1.0"?>
    <VQReportEvent xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" Version="1.1" xmlns="ms-rtcp-metrics">
      <VQSessionReport SessionId="16972244-c3d4-4324-91f7-46f2db483a2d;from-tag=8df75297b0;to-tag=e7839fdff4">
        <LocationProfile>mydomainumdial.mydomain.com</LocationProfile>
        <Endpoint Name="mydomainmed01.mydomain.com" />
        <DialogInfo CallId="16972244-c3d4-4324-91f7-46f2db483a2d" FromTag="8df75297b0" ToTag="e7839fdff4" Start="2010-06-29T10:53:36.0897847+01:00" End="2010-06-29T10:53:39.7148311+01:00">
          <DialogCategory>OCS</DialogCategory>
          <CorrelationID>16972244-c3d4-4324-91f7-46f2db483a2d;from-tag=8df75297b0;to-tag=e7839fdff4</CorrelationID>
          <FromURI>sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone</FromURI>
          <ToURI>sip:8230;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone</ToURI>
          <Caller>true</Caller>
          <LocalContactURI>sip:mydomainmed01.mydomain.com@mydomain.com;gruu;opaque=srvr:MediationServer:nc92k5VOXUyvgijcrqfCtQAA;grid=0663c694aad44d25b81bfcd281740c3c</LocalContactURI>
          <RemoteContactURI>sip:mydomainexc02.mydomain.com:5066;transport=Tls</RemoteContactURI>
          <LocalUserAgent>RTCC/3.5.0.0 MediationServer/3.5.6907.0</LocalUserAgent>
          <RemoteUserAgent>RTCC/3.0.0.0</RemoteUserAgent>
          <LocalPAI>sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone</LocalPAI>
        </DialogInfo>
        <MediaLine Label="main-audio">
          <Description>
            <Connectivity>
              <Ice>DIRECT</Ice>
            </Connectivity>
            <Security>SRTP</Security>
            <Offerer>true</Offerer>
            <Transport>UDP</Transport>
            <LocalAddr>
              <IPAddr>192.168.1.228</IPAddr>
              <Port>61865</Port>
              <Inside>true</Inside>
              <SubnetMask>255.255.255.0</SubnetMask>
            </LocalAddr>
            <RemoteAddr>
              <IPAddr>192.168.1.222</IPAddr>
              <Port>6912</Port>
            </RemoteAddr>
          </Description>
          <InboundStream Id="3756956364" Start="2010-06-29T10:53:28.3396855+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter>
                <InterArrival>2</InterArrival>
                <InterArrivalMax>2</InterArrivalMax>
              </Jitter>
              <PacketLoss />
              <BurstGapLoss>
                <BurstDensity>0</BurstDensity>
                <BurstDuration>0</BurstDuration>
                <GapDensity>0</GapDensity>
                <GapDuration>1620</GapDuration>
              </BurstGapLoss>
              <Utilization>
                <Packets>147</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio />
            </Payload>
            <QualityEstimates>
              <Audio>
                <NetworkMOS>
                  <OverallAvg>3.61</OverallAvg>
                  <OverallMin>3.61</OverallMin>
                  <DegradationAvg>0</DegradationAvg>
                  <DegradationMax>0</DegradationMax>
                  <DegradationJitterAvg>0</DegradationJitterAvg>
                  <DegradationPacketLossAvg>0</DegradationPacketLossAvg>
                </NetworkMOS>
              </Audio>
            </QualityEstimates>
          </InboundStream>
          <Out$$$SplitMessageSegmentEnd$$$
    TL_INFO(TF_PROTOCOL) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87c (S4,SipMessage.DataLoggingHelper:sipmessage.cs(581))$$$SplitMessageSegmentBegin$$$boundStream Id="4214722080" Start="2010-06-29T10:53:28.3396855+01:00" End="2010-06-29T10:53:39.6679555+01:00">
            <Network>
              <Jitter>
                <InterArrival>2</InterArrival>
                <InterArrivalMax>2</InterArrivalMax>
              </Jitter>
              <PacketLoss />
              <Delay>
                <RoundTrip>0</RoundTrip>
                <RoundTripMax>0</RoundTripMax>
              </Delay>
              <Utilization>
                <Packets>174</Packets>
              </Utilization>
            </Network>
            <Payload>
              <Audio>
                <PayloadType>115</PayloadType>
                <PayloadDescription>x-msrta</PayloadDescription>
                <SampleRate>8000</SampleRate>
              </Audio>
            </Payload>
          </OutboundStream>
        </MediaLine>
      </VQSessionReport>
    </VQReportEvent>------------EndOfIncoming SipMessage


    Tuesday, June 29, 2010 10:38 AM
  • TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87d (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(449))( 0000000003DF8A91 )Processing routing.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87e (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(457))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c87f (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(467))( 0000000003DF8A91 )Processing authentication.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c880 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(475))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c881 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(485))( 0000000003DF8A91 )Processing state manager.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c882 (S4,MessageProcessingController.ProcessIncomingMessage:messageprocessingcontroller.cs(493))( 0000000003DF8A91 )Status=1
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c883 (S4,MessageProcessingController.OnMessageReceived:messageprocessingcontroller.cs(288))( 0000000003DF8A91 )Indicating message received to sip stack
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c884 (S4,SipStack.OnMessageReceived:sipstack.cs(1492))( 00000000024B5BA0 )Indicating message received to core layer
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c885 (S4,SipCoreManager.OnMessageReceived:sipcorelayer.cs(3992))( 00000000033F1B47 )Calling ProcessIncomingRequest
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c886 (S4,SipCoreManager.ProcessIncomingRequest:sipcorelayer.cs(3808))( 00000000033F1B47 )Invoking request received event handler
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c887 (S4,SipCoreManager.ProcessIncomingServiceRequest:sipcorelayer.cs(3261))( 00000000033F1B47 )Incoming Service Request
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c888 (S4,StateManagerModule.RegisterTransaction:statemanagermodule.cs(281))( 000000000217CB8C )Registering transaction SERVICE:z9hG4bK44DE37D4.F53DFAEB9B4B2C93
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c889 (S4,StateManagerModule.EnsureCallContext:statemanagermodule.cs(505))( 000000000217CB8C )Attempting to create call context for 97e5a0c5927a4c978f20e1b486ab8b29
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c88a (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000022EC7B6 )Queueing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c88b (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 00000000022EC7B6 )Starting Dispatcher on new thread pool thread
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c88c (S4,MessageProcessingController.OnMessageReceived:messageprocessingcontroller.cs(290))( 0000000003DF8A91 )OnMessageReceived returned
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c88d (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c88e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000022EC7B6 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c88f (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.Receive 0x64D82A
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c890 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000022EC7B6 )Executing Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c891 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000022EC7B6 ) workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem was queued for 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c892 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback SipTlsConnection.OnReceived 0x681EC, arg=<TransportsDataBuffer_88AD8D> took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c893 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem SipTlsConnection.OnReceived 0x681EC, arg=<TransportsDataBuffer_88AD8D>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c894 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.Receive 0x64D82A
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c895 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.Receive 0x64D82A was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c896 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.Receive 0x1B9FF77
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c897 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c898 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.Receive 0x64D82A took 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c899 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89a (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.Receive 0x64D82A
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89b (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.Receive 0x1B9FF77
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89c (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.Receive 0x1B9FF77 was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89d (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.Receive 0x1B1E7EF
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89e (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.Receive 0x1B9FF77 took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c89f (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.Receive 0x1B9FF77
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.Receive 0x1B1E7EF
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.Receive 0x1B1E7EF was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a2 (S4,TcpTransport.ReceiveMore:tcptransport.cs(315))( 00000000022826EA )IOStart: Receive
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.Receive 0x1B1E7EF took 0 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.Receive 0x1B1E7EF
    TL_INFO(TF_COMPONENT) [0]0CE4.0DA0::06/29/2010-09:53:39.265.0000c8a5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_VERBOSE(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c8a6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000022EC7B6 ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem took 0 mseconds
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c8a7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000022EC7B6 )Finished  Workitem Microsoft.Rtc.Internal.Sip.DispatchEventWorkitem
    TL_INFO(TF_COMPONENT) [2]0CE4.0E6C::06/29/2010-09:53:39.265.0000c8a8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000022EC7B6 )Finished
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.265.0000c8a9 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8aa (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8ab (S4,SipMessage.set_Connection:sipmessage.cs(211))( 00000000010344F7 )connection set <null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8ac (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8ad (S4,SipStack.SendMessage:sipstack.cs(1151))( 00000000024B5BA0 )controller=<MessageProcessingController_3DF8A91>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8ae (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))( 0000000003DF8A91 )message.from=sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8af (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(585))( 0000000003DF8A91 )Processing outgoing state manager. this.stateManagerModule=<StateManagerModule_217CB8C>.
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b0 (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(197))( 000000000217CB8C )Processing outgoing msg <SipResponse_10344F7>, msg.Trans=<IncomingServiceTransaction_1860B93>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b1 (S4,StateManagerModule.ProcessOutgoing:statemanagermodule.cs(248))( 000000000217CB8C )response.dialog=<null>, response.tran.dialogContext=<null>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b2 (S4,StateManagerModule.UnregisterTransaction:statemanagermodule.cs(335))( 000000000217CB8C )Unregistering transaction SERVICE:z9hG4bK44DE37D4.F53DFAEB9B4B2C93
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b3 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 000000000379B528 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b4 (S4,StateManagerModule.CheckCallContextReferences:statemanagermodule.cs(565))( 000000000217CB8C )<Dictionary`2_1A10B6F>.Remove(97e5a0c5927a4c978f20e1b486ab8b29);
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b5 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(602))( 0000000003DF8A91 )Processing outgoing routing.
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b6 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b7 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b8 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8b9 (S4,SipConnection.MessageProcessingWorkitem.constructor:sipconnection.cs(1225))message=<SipResponse_10344F7>, controller=<ConnectionControlModule_2CAD4C9>
    TL_INFO(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8ba (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 0000000002396DB9 )Queueing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_INFO(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:39.266.0000c8bb (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 0000000002396DB9 )Starting Dispatcher on new thread pool thread
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8bc (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 0000000002396DB9 )Started
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8bd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 0000000002396DB9 )Executing Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8be (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 0000000002396DB9 ) workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8bf (S4,ConnectionControlModule.HandlePostponedMessage:connectioncontrolmodule.cs(1610))( 0000000002CAD4C9 )message.from=sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone, controller=<MessageProcessingController_3DF8A91>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c0 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c1 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c2 (S4,MessageProcessingController.ProcessMessage:messageprocessingcontroller.cs(226))( 0000000003DF8A91 )message.from=sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c3 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(700))( 0000000003DF8A91 )Processing outgoing routed.
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c4 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c5 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c6 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(717))( 0000000003DF8A91 )Processing outgoing authentication. authModule=<AuthenticationModule_209383C>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c7 (S4,MessageProcessingController.ProcessOutgoingMessage:messageprocessingcontroller.cs(736))( 0000000003DF8A91 )Processing outgoing parser. msg.From=sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.266.0000c8c8 (S4,ParserModule.ProcessOutgoing:parsermodule.cs(513))( 0000000000326668 )controller=<MessageProcessingController_3DF8A91>, sipStack=<SipStack_24B5BA0>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8c9 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8ca (S4,RawDataBuffer.set_Connection:rawdatabuffer.cs(50))( 00000000010AF16B )set connection=<null>-><SipTlsConnection_376BB23>
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8cb (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 00000000010AF16B )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_PROTOCOL) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8cc (S4,SipMessage.DataLoggingHelper:sipmessage.cs(531))
    >>>>>>>>>>>>Outgoing SipMessage c=[<SipTlsConnection_376BB23>], 192.168.1.227:5069->192.168.1.227:50059
    SIP/2.0 202 Accepted
    FROM: <sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone>;tag=f230354b92;epid=A362C5045C
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>;tag=a8163ece7d
    CSEQ: 3005 SERVICE
    CALL-ID: 97e5a0c5927a4c978f20e1b486ab8b29
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bK44DE37D4.F53DFAEB9B4B2C93;branched=FALSE,SIP/2.0/TLS 192.168.1.234:3557;branch=z9hG4bK86c905d;ms-received-port=3557;ms-received-cid=A3100
    CONTENT-LENGTH: 0
    SERVER: RTCC/3.5.0.0

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

    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8cd (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 00000000010AF16B )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8ce (S4,MessageProcessingController.ProcessOutgoingBuffer:messageprocessingcontroller.cs(420))( 0000000003DF8A91 )connection=<SipTlsConnection_376BB23>,buffer=<RawDataBuffer_10AF16B>
    TL_VERBOSE(TF_NETWORK) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8cf (S4,RawDataBuffer.get_Connection:rawdatabuffer.cs(43))( 00000000010AF16B )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d0 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.Send 0x1E5CDD0, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d1 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 00000000010ED731 )Starting Dispatcher on new thread pool thread
    TL_INFO(TF_PROTOCOL) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d2 (S4,SipMessage.DataLoggingHelper:sipmessage.cs(531))
    >>>>>>>>>>>>Outgoing RawDataBuffer 192.168.1.227:5069->192.168.1.227:50059
    SIP/2.0 202 Accepted
    FROM: <sip:1234567890;phone-context=mydomainumdial.mydomain.com@mydomain.com;user=phone>;tag=f230354b92;epid=A362C5045C
    TO: <sip:mydomainocs01.mydomain.com@mydomain.com;gruu;opaque=srvr:QoS:i9Y4cLNIq0iF3tPKpY8koAAA>;tag=a8163ece7d
    CSEQ: 3005 SERVICE
    CALL-ID: 97e5a0c5927a4c978f20e1b486ab8b29
    VIA: SIP/2.0/TLS 192.168.1.227:50059;branch=z9hG4bK44DE37D4.F53DFAEB9B4B2C93;branched=FALSE,SIP/2.0/TLS 192.168.1.234:3557;branch=z9hG4bK86c905d;ms-received-port=3557;ms-received-cid=A3100
    CONTENT-LENGTH: 0
    SERVER: RTCC/3.5.0.0

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

    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8d3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 00000000010ED731 )Started
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 0000000002396DB9 ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem took 0.9766 mseconds
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 0000000002396DB9 )Finished  Workitem Microsoft.Rtc.Internal.Sip.SipConnection+MessageProcessingWorkitem
    TL_INFO(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:39.267.0000c8d6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 0000000002396DB9 )Finished
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8d7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.Send 0x1E5CDD0, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8d8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.Send 0x1E5CDD0, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8d9 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.Send 0x28685A1, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8da (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.Send 0x1E5CDD0, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8db (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.Send 0x1E5CDD0, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8dc (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.Send 0x28685A1, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8dd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.Send 0x28685A1, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7> was queued for 0 mseconds
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8de (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1186))( 0000000001636F30 ) Enter: EncryptSendBuffer()
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8df (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1068))( 0000000001636F30 ) Enter: PrepareDataAndEncrypt()
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e0 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSingleBuffer:TlsTransportHelper.cpp(1043))( 0000000001636F30 ) EncryptSingleBuffer(); status = 0
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e1 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::PrepareDataAndEncrypt:TlsTransportHelper.cpp(1164))( 0000000001636F30 ) Exit: PrepareDataAndEncrypt()
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e2 (S4,Microsoft::Rtc::Internal::Sip::TlsTransportHelper::EncryptSendBuffer:TlsTransportHelper.cpp(1222))( 0000000001636F30 ) Exit: EncryptSendBuffer()
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e3 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TcpTransport.Send 0x3230CC9, arg1=<TransportsDataBuffer_26C3FAB>, arg2=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e4 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.Send 0x28685A1, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.Send 0x28685A1, arg1=<TransportsDataBuffer_3D9E214>, arg2=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TcpTransport.Send 0x3230CC9, arg1=<TransportsDataBuffer_26C3FAB>, arg2=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TcpTransport.Send 0x3230CC9, arg1=<TransportsDataBuffer_26C3FAB>, arg2=<SipResponse_10344F7> was queued for 0 mseconds
    TL_INFO(TF_PROTOCOL) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e8 (S4,TcpTransport.TraceNetworkPacket:tcptransport.cs(559))( 00000000022826EA )Packet size=565
    >>> Outgoing TCP packet BEGIN
    \0x17\0x03\0x01\0x020\0xda\0x92I 7\0xd3\0x93\0x02\0xce\0x05I\0xd9\0xdb\0x11\0x19\0x14\0xf4\0x9b\0x1c\0xc0/pn\0xa4\0x1c\0xe0\0x9e\0x1dJ\0xcb\0xf7\0x01}{\0xaf\0x89\0xfbz\0xf7n)\0x18Q\0x0c\0x1e\0x98a<8=\0xdc\0x8a*h\0xec\0x0c\0x88\0x00\0xa2\0xa8\0xfb\0xa3\0xa1\0xc1\0xa2\0x8b,\0xa4w\0xc8\0x17\0x08\0x9c9PQ\0x87QB\0xea... the rest is skipped (non-printable data)
    <<< Outgoing TCP packet END
    TL_VERBOSE(TF_NETWORK) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8e9 (S4,TcpTransport.Send:tcptransport.cs(243))( 00000000022826EA )SyncIO: Send
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ea (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem TlsTransport.OnSent 0x9237C1, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8eb (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TcpTransport.Send 0x3230CC9, arg1=<TransportsDataBuffer_26C3FAB>, arg2=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ec (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TcpTransport.Send 0x3230CC9, arg1=<TransportsDataBuffer_26C3FAB>, arg2=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ed (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem TlsTransport.OnSent 0x9237C1, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ee (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem TlsTransport.OnSent 0x9237C1, arg=<SipResponse_10344F7> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ef (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem CompressionTransport.OnSent 0x24771DA, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f0 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback TlsTransport.OnSent 0x9237C1, arg=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f1 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem TlsTransport.OnSent 0x9237C1, arg=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f2 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem CompressionTransport.OnSent 0x24771DA, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f3 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem CompressionTransport.OnSent 0x24771DA, arg=<SipResponse_10344F7> was queued for 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f4 (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 00000000010ED731 )Queueing Workitem SipTlsConnection.OnSent 0xFA1E62, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f5 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback CompressionTransport.OnSent 0x24771DA, arg=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f6 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem CompressionTransport.OnSent 0x24771DA, arg=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f7 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 00000000010ED731 )Executing Workitem SipTlsConnection.OnSent 0xFA1E62, arg=<SipResponse_10344F7>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f8 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 00000000010ED731 ) workitem SipTlsConnection.OnSent 0xFA1E62, arg=<SipResponse_10344F7> was queued for 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8f9 (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8fa (S4,SipMessage.get_Connection:sipmessage.cs(205))( 00000000010344F7 )return connection=<SipTlsConnection_376BB23>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8fb (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(79))( 0000000003AA2E7F )Queueing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8fc (S4,SingleThreadedDispatcherQueue.Enqueue:eventdispatcherqueue.cs(138))( 0000000003AA2E7F )Starting Dispatcher on new thread pool thread
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8fd (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 00000000010ED731 ) <unknown> queue workitem callback SipTlsConnection.OnSent 0xFA1E62, arg=<SipResponse_10344F7> took 0 mseconds
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8fe (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 00000000010ED731 )Finished  Workitem SipTlsConnection.OnSent 0xFA1E62, arg=<SipResponse_10344F7>
    TL_INFO(TF_COMPONENT) [3]0CE4.0E6C::06/29/2010-09:53:39.267.0000c8ff (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 00000000010ED731 )Finished
    TL_INFO(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c900 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(169))( 0000000003AA2E7F )Started
    TL_INFO(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c901 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(204))( 0000000003AA2E7F )Executing Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_VERBOSE(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c902 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(221))( 0000000003AA2E7F ) workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem was queued for 0 mseconds
    TL_VERBOSE(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c903 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(236))( 0000000003AA2E7F ) <unknown> queue workitem callback Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem took 0 mseconds
    TL_INFO(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c904 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(274))( 0000000003AA2E7F )Finished  Workitem Microsoft.Rtc.Internal.Sip.SipStack+MessageSentWorkitem
    TL_INFO(TF_COMPONENT) [1]0CE4.0E04::06/29/2010-09:53:39.267.0000c905 (S4,SingleThreadedDispatcherQueue.DispatcherCallback:eventdispatcherqueue.cs(306))( 0000000003AA2E7F )Finished
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:39.456.0000c906 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002EB4292 ) signal Time = 326743421
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0F70::06/29/2010-09:53:39.456.0000c907 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000002E55B17 ) signal Time = 326743421
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0E4C::06/29/2010-09:53:39.456.0000c908 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001038339 ) signal Time = 326743421
    TL_VERBOSE(TF_COMPONENT) [2]0CC0.0ED4::06/29/2010-09:53:39.456.0000c909 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002EB4292 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [3]0CC0.0F70::06/29/2010-09:53:39.456.0000c90a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000002E55B17 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [1]0CC0.0E4C::06/29/2010-09:53:39.456.0000c90b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001038339 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:40.331.0000c90c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003F38432 ) signal Time = 326744296
    TL_VERBOSE(TF_COMPONENT) [0]0CC0.0E4C::06/29/2010-09:53:40.331.0000c90d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003F38432 ) Expiring interval 17
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:40.837.0000c90e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001D21280 ) signal Time = 326744796
    TL_VERBOSE(TF_COMPONENT) [3]0A38.0C98::06/29/2010-09:53:40.837.0000c90f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001D21280 ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:40.837.0000c910 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001C996DB ) signal Time = 326744796
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:40.837.0000c911 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 00000000006216E0 ) signal Time = 326744796
    TL_VERBOSE(TF_COMPONENT) [1]0A38.0D2C::06/29/2010-09:53:40.837.0000c912 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 00000000006216E0 ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [0]0A38.1010::06/29/2010-09:53:40.837.0000c913 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001C996DB ) Expiring interval 19
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:40.956.0000c914 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003106CA3 ) signal Time = 326744921
    TL_VERBOSE(TF_COMPONENT) [3]0CE4.0CEC::06/29/2010-09:53:40.956.0000c915 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003106CA3 ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:40.956.0000c916 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000564474 ) signal Time = 326744921
    TL_VERBOSE(TF_COMPONENT) [1]0CE4.0E6C::06/29/2010-09:53:40.956.0000c917 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 000000000136B561 ) signal Time = 326744921
    TL_VERBOSE(TF_COMPONENT) [1]0CE4.0E6C::06/29/2010-09:53:40.956.0000c918 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 000000000136B561 ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [0]0CE4.0E04::06/29/2010-09:53:40.956.0000c919 (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000564474 ) Expiring interval 10
    TL_VERBOSE(TF_COMPONENT) [3]01AC.160C::06/29/2010-09:53:41.207.0000c91a (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000003793BEF ) signal Time = 326745171
    TL_VERBOSE(TF_COMPONENT) [3]01AC.160C::06/29/2010-09:53:41.207.0000c91b (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000003793BEF ) Expiring interval 8
    TL_VERBOSE(TF_COMPONENT) [2]01AC.1064::06/29/2010-09:53:41.207.0000c91c (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000000B049CF ) signal Time = 326745171
    TL_VERBOSE(TF_COMPONENT) [2]01AC.1064::06/29/2010-09:53:41.207.0000c91d (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000000B049CF ) Expiring interval 8
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:41.221.0000c91e (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(423))( 0000000001FE585E ) signal Time = 326745187
    TL_VERBOSE(TF_COMPONENT) [1]01AC.10F0::06/29/2010-09:53:41.221.0000c91f (S4,Microsoft::Rtc::Internal::Sip::TimerWheel::timer_Elapsed:TimerWheel.cpp(439))( 0000000001FE585E ) Expiring interval 8
    Tuesday, June 29, 2010 10:39 AM
  • can you please email me the ocslogger.txt file to kingma10 at live dot com?
    Mark King | MCTS:UC Voice | MCSE: Messaging | MCITP:Enterprise Messaging | CCNA | www.unplugthepbx.com
    Tuesday, June 29, 2010 1:28 PM
  • Hi,

    Can you try a couple things:

    1) change the user's "call forwarding settings" to forward all calls to their cell (or some other destination) and see if the call is able to ring out

    2) try assigning a new line uri to the problem user; logout log back in  & try again

    3) if the problem user is remote (off network) try having them log in from inside the firewall

    Regards,

    Matt


    Matt McGillen, PointBridge - https://blogs.pointbridge.com/Blogs/mcgillen_matt/default.aspx
    Tuesday, June 29, 2010 1:58 PM
  • @Matt  I have been working with Paolo off the forums and it appears to be a translation or normalization rule issue.  Observing the s4 and sipstack logs he sent me show that the number passes to OCS as a 4 digit when OCS is configured with full e.164.  I am waiting on his norm rules to identify if he is not normalizing this number correctly.

    Mark


    Mark King | MCTS:UC Voice | MCSE: Messaging | MCITP:Enterprise Messaging | CCNA | www.unplugthepbx.com
    Tuesday, June 29, 2010 7:18 PM
  • The issue is resolved.

     

    I have changed the forwarding settings to specifically "Ring me and my delegates", adding a delegate, apply, then remove the delegate

    This fixed the issue and the users were able to receive external calls.

    I don't know why that specific setting would fix an issue like that but then again I didn't know what the problem was to start with

    Thursday, July 1, 2010 9:30 AM