Wednesday, November 2, 2016

How to enable Microsoft Teams Preview

So you are all revved up and ready to use Microsoft Teams... but you can't find it in your Admin Portal on Office365. Well I got you covered and its real simple.

All you need to do is go into your Admin Portal and navigate to "Services". Under there click "Services & add-in"



Then click "Microsoft Teams" and flip the on switch. Additionally you can get more granular about the features you want your users to have access to.



To start... Navigate to https://teams.microsoft.com/ and create your first team.

Enjoy!

Tuesday, June 28, 2016

Decrypting HTTPS web traffic without private key

So anyone who knows me... knows that I love Wireshark. Recently while preparing for a presentation at the Colorado UC User Group, I found out that my old reliable technique of decrypting HTTPS traffic using a private key, actually no longer works anymore since many of the modern servers and devices I work with use some form of Diffie Hellman cipher to setup the Encrypted connection. Why is this so... because Diffie Hellman type ciphers never actually transmit the "secret" on the wire like the old RSA based ciphers did. Here is a pretty good explanation of what happens in English.

So I went searching for alternatives and much like one of my favorite podcast from RadioLab revealed about magic tricks... The only secret in magic is that the secret must be ugly (said by Penn Jillette).

I present to you the fantastic and ugly secret of the SSLKEYLOGFILE environment variable.

So... what I stumbled upon and have been debating for over a month is a way in which you can decrypt HTTPS traffic without a man in the middle technique (Fiddler) or having the private key (old Wireshark method that is useless now). Instead, the browser does all the hard work and logs yours session key to a log file that is then easily referenced by Wireshark.

Say what?!

Let me repeat... your browser tells all your secrets and makes decrypting HTTPS traffic something that even sniveling grade school kid could do.

Before I go on... I truly hope that you will use this information for good and not evil. Because someone that is a bit creative could really wreak havoc on someone else's life without much effort. I'm telling you this, because I finally came to the conclusion that knowing this will make you able to defend yourself better.

The Ugly Secret


First off, this only works with Chrome and Firefox. Edge and Internet Explorer do not use this technique. My guess is that won't be a problem since most people seem to use Chrome these days. Start off by navigating to the "System" Control Panel applet. Select "Advanced system settings" from the links on the left.


A "System Properties" dialog box appears. Next select "Environment Variables"

When the "Environment Variables" dialog appears, Select "New" under "System variables".

 Yet another dialog box appears. The "Variable name" is "SSLKEYLOGFILE" and the value is a directory and filename of your desire. Please make note of this directory and filename for future use in the configuration of Wireshark. Click OK

View that the "SSLKEYLOGFILE" variable now appears in the "System variables" list with the correct path to the filename you specified.


Start up Chrome or Firefox and browse to a website with HTTPS capability. After doing so, you should see the log file you specified. Feel free to open it in Notepad if you want to see what is there. You'll be surprised as to how many entries appear in a short time.




