IIS – IISLog – 500 and Log Parser Studio

Background

As I reviewed some papers, that I unfortunately killed trees printing out months ago, I buoyantly ran into a blog posting by Andre Klingsheim.

 

Andre Klingsheim

Andre is a Microsoft MVP, in the area of Developer Security.  His personal site is @ http://www.klings.org/ and he blogs at http://www.dotnetnoob.com/.

I found out about Andre while googling  for IIS 500.  The relevant post is ” IIS 500 errors leave clues in the log ” ( http://www.dotnetnoob.com/2012/03/iis-500-errors-leave-clues-in-log.html ).

In the post, he was able to fix a pesky problem by reviewing IIS Logs and has an afterthought, he said, one can also accomplish the same via “Failed Requests Tracing”.

 

Log Files Parsing

As I reviewed some of our IIS Log files, I started noticing things that I had not previously noticed.  And, so decided to see what tools exist for parsing and aggregating data from log files.

In the rest of this post we will talk more about using “Log Parser Studio” to interactively query IIS Log files.

 

 

Kary Wall

Log Parser Studio was written and maintained by Kary Wall.  His Bio @ https://social.technet.microsoft.com/profile/Kary%20Wall has him as a Senior Engineer with the Microsoft Exchange Support Team.

 

Download

Let us download and install the following utilities:

Once downloaded, please install.

 

Avail IIS Logs

We need IIS Logs to churn on.  I will suggest that you have your Operations Team share the IIS Log folder on your web servers or copy them over to a network location where you have access.

 

Run Log Parser Studio

Interface

Like other GUI Applications, to configure and initiate requests we will use the menu or tool bar.

Here is what this Application’s offering looks like.

menuandtoolbar

Specify Log Files

To specify the log files to query against we will use the  IconLog icon.

Upon invoking that request the “Log File Manager” dialog appears; within that new window, currently specified log folders and files are listed.  Requests to add new individual files and Folders can also be initiated. Existing Log Files and Folders can also be pruned from our request list.

Here is what ours looks like.

LogFileManager

 

If you attempt to run a query without specifying Log Folders and Files, you will be greeted with this choice.

 

LogPathNotFound

 

 

 

Queries

Queries – Aggregate by HTTP Status Code

Thankfully in the shipped library, there is an existing query that groups all requests by HTTP Status Code.

To per-use the query, please access the “Library” tab and navigate to the entry titled “IIS: Status/SubStatus Report”.

Library-IISEntries

Once you find the Query, please select it and double-click your selection.  A new tab with its query pane pre-filled with the canned query is furbished.

Query:


SELECT
        STRCAT(TO_STRING(sc-status)
                  , STRCAT('.', TO_STRING(sc-substatus))
              )
            AS Status
        , COUNT(*) AS Total
FROM '[LOGFILEPATH]'
GROUP BY Status
ORDER BY Total DESC

Output:

HTTPStatusCodeAggregated

 

Explanation:

  • A couple of things are immediately obvious, most of entries are earmarked with HTTP 200.
  • HTTP 200 is good as it means everything is OK
  • There is quite a few 405.0.
  • 405.0 is not so good, has it means that we are trying to access pages with the wrong HTTP Method.  Please read more here – “Error message when a user visits a website that is hosted on a server that is running Internet Information Services 7.0: ‘HTTP Error 405.0 – Method not allowed’ ” – http://support.microsoft.com/kb/942051
  • And, then there are others such as 500.0, 500.24

 


 

Queries – Aggregate by HTTP Status Code (include percentile)

If your manager is like mine, he will like the data broken down into percentiles, as well.

 

Code:


/*  HTTP Status Codes with Hits percentile */

SELECT
         STRCAT(TO_STRING(sc-status)
                    , STRCAT('.', TO_STRING(sc-substatus)))
           AS Status
	, COUNT(*) AS Total
       , MUL(PROPCOUNT(*), 100) AS [PercentOfTotal]
       , Max(TO_LOCALTIME(TO_TIMESTAMP(date, time)))
               as [TimestampOfLastEntry]

FROM '[LOGFILEPATH]'
GROUP BY Status
ORDER BY Total DESC

 

Output:


HTTPStatusCodeAggregatedAndPercentile

 

Explanation: In the output displayed above, we have added % and also the last time the error occurred. Our last 200 entry occurred on Dec 17th and our 500.24 was back in September 18th. Yes, this is my local development machine, the Production box has more recent errors; but you get my drift about the queries.

 

Queries – Aggregate HTTP 500 Entries (with percentile)


/*  Count and sort HTTP 500 status codes */

SELECT
      STRCAT(TO_STRING(sc-status),
                 STRCAT('.', TO_STRING(sc-substatus))) As Status
       , sc-win32-status
       , WIN32_ERROR_DESCRIPTION(sc-win32-status) as Description
       , count(*) as Hits
       , MUL(PROPCOUNT(sc-win32-status), 100) AS [PercentOfTotal]
       , Max(TO_LOCALTIME(TO_TIMESTAMP(date, time)))
           as [TimestampOfLastEntry]

FROM '[LOGFILEPATH]' 

where sc-status = 500

group by
       sc-status
     , sc-substatus
     , sc-win32-status

order by Hits desc

 

Output:

 

CountHTTP500StatusCodes

 

Explanation:

  • Status = 500
    • What does SubStatus = 0 mean?
    • sc-win32-status?
      • If sc-win32-status has a value other than 0, then utilize “net helpmsg <#>” to determine the actual Windows OS Error
      • When win32-status is 64, the actual Windows OS Error is “The specified network name is no longer available.”
      • When win32-status is 50, the actual Windows OS Error is “The request is not supported.”

 


 

Queries – HTTP 500 Entries – Details – Column – cs-uri-query

As I visually inspected the log files, I found entries that have the literal ODBC in them.  They are indicating actual database errors. Let us use LogParser to make sense of them.

 

Code


/*  Filter cs-uri-query like %ODBC% */

SELECT TOP 25
       STRCAT(TO_STRING(sc-status),
                STRCAT('.', TO_STRING(sc-substatus))) As Status
     , sc-win32-status
     , WIN32_ERROR_DESCRIPTION(sc-win32-status) as Description
     , to_localtime(to_timestamp(date, time)) as LocalTime
     , cs-uri-query

FROM '[LOGFILEPATH]' 

where  cs-uri-query like '%ODBC%'

order by LocalTime desc

 

Output:

HTTP-cs-uri-querylikeODBC

 

Explanation:

  • The cs-uri-query is an overloaded field
  • In this case it is being used to give us an elaborate view of ODBC DB Errors
  • Here are the distinct errors
    • |207|80040e14|[Microsoft][ODBC_SQL_Server_Driver][SQL_Server]Could_not_find_stored_procedure_’dbo.usp_myMissingSP’.
    • |113|80004005|[Microsoft][ODBC_SQL_Server_Driver][SQL_Server]The_conversion_of_a_varchar_data_type_to_a_datetime_data_type_resulted_in_an_out-of-range_value.

 

 

Dig Deeper

First Code

This is the line number in the source code file.

 

Second and Third Code

Here is our second and third values in tabular form.

 

ODBC Error Sample
 80040e14 Could_not_find_stored_procedure_’dbo.usp_myMissingSP’.
 80004005  The_conversion_of_a_varchar_data_type_to_a_datetime_data_type_resulted_in_an_out-of-range_value.

 

 

 

The first error with missing SP is because we had yet to port a new SP to this DB Environment.

And, the second problem was due to a SQL Server Language & Internalization setting that was yet configured for the user.

We posted about same error here – “The conversion of a nvarchar data type to a datetime data type resulted in an out-of-range value“.  ( https://danieladeniji.wordpress.com/2014/11/15/microsoft-sql-server-transact-sql-error-the-conversion-of-a-nvarchar-data-type-to-a-datetime-data-type-resulted-in-an-out-of-range-value/ ).

 

 

Charts

At this point the chart’s interface is very minimal and it does not appear that we can configure X and Y axis much.  And, so we ended up striping away extraneous columns and having only the columns we wanted to chart on.

Here is the query for looking at our 500’s against Win32 Error Codes.

Code


/*  Count and sort HTTP 500 status codes */

SELECT  

       sc-win32-status
     , count(*) as Hits

FROM '[LOGFILEPATH]' 

where  sc-status = 500

group by
       sc-status
     , sc-substatus
     , sc-win32-status

order by Hits desc

 

Output:

Win32Status4HTTP500Graphed

 

Acknowledged

As I always say the good thing about writing is that it forces and encourages one to publicly give credit.  Most of the LogParser queries are seeded by the ones shared by James Skemp @ http://logparserplus.com/Examples.

 

Conclusion

Set out to write more about HTTP 500 and SQL Server time outs.

But, like Jude, whose book I have been listening to via a shared commentary on YouTube, I found myself with a problem.

Here is Jude’s opening Salvo:

Dear friends, although I was very eager to write to you about the salvation we share, I felt compelled to write and urge you to contend for the faith…

Mine is far away simpler.  And, I will anchor on what my far younger “Play Sister” told me last weekend. She wanted me to do something for her, and I wanted to avoid doing it.  And, so she quipped “Hey Mister….”.

More on the semblance later.

 

Listening

The talk about Jude took me back to “Hey Jude” by the Beatles.  Here is a fabulous song I only just discovered within the same journey.

John Lennon – Beautiful Boy
https://www.youtube.com/watch?v=Lt3IOdDE5iA

 

And, the song does make a shared, universal sense and truth, as “Life is what happens to you while you’re busy making other plans” – John Lennon.  I  can’t believe it is 34 years to the month already.

 

References

IIS W3c Extended Log Format

 

IIS Status and Substatus codes

 IIS 6

 

HTTP 500

 

HTTP TroubleShooting

 

Log Parser Query Samples

 

Log Parser Studio

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s