IIS Logs / Log Parser Studio – Aggregated Hits per Server

Background

Our monitoring team has developed and rolled out scripts for monitoring our web farm.

And, we are getting alerts through email.

Quite a lot of emails are coming across and wanted to see if they are coming from same host or a combination of hosts.

 

Emails

Looked at the emails and they happen to be coming from same host.

And, so will have to engage our Network team and see how the Load Balancer is configured.

Is there a prospect that more traffic is being directed at the failing node?

Network Load Balancer

As we prepared to go to the Network Load Balancer team took the opportunity to take gather and query the IIS Logs, as well.

 

TroubleShooting

Log Parser Studio

Query


SELECT 
            To_String(date, 'yyyy-MM-dd') as dated

          , sc-status as status

          , sum (
                    case s-ip
                        when '10.0.4.25' then 1
                        else 0
                   end
               ) as S1

          , sum (
                    case s-ip
                        when '10.0.4.26' then 1
                        else 0
                   end
               ) as S2


          , sum (
                    case s-ip
                        when '10.0.4.27' then 1
                        else 0
                   end
               ) as S3

         , sum (
                    case s-ip
                        when '10.0.4.28' then 1
                        else 0
                   end
               ) as S4

          , min(TO_TIMESTAMP(date, time)) as tsRecordedMin


          , max(TO_TIMESTAMP(date, time)) as tsRecordedMax


FROM '[LOGFILEPATH]' 


where   (


           (

             TO_TIMESTAMP(date, time) 
                     between timestamp('2017/08/02 10:30:00', 'yyyy/MM/dd hh:mm:ss')  
                          and timestamp('2017/08/02 17:20:00', 'yyyy/MM/dd hh:mm:ss')
           )

       )

/*

	and  c-ip not in ('10.0.4.141')
	
*/

group by
         date
       , sc-status


order by
           dated 
         , status



Output

Time Range – 1 ( August 2nd 10:30 AM – 5:20 PM )

Results

Explanation
  1. It is difficult to make case that traffic is exhaustively being waded into a specific host

Time Range – 2 ( August 8th 5:13 PM – 8:40 PM )

Results

Explanation
  1. In our second time slot, 4700 records bearing HTTP 200 is right around average

Summary

At this time it is likely that the sufferance we are seeing with this specific host is not due to outside pressure, but internal to the host itself.

 

Internet Information Server (IIS) – Application Pool – Tracking – Day 2

Background

This is the second post on our series on tracking the status of IIS’s Application Pool.

Lineage

Here is our initial post:

  1. Internet Information Server (IIS) – Application Pool – Tracking
    Link

 

TroubleShooting

Event Viewer

Log Parser Studio

Queries

Query – Get All WAS Entries
Query
SELECT TOP 1000

         TO_STRING(TimeGenerated, 'yyyy-MM-dd HH:mm:ss') as TimeGenerated
       , ComputerName
       , EventCategoryName
       , EventTypeName
       , EventID
       , SourceName
       , Message as Message
  
from  '[LOGFILEPATH]'

where ( SourceName = 'WAS' ) 
 
ORDER BY
           ComputerName
         , TO_STRING(TimeGenerated, 'yyyy-MM-dd HH:mm:ss') DESC

Output

 

Query – Get WAS Entries – Application Pool Disabled
Query


SELECT TOP 1000

         TO_STRING(TimeGenerated, 'yyyy-MM-dd HH:mm:ss') as TimeGenerated
       , ComputerName
       , EventCategoryName
       , EventTypeName
       , EventID
       , SourceName
       , Message as Message
  
from  '[LOGFILEPATH]'

where ( SourceName = 'WAS' ) 
 
and ( Message like '%disable%' ) 

ORDER BY
           ComputerName
         , TO_STRING(TimeGenerated, 'yyyy-MM-dd HH:mm:ss') DESC
Output

 

Summary

There are a few entries bearing the Source WAS in Windows System Event Viewer.
Inclusive are :

  1. A process serving application pool ‘DefaultAppPool’ failed to respond to a ping. The process id was ‘6208’.
  2. A process serving application pool ‘DefaultAppPool’ suffered a fatal communication error with the Windows Process Activation Service. The process id was ‘13844’. The data field contains the error number.
  3. A worker process with process id of ‘21412’ serving application pool ‘DefaultAppPool’ has requested a recycle because the worker process reached its allowed processing time limit.
  4. Application pool ‘DefaultAppPool’ is being automatically disabled due to a series of failures in the process(es) serving that application pool.

 

The ones most pernicious is “Application pool ‘DefaultAppPool’ is being automatically disabled due to a series of failures in the process(es) serving that application pool. “

Internet Information (IIS) / Log Parser – Queries – String Pattern Matching

Background

Looking for File I/O Exceptions in the Event Viewer.

 

Query

Sample

Sample 001

Code


SELECT TOP 100 
 
         TimeGenerated
       , ComputerName
       , EventCategoryName
       , EventTypeName
       , EventID
       , SourceName
       , Message as Mesg
       , Strings as Strings
       , EXTRACT_TOKEN(Strings,1,'|') AS AppName
       , EXTRACT_TOKEN(Strings,2,'|') AS AppVersion
       , EXTRACT_TOKEN(Strings,3,'|') AS S3
       , EXTRACT_TOKEN(Strings,4,'|') AS Module
       , INDEX_OF(Message, 'System.IO.IOException') as indexOf
       , case INDEX_OF(Message, 'System.IO.IOException') 
            when 0 then 'N'
            when NULL then 'N'
            else 'Y'
         end as IOE
       , CASE strcnt(Message, 'System.IO.IOException')
             when 0 then 'No'
             else 'Yes'   
         end as IOException
 
