Recently I had an interesting discussion with a friend of mine about IIS logging: basically he configured his web server to create a new log every day and then wanted to use a third party tool to extract some statistics and graphics from the logs. Unfortunately the tool often has troubles and gets weird results because sometime at the end of the old log file (the one about the ending day) they have some records whose date and time is into the new day. Something like the following:
#Software: Microsoft Internet Information Services 7.0 #Version: 1.0 #Date: 2009-03-06 23:59:53 #Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger.htm - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/global.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/light_sidebar_left_wide.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/customcss.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/vjr6phmypy.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/msAnalytics.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/PopupPanel.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/style.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15 2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/trans_pixel.gif - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0 2009-03-07 00:00:01 ::1 GET /Themes/Blogs/luxinterior/style/print.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 0 2 15 2009-03-07 00:00:01 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/Modal.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0 2009-03-07 00:00:02 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/InlineEditor.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0
Even if this is not easy to reproduce (I had to try quite a few times to get enough load on IIS and obtain the result above) this behavior is expected: when a client requests a web page, very likely IIS will have to serve multiple files as part of that same request (the page itself plus any linked/included image, CSS style, script etc…), we can say those resources are all part of a single logical request and therefore are treated as a single unit. So if for example you get a request at 23:59:59 very likely the page execution will take more than 1 second, let alone serving the images and other files that might be several Kb large… If we are around midnight we’ll very likely have a few resources served into the new day but logged in the previous day’s file, which is the one there the start of the logical request belongs. Usually this is a “gap” just a few seconds long, normally 2-3 seconds into the new day, even if a longer timeframe in theory cannot be excluded.
A possible solution for this friend of mine is to customize the IIS logging mechanism (see Customize IIS logging), but this could have an impact on performance (one of the requirements here was to not affect the current performance in any way) even simply because of the time needed for the information to transit from kernel mode (IIS default) to user mode. This was not an option in our case.
Anyway you can LogParser to extract your statistics (I have some sample scripts here), or as my friend finally chose, you can use LogParser to reformat your IIS log files and exactly dividing the records as you (or your statistical application) prefer. For example:
logparser "select date, time, s-ip, cs-method, cs-uri-stem, cs-uri-query, s-port, cs-username, c-ip,
cs(User-Agent), sc-status, sc-substatus, sc-win32-status, time-taken into day_1.csv from *.log
where to_timestamp(date,time) between timestamp('2009/03/06 00:00:00', 'yyyy/MM/dd hh:mm:ss')
and timestamp('2009/03/06 23:59:59', 'yyyy/MM/dd hh:mm:ss')"
-i:iisw3c -o:tsv -headers:on -oSeparator:space
As usual note that the command must be on a single line, I’m breaking the line here only to improve readability.
The script above is quite simple and “static”, it takes into account only a specific day and output log file, anyway it should not be too difficult to include is in a vbscript or batch file to dynamically parse and output all of your IIS log files at once.
By the way, do not forget the –consolidateLogs parameter for the IISW3C input file type if you have multiple virtual sites and want to consolidate your data:
consolidateLogs
Values: ON | OFF
Default: OFF
Description: Return entries from all the input log files ordering by date and time.
Details: When a from-entity refers to log files from multiple IIS virtual sites, specifying ON for this parameter causes the IISW3C input format to parse all the input log files in parallel, returning entries ordered by the values of the "date" and "time" fields in the log files; the input records returned will thus appear as if a single IISW3C log file was being parsed. Enabling this feature is equivalent to executing a query with an "ORDER BY date, time" clause on all the log files. However, the implementation of this feature leverages the pre-existing chronological order of entries in each log file, and it does not require the extensive memory resources otherwise required by the ORDER BY query clause.
Carlo
Quote of the day:
Your true value depends entirely on what you are compared with. – Bob Wells