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.