from  '[LOGFILEPATH]'
 
WHERE ( EventType = 1 OR EventType = 2 )

and    INDEX_OF(Message, 'System.IO.IOException') > 0

 
ORDER BY
         TimeGenerated DESC


Output

 

Explanation

  1. INDEX_OF
    • We use INDEX_OF to find the position of the sought string in the Message column
      • When the column contains System.IO.IOException the query returns the starting position of the found pattern
      • When not found, null is returned
  2. STRCNT
    • We invoke STRCNT to count number of matches
      • When String not found, 0 return
      • When matched, number of matches

 

References

  1. StackOverflow
    • Log Parser Case Statement
      Link

 

Windows – Event Viewer Parsing Through Log Parser Studio

Background

Need to parse MS Windows Event Logs.

One of the ways to do so is to use Log Parser Studio.

 

Event Viewer

Let us save the events unto the File System.

Outline

  1. Launch Event Viewer
  2. Select the Logs you want ( Application / System / Security )
  3. Right click on the Logs and from the drop down menu, choose “Save All Events As …
  4. Choose Folder And Filename
  5. The file is saved with an extension of “Event Files (*.evtx )

 

Images

Launch Save Event As

Choose Filename

 

Log Parser Studio

Outline

  1. Launch Log Parser Studio
  2. Choose Log Type: EVTLOG
  3. Enter Query
  4. Execute Query

 

Choose Log Type : EVTLOG

Sample Queries


/*  Find top 1000 warnings and errors in the Application Log 
    Levels: 1=Error, 2=Warning                                
*/
SELECT TOP 1000 
             TimeGenerated
           , ComputerName
           , EventCategoryName
           , EventTypeName
           , EventID
           , SourceName
           , Message
FROM 'C:\Temp\04_WindowsLogs_Applications_20170518_0403PM.evtx'
WHERE ( EventType = 1 OR EventType = 2 )
AND   (
               (SourceName like 'ASP%' )
            or (SourceName = '.NET Runtime' )
            or (SourceName = 'Application Error' )
      )
ORDER BY TimeGenerated DESC


Click Execute Button

Click on the Execute Button – The Read icon with the exclamation mark!

 

Sample Output

 

Export

Outline

  1. In Log Parser Studio, use menu File \ Export \ Output as .CSV
  2. In the “Choose Location to save CSV File” window, please specify folder and file name

 

Images

File \ Export \ “Output as .CSV”

 

Choose Location to save CSV File

Excel File

 

Microsoft – Log Parser Studio – Will not start

Background

Last week I used Microsoft’s Log Parser Studio to review some IIS Logs, but in the middle of my analysis the Application aborted on me.

I tried restarting the Application a few times, but that proved fruitless.

 

Thankfully

Thankfully it is now Saturday afternoon and we received MS Security updates early Saturday morning.  And, so I was hoping that the reboot that occurs after security patches would have saved me.

But, still no help.

Error Messages

The system itself does not keep an actually log file, but uses MS Windows Event Viewer.

Here is what is logged.

MS Windows Event Viewer

The process was terminated due to an unhandled exception.


Application: LPS.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.Configuration.ConfigurationErrorsException
   at System.Configuration.ConfigurationSchemaErrors.ThrowIfErrors(Boolean)
   at System.Configuration.BaseConfigurationRecord.ThrowIfParseErrors(System.Configuration.ConfigurationSchemaErrors)
   at System.Configuration.BaseConfigurationRecord.ThrowIfInitErrors()
   at System.Configuration.ClientConfigurationSystem.OnConfigRemoved(System.Object, System.Configuration.Internal.InternalConfigEventArgs)

Exception Info: System.Configuration.ConfigurationErrorsException
   at System.Configuration.ClientConfigurationSystem.OnConfigRemoved(System.Object, System.Configuration.Internal.InternalConfigEventArgs)
   at System.Configuration.Internal.InternalConfigRoot.OnConfigRemoved(System.Configuration.Internal.InternalConfigEventArgs)
   at System.Configuration.Internal.InternalConfigRoot.RemoveConfigImpl(System.String, System.Configuration.BaseConfigurationRecord)
   at System.Configuration.BaseConfigurationRecord.GetSectionRecursive(System.String, Boolean, Boolean, Boolean, Boolean, System.Object ByRef, System.Object ByRef)
   at System.Configuration.BaseConfigurationRecord.GetSection(System.String)
   at System.Configuration.ClientConfigurationSystem.System.Configuration.Internal.IInternalConfigSystem.GetSection(System.String)
   at System.Configuration.ConfigurationManager.GetSection(System.String)
   at System.Configuration.ClientSettingsStore.ReadSettings(System.String, Boolean)
   at System.Configuration.LocalFileSettingsProvider.GetPropertyValues(System.Configuration.SettingsContext, System.Configuration.SettingsPropertyCollection)
   at System.Configuration.SettingsBase.GetPropertiesFromProvider(System.Configuration.SettingsProvider)
   at System.Configuration.SettingsBase.GetPropertyValueByName(System.String)
   at System.Configuration.SettingsBase.get_Item(System.String)
   at System.Configuration.ApplicationSettingsBase.GetPropertyValue(System.String)
   at System.Configuration.ApplicationSettingsBase.get_Item(System.String)
   at ExLPT.Properties.Settings.get_LastLogFolder()
   at ExLPT.MainForm..ctor()
   at ExLPT.Program.Main()


 

Remediation

There are a couple of remediation choices:

  1. Copy everything in the Application’s folder to a new folder and run from the new folder
  2. Run from same folder after renaming the application’s configuration file ( LPSV2Library.XML)

 

FileList

IIS – IISLog – 500 and Log Parser Studio

Background

As I reviewed some papers, which 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 carry out 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