Wednesday, July 5, 2017

PowerShell Script to Backup AudioCodes Gateways (updated for 7.0 and 7.2)

A few years ago I created a PowerShell script that would backup AudioCodes gateways. It's gone through several iterations as AudioCodes has changed how they do authentication. Now with 7.0 and 7.2 out in the wild, I again found that I needed to update this script again to support the changes to the user interface.

Fortunately I've got great friends and Mitch Steiner had been messing with AudioCodes new API to pull some interesting metrics for our T2M Cloud and he let me know that he stumbled upon a way to pull the .ini configuration using the REST API. The new REST API reduced the amount of code to do a backup down to literally one line. Now obviously it would be cool to have a script that detected which AudioCodes version it was connected to, so it is more than just one line in the script below. I also found a way to "Burn" the configuration on 7.0 and 7.2 using the API. So that is part of the script and executes just before backup.

Couple of key items before you run the script below.
  • If you are running on a Windows 7 or other workstation you'll need to set your PowerShell Execution Policy.
  • Next you will need to install a package called cURL that is a command line tool for interacting with web pages. It is required to work with the Forms Based Auth that audiocodes uses. I used a new tool to install it called Chocolatey, which is the equivalent of RPM packages for Windows. Here is the page for cURL (http://chocolatey.org/packages/curl) and here is the main page for Chocolatey (http://chocolatey.org/)
  • PowerShell has an alias for curl that you'll need to remove. The command is Remove-Item alias:curl 
Without further adieu... I give you the AudioCodes backup script that will backup any 6.4, 6.6, 6.8, 7.0, or 7.2 AudioCodes Gateway/SBC. 

# Script to Backup AudioCodes Gateways# Created By Jonathan McKinney (blog.ucomsgeek.com)# Disclaimer: You running this script means you won't blame Jonathan McKinney or his employer if this breaks your stuff. This script is provided AS IS without warranty of any kind.

# User Modifiable Variables
$username = "Admin"
$password = "Admin"
$address = "m4000.ucomsgeek.com"
$backuppath = "c:\scripts\backups\"


# Variable Initialization
$filename = $null
$statuscodeeval = $null


#Function to detect if Forms Auth is present
function DetectAuthType ($ad)
{
    $loginurl = $null
    
    $loginurl = "http://" + $ad + "/api"
    $statuscode = curl -o null.txt $loginurl -w '%{http_code}'
    If ($statuscode -eq "404")
    {
        $loginurl = "http://" + $ad + "/"
        $statuscode = curl -o null.txt $loginurl -w '%{http_code}'
        Write-host `r`n "Status Code " $statuscode
        If ($statuscode -eq "401")
        {
            $statuscodeeval = "basic"
        }
        ElseIf ($statuscode -eq "203")
        {
            $statuscodeeval = "forms"
        }
        Else
        {
            $statuscodeeval = "neither"
        }
    }
    ElseIf ($statuscode -eq "401")
        {
            $statuscodeeval = "api"
        }
    Return $statuscodeeval
    Remove-Item null.txt
}


 # Function to Authenticate with Forms Auth
function AuthenticateForms ($un, $pw, $ad)
{
     $login1sregex = "\<s\>(\d*)\<\/s\>"
     $login1rregex = "\<r\>(.*)\<\/r\>"
     $a1 = $null
     $loginusername = $null
     $loginurl = $null
     $login1webpage = $null
     $login1spattern = $null
     $login1rpattern = $null
     $hashByteArray1 = $null
     $hashByteArray2 = $null
     $passwordhash = $null
     $resultwebpage = $null
     $formsbasedauth = $null
     
     Write-Host `r`n 'Forms Authentication' `r`n
     $login1username = "c1=" + $un
     $loginurl = "http://" + $ad + "/UE/Login"
     $login1webpage = curl $loginurl --data-urlencode "t=1" `
                                     --data-urlencode "c0=0" `
                                     --data-urlencode $login1username `
                                     --header "X-Requested-With: XMLHttpRequest" `
                                     -c cookiejar.txt `
                                     --header "Cookie: aclogname=; C2=ct" `
                                     --user-agent "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

      $login1spattern = $login1webpage -split "`n" | Select-String -pattern $login1sregex -Allmatches | % { $_.Matches | % { $_.groups[1].Value } }

      $login1spattern = "s=" + $login1spattern
     $login1rpattern = $login1webpage -split "`n" | Select-String -pattern $login1rregex -Allmatches | % { $_.Matches | % { $_.groups[1].Value } }

      $cryptoServiceProvider = [System.Security.Cryptography.SHA256CryptoServiceProvider]
     $hashAlgorithm = New-Object $cryptoServiceProvider
     $hashByteArray1 = $hashAlgorithm.ComputeHash($([Char[]]$password))
     foreach ($byte in $hashByteArray1)
     {
          $a1 += "{0:x2}" -f $byte
     }
     
     $a2 = $username + ":" + $login1rpattern + ":" + $a1
     $hashByteArray2 = $hashAlgorithm.ComputeHash($([Char[]]$a2))

      foreach ($byte in $hashByteArray2)
     {
          $passwordhash += "{0:x2}" -f $byte
     }
     
     $passwordhash = "c1=" + $passwordhash
     $resultwebpage = curl $loginurl --data-urlencode "t=1" `
                                     --data-urlencode $login1spattern `
                                     --data-urlencode "c0=1" `
                                     --data-urlencode $passwordhash `
                                     --header "X-Requested-With: XMLHttpRequest" `
                                     -c cookiejar.txt `
                                     --header "Cookie: aclogname=; C2=ct" `
                                     --user-agent "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"
}


# Function to Backup Gateway WITHOUT Forms Auth
function BackupBasic ($un, $pw, $ad, $path)
{
     $regex = "BOARD.*\.ini"
     $webclient = $null
     $configurl = $null
     $backupurl = $null
     $webpage = $null
     $pattern = $null
     $backupfilename = $null

     $webclient = new-object System.Net.WebClient
     $webclient.Credentials = New-Object System.Net.NetworkCredential($un, $pw)

     Write-Host `r`n 'Detecting .ini name' `r`n
     $configurl = "http://" + $ad + "/ConfigurationFile"
     $webpage = $webclient.DownloadString($configurl)
     $pattern = $webpage -split "`n" | Select-String -pattern $regex -Allmatches | % { $_.Matches | % { $_.Value } }
     Write-Host `r`n 'Detected Board Filename ' $pattern

      Write-Host `r`n 'Backing up ' $ad `r`n
     $backupurl = "http://" + $ad + "/FS/" + $pattern
     $backupfilename = $path + $pattern
     $webclient.DownloadFile($backupurl,$backupfilename)
     Write-Host `r
}


# Function to Detect the Backup Filename with Forms Auth for the Audiocodes Configuration File
function DetectFilenameForms ($ad)
{
     $fnregex = "BOARD.*\.ini"
     $configurl = $null
     $fnpat = $null
     $configwebpage = $null

     Write-Host `r`n 'Detecting .ini name' `r`n
     $configurl = "http://" + $ad + "/ConfigurationFile"
     $configwebpage = curl $configurl -b cookiejar.txt
     $fnpat = $configwebpage -split "`n" | Select-String -pattern $fnregex -Allmatches | % { $_.Matches | % { $_.Value } }

     Write-Host `r`n 'Detected Board Filename ' $fnpat
     return $fnpat
}


# Function to Backup Gateway with Forms Auth
function BackupGatewayForms ($ad, $path, $fn)
{
     $backupurl = $null
     $backupfilename = $null
     
     Write-Host `r`n 'Backing up ' $ad `r`n
     $backupurl = "http://" + $ad + "/FS/" + $fn
     $backupfilename = $path + $fn
     curl -o $backupfilename $backupurl -b cookiejar.txt
     Write-Host `r
}

function BackupGatewayAPI ($un, $pw, $ad, $path)
{
    $backupurlsc = $null
    $backupurlini = $null
    $backupfilename = $null
    $securepw = $null
    $cred = $null

    $backupurlsc = "http://" + $ad + "/api/v1/actions/saveConfiguration"
    $backupurlini = "http://" + $ad + "/api/v1/files/ini"
    $addressfilename = $ad.Replace(“.”,”-”)
    $backupfilename = $path + "BOARD.ini"
    Write-Host $backupfilename
    $securepw = ConvertTo-SecureString -String $pw -AsPlainText -Force
    $cred = new-object System.Management.Automation.PSCredential ($un, $securepw)
    Invoke-RestMethod $backupurlsc -Method post -Credential $cred
    Invoke-RestMethod $backupurlini -Method get -Credential $cred -OutFile $backupfilename -verbose
    
    Write-Host  `r
}


# Function to Logoff Audiocodes with Forms Auth after finishing work
function LogoffForms ($ad)
{
     $logoffurl = $null
     $logoffwebpage = $null
     
     $logoffurl = "http://" + $ad + "/PressLogOff"
     $logoffwebpage = curl $logoffurl -b cookiejar.txt
     Remove-Item cookiejar.txt
}


# Main Script

 $formsbasedauth = DetectAuthType $address

 if ($formsbasedauth -eq "forms")
{
     AuthenticateForms $username $password $address
     $filename = DetectFilenameForms $address
     BackupGatewayForms $address $backuppath $filename
     LogoffForms $address
}
ElseIf ($formsbasedauth -eq "basic")
{
     BackupBasic $username $password $address $backuppath
}
ElseIf ($formsbasedauth -eq "api")
{
     BackupGatewayAPI $username $password $address $backuppath
}
Else
{
     Write-Host "Something went really wrong... couldn't detect Authentication type... Might I suggest Wireshark"
}

Friday, June 30, 2017

Polycom VVX 5.5.2 QoE Reports

It's no secret that I've been hard on Polycom VVX phones in the past (especially with the lack of local Normalization rules processing). But I will say with the version 5.5 release they have come a long way on addressing some key issues and making the phone a decent replacement for the old Aries sets (Polycom CX Series).

Today, I'm excited to share that I've verified that Polycom VVX 5.5.2 now produces QoE reports just like the SfB/Lync PC Client. This means if you have Lync, Skype for Business on-premises or Skype for Business CloudPBX, they all will start showing reports for VVX phones.

If you look at the release notes, QoE Reporting actually was in 5.5.1 but at least for my customer there was a problem with that release that prevented deployment. My guess is there are a lot of people out there that haven't updated to 5.5 because what they have just works.

I am super excited about QoE reporting for VVX because it was a huge hole that was missing in the story. It's really hard to explain to customers that they have these great phones, but there is no way to see how they are performing on a call-by-call basis with what SfB provides out of the box (Polycom has some solutions of course). 

This also means that other tools like EventZero, IR Prognosis, Nectar, etc can now have more complete reporting on these devices.

Here are a couple of screen shots of how the information looks in Monitoring Server for VVX phones. The VVX was the Calee side of the call in these examples.


One of the things I noticed right off the bat is that the Codec report is G711Mu instead of the typical PCMU for G.711 Mulaw. It's minor... but it is a diff. 

On the device metrics, it seems on par with other devices providing good information on how the audio performance of the device is doing.

Anyway... I hope you are already downloading the firmware so you can go see for yourself what you've been missing... Later


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.