Next start Wireshark (Download here if you don't have it). I'm using the Legacy UI in case you are wondering why yours might be different. Navigate to the Edit -> Preferences Menu.



Navigate to the "SSL" Protocol and enter the directory path and filename for the log file you specified in the Envrionment Variable under "(Pre)-Master-Secret log filename". Click OK


Capturing HTTPS Traffic


So now all this is setup, what does it all look like when you do a capture? Start your Wireshark capture and browse to a website that uses HTTPS. If you want to make it easier to view the traffic you can set your Display filter to "http" and hit Apply.


You know that decryption is happening by viewing the Decypted SSL portion at the bottom of the screen. If this is not there, then decryption is not happening and you either have a packet that is not encrypted or the reference to the log file is incorrect.



So there you have it. The ugly secret your browser has. I hope you didn't read this just before bedtime.




Wednesday, May 25, 2016

InboundRouting and tmx file madness... AGAIN

Oh hey! It's been awhile... okay... it's been WAAAAAY too long since I've posted a blog. I've had many blogs that I thought I should write, but having 5 kids, all with various activities in the spring, just kills the mood of blog writing in the evening.

So many moons ago I wrote about how the default.tmx file was corrupt and didn't produce any output and that it could be fixed by copying the default.tmx file from a directory under "Common Files".

Well same song... second verse. I recently found InboundRouting debug produces some output... just not all the goey goodness you'd expect when you are trying to see how calls are routing and all the decisions that are being made.

The Problem

The Lync Server 2013 Debugging Tools that are installed separately have sparse output for debug logs for after you click "View Log Files" for InboundRouting.

The easiest way you can verify this is by starting OCSLogger.exe and set a debug session for InboundRouting and set the "Level" to All and "Flags" to All Flags.


Start Logging and make a call from the PSTN in to your Lync Server 2013 system. When the call is completed hang up and click Stop Logging.

Click "View Log Files" and make sure "InboundRouting" is the only Log File selected. If you get output similar to this... Congratulations... you have reproduced the problem I saw.

TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecb (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(block)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecc (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(e911active)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecd (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=class:Secondary>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deece (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=privateLine>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecf (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed0 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=member:breakthrough>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed1 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=referred:breakthrough>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed2 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=member:add_voice>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed3 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(work_hours)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed4 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed5 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(team_ring)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed6 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(delegate_ring)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed7 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=dnd>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed8 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed9 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=flags:clientflags(forward_immediate)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deeda (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deedb (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Registered' action='Replace' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee9 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='StaticRegistered' action='Extend' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeed (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Secondary' action='Extend' wait='0' criteria='registered'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef3 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Secondary' action='NoRing' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef7 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Secondary' action='Extend' waitref='total' wait='15' criteria='flags:clientflags(simultaneous_ring)'>
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def20 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Primary' action='Replace' wait='60' criteria='flags:clientflags(enablecf)'>
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def23 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[484752463]<group class='Primary' action='Replace' wait='60' criteria='umenabled'>
TL_VERBOSE(TF_COMPONENT) [1]11BC.0CA8::05/25/2016-16:32:17.647.001def5e (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[2153832770]<filter criteria=flags:clientflags(block)>=false
TL_VERBOSE(TF_COMPONENT) [1]11BC.0CA8::05/25/2016-16:32:17.647.001def5f (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[2153832770]<filter criteria=routingAppInvite>=false
TL_VERBOSE(TF_COMPONENT) [1]11BC.0CA8::05/25/2016-16:32:17.647.001def60 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[2153832770]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [1]11BC.0CA8::05/25/2016-16:32:17.647.001def61 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[2153832770]<group class='Registered' action='Replace' wait='0'>
TL_VERBOSE(TF_COMPONENT) [1]11BC.0CA8::05/25/2016-16:32:17.647.001def6b (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[2153832770]<group class='StaticRegistered' action='Extend'>
TL_VERBOSE(TF_COMPONENT) [1]11BC.19D4::05/25/2016-16:32:20.840.001def96 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3011151961]<filter criteria=umenabled>=false
TL_VERBOSE(TF_COMPONENT) [1]11BC.19D4::05/25/2016-16:32:20.840.001def97 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3011151961]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [1]11BC.19D4::05/25/2016-16:32:20.840.001def98 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[3011151961]<group class='Registered' action='Replace'>
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.762.001defb8 (InboundRouting,RoutingPresenceState.Parse:routingpresencestate.cs(35))[3994464144]XML that should contain user's dnd state is empty.
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defc6 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=routingAppInvite>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defc7 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=flags:clientflags(block)>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defc8 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=class:Secondary>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defc9 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=privateLine>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defca (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=flags:clientflags(work_hours)>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defcb (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defcc (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=dnd>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defcd (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=flags:clientflags(forward_immediate)>=false
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defce (InboundRouting,RoutingFilter.Execute:routingmodel.cs(145))[3994464144]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defcf (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[3994464144]<group class='Registered' action='Replace' wait='0'>
TL_VERBOSE(TF_COMPONENT) [0]11BC.182C::05/25/2016-16:32:35.763.001defd9 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(966))[3994464144]<group class='Secondary' action='Extend' waitref='total' wait='15' criteria='flags:clientflags(simultaneous_ring)'>




The correct output should look something like this... with a lot more details about what the routing is actually doing (note this is output from the same .etl file with numbers, names, and IPs to protect the innocent).

TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deeb6 (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(521))[484752463]OnInboundRequest() for someuser@ucomsgeek.com
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deeb7 (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(532))[484752463]routing instance=<routing xmlns="http://schemas.microsoft.com/02/2006/sip/routing" name="rtcdefault" version="2" minSupportedClientVersion="4.0.0.0"><preamble><flags name="clientflags" value=""></flags><wait name="total" seconds="20"></wait></preamble></routing>
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deeb8 (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(537))[484752463]dndStateXml=<state xmlns:xsi="
http://www.w3.org/2001/XMLSchema-instance" xmlns="http://schemas.microsoft.com/2006/09/sip/state" xsi:type="userState" manual="true"></state>
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deeb9 (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(538))[484752463]userPropertiesXml=<userProperties xmlns="
http://schemas.microsoft.com/2006/09/sip/categories">
<lines>
<line lineType="Uc">
tel:+13039973064;ext=89973064</line>
</lines>
<telephonyMode>
Uc</telephonyMode>
<l>
Roseville</l>
<st>
Mn</st>
<exumEnabled>
1</exumEnabled>
<exumURL>
EUM:someuser@ucomsgeek.com;voicemail-destination=default</exumURL>
</userProperties>
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deeba (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(539))[484752463]calendarDataXml=<calendarData xmlns="
http://schemas.microsoft.com/2006/09/sip/calendarData" mailboxID="someuser@ucomsgeek.com"><WorkingHours xmlns="http://schemas.microsoft.com/exchange/services/2006/types"><TimeZone><Bias>360</Bias><StandardTime><Bias>0</Bias><Time>02:00:00</Time><DayOrder>1</DayOrder><Month>11</Month><DayOfWeek>Sunday</DayOfWeek></StandardTime><DaylightTime><Bias>-60</Bias><Time>02:00:00</Time><DayOrder>2</DayOrder><Month>3</Month><DayOfWeek>Sunday</DayOfWeek></DaylightTime></TimeZone><WorkingPeriodArray><WorkingPeriod><DayOfWeek>Monday Tuesday Wednesday Thursday Friday</DayOfWeek><StartTimeInMinutes>480</StartTimeInMinutes><EndTimeInMinutes>1020</EndTimeInMinutes></WorkingPeriod></WorkingPeriodArray></WorkingHours></calendarData>
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deebb (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(540))[484752463]registeredEndpointCount=2
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:31:46.395.001deebc (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(541))[484752463]userIsDualMode=False
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deebd (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(616))[484752463]Not checking for LBR
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deebe (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(630))[484752463]Presence State is 0
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deebf (InboundRouting,UserProperties.Parse:exumuserproperties.cs(281))[484752463]ExumEnabled=1 ExumAddress='EUM:someuser@ucomsgeek.com;voicemail-destination=default'
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec0 (InboundRouting,InboundRouting.OnInboundInvite:inboundrouting.cs(697))[484752463]Preamble matched a known script name=rtcdefault version=2 for user
someuser@ucomsgeek.com
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec1 (InboundRouting,InboundRoutingContext.InitializeAttributesFromRequest:inboundroutingcontext.cs(1496))[484752463]Found 'max-forwards' header with value 70.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec2 (InboundRouting,InboundRoutingContext.InitializeAttributesFromRequest:inboundroutingcontext.cs(1593))[484752463]Found Multipart content-type: multipart/alternative; boundary=s704xhVieLenjcRabw4IMHITzZm6d4Lk
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec3 (InboundRouting,InboundRoutingContext.InitializeAttributesFromRequest:inboundroutingcontext.cs(1644))[484752463]Request Sensitivity: Normal
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec4 (InboundRouting,InboundRoutingContext.InitializeAttributesFromRequest:inboundroutingcontext.cs(1646))[484752463]Request Target Class: Primary
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec5 (InboundRouting,InboundRoutingContext.CheckForPrivateLine:inboundroutingcontext.cs(1740))[484752463]UserProperties empty or no private line for this user. Nothing to do further.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec6 (InboundRouting,InboundRoutingContext.InitializeAttributesFromRequest:inboundroutingcontext.cs(1726))[484752463]Phone Invite: [Public] Line
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec7 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: NotReady->Active
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec8 (InboundRouting,RoutingContext.AddTargetToAttemptedList:routingcontext.cs(15))[484752463]Added to attempt list:
+13039973064@ucomsgeek.com;user=phone
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deec9 (InboundRouting,RoutingContext.AddTargetToAttemptedList:routingcontext.cs(15))[484752463]Added to attempt list: 7203398001;phone-context=PstnGateway_192.168.67.198@ucomsgeek.com;user=phone
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deeca (InboundRouting,RoutingContext.AddTargetToAttemptedList:routingcontext.cs(15))[484752463]Added to attempt list: 89973064;phone-context=PstnGateway_192.168.67.198@ucomsgeek.com;user=phone
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecb (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(block)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecc (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(e911active)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecd (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=class:Secondary>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deece (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=privateLine>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deecf (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed0 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=member:breakthrough>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed1 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=referred:breakthrough>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed2 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=member:add_voice>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed3 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(work_hours)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed4 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed5 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(team_ring)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed6 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(delegate_ring)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed7 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=dnd>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed8 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deed9 (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=flags:clientflags(forward_immediate)>=false
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deeda (InboundRouting,RoutingFilter.Execute:routingmodel.cs(14))[484752463]<filter criteria=default>=true
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deedb (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Registered' action='Replace' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deedc (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(45))[484752463]Cancelling existing transactions since group criteria result is true.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deedd (InboundRouting,RoutingContext.SendRequestsForGroup:routingcontext.cs(96))[484752463]Sending request to 2 registered endpoints.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deede (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(573))[484752463]Creating Client Transaction to: sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deedf (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(744))[484752463]Adding Max-Forwards header: 69
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.397.001deee0 (InboundRouting,InboundRoutingClientTransaction.constructor:inboundroutingcontext.cs(1910))[484752463]Addressing request using ContactInfo.
TL_INFO(TF_PROTOCOL) [2]11BC.06EC::05/25/2016-16:31:46.397.001deee1 (InboundRouting,InboundRoutingClientTransaction.SendImpl:inboundroutingcontext.cs(2315))[484752463]SendImpl() to sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee2 (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(573))[484752463]Creating Client Transaction to: sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee3 (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(744))[484752463]Adding Max-Forwards header: 69
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee4 (InboundRouting,InboundRoutingClientTransaction.constructor:inboundroutingcontext.cs(1910))[484752463]Addressing request using ContactInfo.
TL_INFO(TF_PROTOCOL) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee5 (InboundRouting,InboundRoutingClientTransaction.SendImpl:inboundroutingcontext.cs(2315))[484752463]SendImpl() to sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee6 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(65))[484752463]There were 2 new requests sent by this group.
TL_INFO(TF_PROTOCOL) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee7 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(904))[484752463]Sending internally generated response 101
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee8 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(941))[484752463]Response 101 generated and sent
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deee9 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='StaticRegistered' action='Extend' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeea (InboundRouting,RoutingContext.CheckAndRequestContactGroupResoltion:routingcontext.cs(28))[484752463]Referenced <list> named 'StaticRegistration' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeeb (InboundRouting,RoutingContext.SendRequestsForGroup:routingcontext.cs(98))[484752463]Referenced <list> named 'StaticRegistration' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeec (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(73))[484752463]There were no new requests sent by this group.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeed (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Secondary' action='Extend' wait='0' criteria='registered'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeee (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(44))[484752463]Group criteria registered=True
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deeef (InboundRouting,RoutingContext.CheckAndRequestContactGroupResoltion:routingcontext.cs(28))[484752463]Referenced <list> named 'GroupPickupList' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef0 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(63))[484752463]Setting Routing Scenario to forwarding.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef1 (InboundRouting,RoutingContext.SendRequestsForGroup:routingcontext.cs(98))[484752463]Referenced <list> named 'GroupPickupList' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef2 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(73))[484752463]There were no new requests sent by this group.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef3 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Secondary' action='NoRing' wait='0'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef4 (InboundRouting,RoutingContext.CheckAndRequestContactGroupResoltion:routingcontext.cs(28))[484752463]Referenced <list> named 'ControlledDevice' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef5 (InboundRouting,RoutingContext.SendRequestsForGroup:routingcontext.cs(98))[484752463]Referenced <list> named 'ControlledDevice' does not exist in preamble.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef6 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(73))[484752463]There were no new requests sent by this group.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef7 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Secondary' action='Extend' waitref='total' wait='15' criteria='flags:clientflags(simultaneous_ring)'>
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef8 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(44))[484752463]Group criteria flags:clientflags(simultaneous_ring)=False
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deef9 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(73))[484752463]There were no new requests sent by this group.
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deefa (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [2]11BC.06EC::05/25/2016-16:31:46.398.001deefb (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(77))[484752463]Started group wait for 20000 milliseconds.
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.403.001deefc (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 100 from sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [1]11BC.01A8::05/25/2016-16:31:46.446.001deefd (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 100 from sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [1]11BC.171C::05/25/2016-16:31:46.604.001deefe (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 180 from sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [1]11BC.171C::05/25/2016-16:31:46.604.001deeff (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [1]11BC.171C::05/25/2016-16:31:46.604.001def00 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 180
TL_VERBOSE(TF_COMPONENT) [1]11BC.171C::05/25/2016-16:31:46.604.001def01 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.802.001def02 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 183 from sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.802.001def03 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.802.001def04 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 183
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.802.001def05 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.992.001def06 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 183 from sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.992.001def07 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.992.001def08 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 183
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:31:46.992.001def09 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [1]11BC.01A8::05/25/2016-16:31:47.033.001def0a (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 180 from sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [1]11BC.01A8::05/25/2016-16:31:47.033.001def0b (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [1]11BC.01A8::05/25/2016-16:31:47.033.001def0c (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 180
TL_VERBOSE(TF_COMPONENT) [1]11BC.01A8::05/25/2016-16:31:47.033.001def0d (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def1e (InboundRouting,RoutingContext.OnWaitTimerElapsed:routingcontext.cs(17))[484752463]Group wait timer elapsed
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def1f (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def20 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Primary' action='Replace' wait='60' criteria='flags:clientflags(enablecf)'>
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def21 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(44))[484752463]Group criteria flags:clientflags(enablecf)=False
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def22 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(73))[484752463]There were no new requests sent by this group.
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def23 (InboundRouting,RoutingGroup.Execute:routingmodel.cs(96))[484752463]<group class='Primary' action='Replace' wait='60' criteria='umenabled'>
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def24 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(44))[484752463]Group criteria umenabled=True
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def25 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(45))[484752463]Cancelling existing transactions since group criteria result is true.
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def26 (InboundRouting,InboundRoutingClientTransaction.CancelImpl:inboundroutingcontext.cs(2234))[484752463]Canceling sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def27 (InboundRouting,InboundRoutingClientTransaction.ClientTransactionCanceled:inboundroutingcontext.cs(2047))[484752463]ClientTransactionCanceled: sip:192.168.66.56:65346;transport=tls;ms-opaque=4cfd005019;ms-received-cid=1FDF200
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def28 (InboundRouting,InboundRoutingClientTransaction.CancelImpl:inboundroutingcontext.cs(2234))[484752463]Canceling sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def29 (InboundRouting,InboundRoutingClientTransaction.ClientTransactionCanceled:inboundroutingcontext.cs(2047))[484752463]ClientTransactionCanceled: sip:someuser@192.168.67.41:35542;transport=tls;ms-received-cid=1612E00
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2a (InboundRouting,RoutingContext.SendRequestsForGroup:routingcontext.cs(10))[484752463]This group has 1 targets
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2b (InboundRouting,RoutingContext.AddTargetToAttemptedList:routingcontext.cs(15))[484752463]Added to attempt list:
+13039973064@ucomsgeek.com;user=phone/voicemail
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2c (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(573))[484752463]Creating Client Transaction to: sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2d (InboundRouting,InboundRoutingContext.CreateClientTransactionForRequest:inboundroutingcontext.cs(744))[484752463]Adding Max-Forwards header: 16
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2e (InboundRouting,InboundRoutingClientTransaction.constructor:inboundroutingcontext.cs(1933))[484752463]Addressing request with Retarget(sip:someuser@ucomsgeek.com;opaque=app:voicemail)
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def2f (InboundRouting,InboundRoutingClientTransaction.InitializeDiagnosticsReporter:inboundroutingcontext.cs(2285))[484752463]Initializing diagnostics error reporter for transaction.
TL_INFO(TF_PROTOCOL) [3]11BC.0E18::05/25/2016-16:32:06.389.001def30 (InboundRouting,InboundRoutingClientTransaction.SendImpl:inboundroutingcontext.cs(2315))[484752463]SendImpl() to sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def31 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(65))[484752463]There were 1 new requests sent by this group.
TL_INFO(TF_PROTOCOL) [3]11BC.0E18::05/25/2016-16:32:06.389.001def32 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(904))[484752463]Sending internally generated response 181
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def33 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(941))[484752463]Response 181 generated and sent
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def34 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [3]11BC.0E18::05/25/2016-16:32:06.389.001def35 (InboundRouting,RoutingContext.ProcessGroup:routingcontext.cs(77))[484752463]Started group wait for 60000 milliseconds.
TL_VERBOSE(TF_COMPONENT) [0]11BC.13B0::05/25/2016-16:32:06.397.001def36 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 101 from sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [0]11BC.13B0::05/25/2016-16:32:06.397.001def37 (InboundRouting,InboundRoutingResponse.constructor:inboundroutingcontext.cs(2392))[484752463]Response has ms-diagnostic header with value: 15010
TL_VERBOSE(TF_COMPONENT) [0]11BC.13B0::05/25/2016-16:32:06.397.001def38 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.13B0::05/25/2016-16:32:06.397.001def39 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 101
TL_VERBOSE(TF_COMPONENT) [0]11BC.13B0::05/25/2016-16:32:06.397.001def3a (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:32:07.232.001def3b (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 101 from sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:32:07.232.001def3c (InboundRouting,InboundRoutingResponse.constructor:inboundroutingcontext.cs(2392))[484752463]Response has ms-diagnostic header with value: 15023
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:32:07.232.001def3d (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:32:07.232.001def3e (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 101
TL_VERBOSE(TF_COMPONENT) [1]11BC.06EC::05/25/2016-16:32:07.232.001def3f (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [0]11BC.171C::05/25/2016-16:32:07.902.001def40 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 101 from sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [0]11BC.171C::05/25/2016-16:32:07.902.001def41 (InboundRouting,InboundRoutingResponse.constructor:inboundroutingcontext.cs(2392))[484752463]Response has ms-diagnostic header with value: 15023
TL_VERBOSE(TF_COMPONENT) [0]11BC.171C::05/25/2016-16:32:07.902.001def42 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.171C::05/25/2016-16:32:07.902.001def43 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 101
TL_VERBOSE(TF_COMPONENT) [0]11BC.171C::05/25/2016-16:32:07.902.001def44 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:32:09.893.001def45 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 180 from sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:32:09.893.001def46 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:32:09.893.001def47 (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 180
TL_VERBOSE(TF_COMPONENT) [0]11BC.19D4::05/25/2016-16:32:09.893.001def48 (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Waiting
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def49 (InboundRouting,InboundRoutingClientTransaction.ResponseReceived:inboundroutingcontext.cs(2150))[484752463]ResponseReceived 200 from sip:someuser@ucomsgeek.com;opaque=app:voicemail
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4a (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Waiting->Active
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4b (InboundRouting,InboundRoutingResponse.get_ProxyAssertedIdentity:inboundroutingcontext.cs(2526))[484752463]value=<sip:someuser@ucomsgeek.com> scheme=sip
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4c (InboundRouting,RoutingContext.CancelAllOutstandingRequests:routingcontext.cs(16))[484752463]Nothing to cancel.
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4d (InboundRouting,InboundRoutingContext.ProxyResponseImpl:inboundroutingcontext.cs(860))[484752463]Proxying response 200
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4e (InboundRouting,RoutingContext.SetState:routingcontext.cs(91))[484752463]Context State: Active->Terminated
TL_VERBOSE(TF_COMPONENT) [0]11BC.06EC::05/25/2016-16:32:10.164.001def4f (InboundRouting,InboundRoutingContext.OnSessionTerminated:inboundroutingcontext.cs(1146))[484752463]Session terminated.


The Fix!

The fix that was shared with me by those smarter than me a long time ago and I was reminded of by @jeffcsp while troubleshooting this :-) ... In my defense the original problem was a really small file of like 5.5MB and the one that is installed with the 5.0.8308.577 Debugging tools is 22MB. But still I should have caught it and he gets props for catching it.

In troubleshooting this problem, I found that the file located in the Common Files directory mentioned below is updated by the Cumulative Updates. I think it comes in during the Core Components update, but I'm not 100% sure. So I'd recommend until Microsoft figures out how to fix this the right way, you check the Common Files directory for any updated files and copy them over and of course TEST after you do so. I also recommend making a backup of any default.tmx files you replace, just in case you need to go back to the original.

Here are the steps...

Rename the default.tmx in the C:\Program Files\Microsoft Lync Server 2013\Debugging Tools directory

You need to copy default.tmx from
c:\Program Files\Common Files\Microsoft Lync Server 2013\Tracing
To
C:\Program Files\Microsoft Lync Server 2013\Debugging Tools

The file size of the default.tmx from the Tracing folder is approximately 26MB (December Update) vs 22MB of the default.tmx that came with the debugging tools (January 18, 2014).

Start up OCSLogger.exe (or CLS) again after the procedure above and run the InboundRouting debug again. This time you should have output in the log file.

So far I have confirmed this impacts at least InboundRouting on this go around. But in the past this has impacted other debug areas... so don't be surprised if there is something you've been missing when troubleshooting.