Why is a small percentage of our IIS Advanced Logs being parsed mid-line, causing them to have incorrect field extractions?

[jberd126]

We are scraping IIS advanced logs using Splunk Universal Forwarder and Indexers on v6.2.2.

We've discovered that a small percentage of our logs are being parsed mid-line causing them to have incorrect field extractions. For example, in Splunk the lines are parsed as:

ro\MainWS.asmx" 200 "AU01" - 0 3015 900 - 1234:5678:abcd::8e98:6635 - "au01" POST 1201 - -

inWS.asmx app=fire(3408) "E:\inetpub\MainWS.asmx" 200 "AP01" - 0 5460 6505 - 1234:5678:abcd::8e98:683a - "ap01" POST 124 - -
nary/mainws.asmx - "E:\inetpub\binary\mainws.asmx" 200 "CGYETRMAP01" - 0 2587 5980 - 169.152.5.219 - "ap01" POST 1981 - -

I've verified in the original source files that the lines are properly formatted.

I did find many instances of these warnings however I cannot determine why they are occurring.

05-25-2015 00:09:24.806 -0600 WARN  DateParserVerbose - Failed to parse timestamp. Defaulting to timestamp of previous event (Mon May 25 00:09:24 2015).

Our inputs.conf is

  [monitor://C:\inetpub\logs\AdvancedLogs]
    index = windows
    sourcetype=iis
    disabled = 0
    whitelist = \.log$

[rcdalisay · Accepted solution]

I suspect that you log file is being written in chunks or intervals or just plain slow. Try adjusting time_before_close parameter in your monitor stanza and see if it would help.

[jberd126]

@rcdalisay,
Thanks for the tip - I'll look into that parameter.

We've discovered that logs were getting parsed incorrectly after several hours (it's fine after rollover then gets wonky). Decreasing the rollover duration from 1 day to 1 hour appears to have worked around this problem however I haven't been able to correlate if it's a time or volume issue.

[jberd126]

I found this note:

The logs for IIS FTP flush to disk
every 6 minutes, and the HTTP logs
every 1 minute (or 64kb)

Flush IIS HTTP and FTP Logs to Disk - http://weblogs.asp.net/owscott/flush-http-and-ftp-logs-in-iis

[jberd126]

We set time_before_close parameter to 60, based on information in the following article and it resolved this parsing problem.

Flush IIS HTTP and FTP Logs to Disk - http://weblogs.asp.net/owscott/flush-http-and-ftp-logs-in-iis

[iis]
...
time_before_close = 60

[woodcock]

We need your props.conf file. The log indicates you have ineffective timestamp configurations.

[bmacias84]

It also possible that your lines are being truncated due to length.

[jberd126]

Local forwarder props.conf
[iis]
TZ = UTC

Indexer props.conf
[iis]
pulldown_type = true
MAX_TIMESTAMP_LOOKAHEAD = 32
SHOULD_LINEMERGE = False
INDEXED_EXTRACTIONS = w3c
detect_trailing_nulls = auto
category = Web
description = W3C Extended log format produced by the Microsoft Internet Information Services (IIS) web server

[woodcock]

Is this part of an app or something you create yourself? I do not see any configuration telling Splunk where and what format the timestamp is. This is a fundamental thing that should always be done and can cause much havoc when not/incorrectly done:

http://docs.splunk.com/Documentation/Splunk/6.2.3/Data/Configuretimestamprecognition

You may get improved/tolerable results by removing the MAX_TIMESTAMP_LOOKAHEAD = 32 because using that without being certain that all of the timestamp is in that range (1-32) will cause Splunk to not find a timestamp (which is what the log is saying).

[jberd126]

We did not create anything other than the input (and assign the timezone, although I wouldn't expect that we should have to)

We are using Splunk 6 indexed extractions that are out of the box.
http://blogs.splunk.com/2013/10/18/iis-logs-and-splunk-6/