Filter UserIdHash to report user activities with IIS Logs in Dynamics CRM IFD

If you are administrating Dynamics CRM on-premises and one day need to report certain CRM activities of a particular user, e.g. Advanced Find or Export activities, you will immediately, or eventually - if it is first time under the assignment, start digging into IIS Logs because you know Auditing feature, if it's ever been turned on,  won't provide that kind of information.

The challenge is that with Internet Facing Deployment (IFD), user authentication is performed in ADFS server, not in IIS server. Therefore IIS Log entries won't have User Name (corresponding to cs-username field for W3C log format) info available for you to filter out the activities of a target user.

What about IP address? Yes, IIS Log entries will include Client IP Address (W3C logging field c-ip) of client machines making CRM requests. But with IFD setup users can log in to CRM from any location; each with a different IP. And even if you know they only do CRM from a specific workstation in office, a specific IP address won't guarantee to stick with one user if corporate network domain is running DHCP configuration.

So how to filter Dynamics CRM interactions belonging to a particular user when IIS Log entries don't include User Name, and logged IP address won't persist over time for one user? I couldn't find the answer online searching around for awhile. But then I started staring at the log files quite longer period and figure out the steps to work out the solution.

If you look at each log entry like one below (again I'm referencing W3C log):

#Fields: date time cs-method cs-uri-stem cs-uri-query c-ip cs(User-Agent) sc-status sc-bytes cs-bytes time-taken
2014-12-08 21:26:00 GET /Reserved.ReportViewerWebControl.axd OpType=Resource&Version=10.0.30319.1&Name=Microsoft.ReportingServices.Rendering.HtmlRenderer.RendererResources.unsorted.gif+OnBeginRequest:12/08/2014-21:26:01.311+UserIdHash:1488234363+LogEntries:0+SqlCalls:0+SqlCallsMs:0+GC:90+OnEndRequest:21:26:01.311 192.168.123.45 Mozilla/5.0+(compatible;+MSIE+10.0;+Windows+NT+6.1;+WOW64;+Trident/6.0) 200 373 3409 218

You notice that the URI Query field (cs-uri-query) in each log entry embeds with it a bunch of information related to the web request from user client. The key piece of info valuable for the reporting purpose is UserIdHash, in this example the digit sequence 1488234363

After running several tests and comparing logs under few user accounts, it turns out that the digit sequence after UserIdHash stay the same unique number for all requests originated from a particular user. For example, the number above, 1488234363, is associated with my own CRM user account and is embedded within URI Query field for each activity logged in IIS. All I need to do is running certain kind of log parser tool to filter all the entries that contain the string UserIdHash:1488234363 and voila... there I have a filtered log of my own activities in CRM.

That's not so bad of a solution, isn't it. I'm able to figure out the UserIdHash value associated with my CRM user account by doing a few CRM actions, noting the time of these actions and the local IP of my workstation. Then go back to the IIS Logs and review new log entries associated with the same IP in Client IP Address (c-ip) that have the same time stamps with my CRM actions.

How would you find out the UserIdHash that map to another user? By doing similar tracing mechanism mentioned above, except this time you could be able to obtain info of his/her client machine IP address that exists at an approximate time frame, but not the exact timing of the CRM actions. One way to obtain client IP is by viewing header of an email the user sends you. For example, in Outlook, open the email and click on File, Info, then Properties. The Internet headers would show the IP of the workstation from which user sends email, and most likely uses to launch CRM:

You don't want to rely on just one client IP to trace back UserIdHash unless you know for sure user access CRM from that client machine at certain time period. I would say 3 separate IP's from 3 different days would be safe bet for the correct UserIdHash mapping.

Last but not least, once done with mapping a unique UserIdHash to a user, time to run a log parser tool to extract all the log entries related to that user for further processing. Did I say Log Parser? Here's the query I run from Log Parser to extract all IIS Log entries that reference to my own CRM activities, and output to a CSV file:

C:\Program Files (x86)\Log Parser 2.2>Logparser -o:CSV "Select date as Date, time as Time, cs-method as Method, cs-uri-stem as URI, cs-uri-query as Query, sc-status as Status, sc-bytes as BytesIn, cs-bytes as BytesOut, time-taken as TimeTaken Into Z:\MyCRMLog.csv From C:\inetpub\logs\LogFiles\W3SVC1\*.log Where cs-uri-query like '%UserIdHash:1488234363%'"

If I'm only interested in Advanced Find or Export activities, I can query the following:

C:\Program Files (x86)\Log Parser 2.2>Logparser -o:CSV "Select date as Date, time as Time, cs-method as Method, cs-uri-stem as URI, cs-uri-query as Query, sc-status as Status, sc-bytes as BytesIn, cs-bytes as BytesOut, time-taken as TimeTaken Into Z:\FilteredCRMLog.csv From C:\inetpub\logs\LogFiles\W3SVC1\*.log Where cs-uri-query like '%UserIdHash:1488234363%' AND cs-uri-stem IN '/_grid/print/print_data.aspx'; '/_grid/print/export_dlg.aspx'; '/AdvancedFind/fetchData.aspx')"

So there it is. No User Name in IIS Logs, no problem. Just figure out the embedded UserIdHash value that belongs to a user, by tracing the possible IP's from user's machine that appear in log entries. Then you can parse log files to extract log entries that contain the value of UserIdHash in URI Query log field.