What search can I use to identify logs with future timestamps?

[Hemnaath]

Hi All, Can any one guide me on how to check whether any log sources that are logging with future time stamps. I am not sure how to identify those log source which are having a future time stamps. Kindly guide me on this.

thanks in advance

[kamal_jagga]

index=* | dedup sourcetype | table index sourcetype host _time. In the time picker, go to advanced options and put earliest time as now and apply.

[preotesoiu]

You can deploy meta_woot app and one of the capabilities of this app is to identify host with future time stamps. Have a look at the app, might help with what you need.

[gjanders]

EDIT: I later packed these alerts and others into an app called Alerts for Splunk Admins on SplunkBase and also on github if you wanted just the searches...

I use (to detect future based data in any index):

index=* earliest=+5m latest=+20y 
| eval ahead=abs(now() - _time)
| eval indextime=_indextime
| bin span=1d indextime 
| stats avg(ahead) as averageahead, max(_time) AS maxTime, min(_time) as minTime, count by host, sourcetype, index, indextime
| where indextime>(now()-604800) AND averageahead > 1000
| eval averageahead =tostring(averageahead, "duration")
| eval indextime=strftime(indextime, "%+"), maxTime = strftime(maxTime, "%+"), minTime = strftime(minTime, "%+")

[Hemnaath]

Hi Garethatiag, Thanks a lot for providing the query to fetch the future log source. When we had executed the above query by setting a time frame as All Time, we got some 550 node servers results.

host sourcetype index indextime averageahead maxTime minTime count
test1 Script:ListeningPorts win_svrs 00:00.0 16:41:30 49:00.0 49:00.0 49
test2 Script:ListeningPorts win_svrs 00:00.0 11:28:30 36:00.0 36:00.0 45
test3 Script:ListeningPorts win_svrs 00:00.0 4:29:30 37:00.0 37:00.0 45
test4 Script:ListeningPorts win_svrs 00:00.0 4:02:30 10:00.0 10:00.0 41
test5 Script:ListeningPorts win_svrs 00:00.0 0:28:30 36:00.0 36:00.0 68
test6 Script:ListeningPorts win_svrs 00:00.0 5:28:30 36:00.0 36:00.0 73

I am not that good in SPL, so could not understand what the output is trying to convey. Could please guide on this.

thanks in advance.

[gjanders]

I've updated my post to use eval/strftime instead to see if that makes it more clear.

The query attempts to look for data that has been parsed between 5 minutes and 20 years into the future, and indexed during the last 7 days

The average ahead should be >1000 in my query and I can see 0 in your results...

If you want to see any future based data irrelevant of when it was indexed (I look over 7 days as a weekly alert FYI) then drop this line:

 | where indextime>(now()-604800) AND averageahead > 1000

And replace it with:

 | where averageahead > 1000

[Hemnaath]

Hi Garethatiag, thanks for your effort, I have executed the update query from your post for a time frame of last 7 days. And I had got the below output .

host sourcetype index indextime averageahead maxTime minTime count
test1 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 15:56:22 Wed Aug 16 22:49:00 EDT 2017 Wed Aug 16 22:49:00 EDT 2017 49
test2 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 10:42:22 Wed Aug 16 17:35:00 EDT 2017 Wed Aug 16 17:35:00 EDT 2017 45
test3 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 3:44:22 Wed Aug 16 10:37:00 EDT 2017 Wed Aug 16 10:37:00 EDT 2017 45
test4 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 3:17:22 Wed Aug 16 10:10:00 EDT 2017 Wed Aug 16 10:10:00 EDT 2017 41
test5 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 4:43:22 Wed Aug 16 11:36:00 EDT 2017 Wed Aug 16 11:36:00 EDT 2017 73
test6 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 16:30:22 Wed Aug 16 23:23:00 EDT 2017 Wed Aug 16 23:23:00 EDT 2017 40

And also after changing the query by replacing it with | where averageahead > 1000 got the below output.

host sourcetype index indextime averageahead maxTime minTime count
test1 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 15:52:28 Wed Aug 16 22:49:00 EDT 2017 Wed Aug 16 22:49:00 EDT 2017 49
test2 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 10:38:28 Wed Aug 16 17:35:00 EDT 2017 Wed Aug 16 17:35:00 EDT 2017 45
test3 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 3:40:28 Wed Aug 16 10:37:00 EDT 2017 Wed Aug 16 10:37:00 EDT 2017 45
test4 Script:ListeningPorts win_svrs Wed Aug 16 00:00:00 EDT 2017 3:13:28 Wed Aug 16 10:10:00 EDT 2017 Wed Aug 16 10:10:00 EDT 2017 41

Could you please guide us, whether we have any future log data source in our environment based on the above output result. As we have got some 550 nodes out of 2500 nodes in our environment, after executing the query.

thanks in advance.

[gjanders]

So the above is advising that hosts test1/2/3/4 with sourcetype Script:ListeningPorts in index win_svrs are definitely logging data with timestamps in the future!

The average is 15 hours ahead in the first line....

Perhaps you can try:
index=win_svrs host=test1 sourcetype=Script:ListeningPorts earliest=+5m latest=+20y
| where _indextime < _time
| eval indextime=strftime(_indextime, "%+")

I have not tested the where clause, but I suspect even without it you should see some data with index time stamps much older than the time stamps received...

[Hemnaath]

Hi Garethatiag, again thanks for your effort, I had executed the query for few of the servers with time frame set as last 24 hours and found below outputs.

index=win_svrs host=test1 sourcetype=Script:ListeningPorts earliest=+5m latest=+20y
| where _indextime < _time
| eval indextime=strftime(_indextime, "%+")

8/17/17
10:49:00.000 PM
08/17/2017 0:22:49 transport=TCP dest_ip=[::] dest_port=63351 pid=6112
host = test1 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/17/17
10:49:00.000 PM
08/17/2017 0:22:49 transport=TCP dest_ip=[::] dest_port=63335 pid=588
host = test1 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/17/17

and there are nearly 375 nodes having the future log time problem from the same sourcetype = Script:ListeningPorts. I have checked the remote server node test1 time, its showing the correct time EDT time. Kindly let me know how to fix this issue.

[gjanders]

Time parsing is done per sourcetype so assuming all logs entries look like this:
08/17/2017 0:22:49 transport=...

You could update props.conf with:
TIME_PREFIX=^
TIME_FORMAT = %m/%d/%Y %k:%M:%S

If your forwarders run in a different time zone or similar you can also use TZ property in the props.conf but the above might fix your issue...

[Hemnaath]

Hi Garethatiag, Good Morning thanks for helping me in this problem. Today I had executed the same query which you had provide in the above comments with a time frame set as Last 24 hours. This query was executed at EST 9:35 AM Sunday, August 20, 2017 (EDT)

Query Details
index=win_svrs host=test01 sourcetype=Script:ListeningPorts earliest=+5m latest=+20y
| where _indextime < _time
| eval indextime=strftime(_indextime, "%+")

8/20/17
10:49:00.000 PM
08/20/2017 0:22:49 transport=TCP dest_ip=[::] dest_port=63350 pid=6112
host = test01 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/20/17
10:49:00.000 PM
08/20/2017 0:22:49 transport=TCP dest_ip=[::] dest_port=63335 pid=588
host = test01 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/20/17
10:49:00.000 PM
08/20/2017 0:22:49 transpor

For the same host when the below query was executed with a time frame set as Last 24 hours, I got this results.
This query was executed at EST 9:35 AM Sunday, August 20, 2017 (EDT)

Query Details
index=win_svrs host=test01 sourcetype=Script:ListeningPorts.

8/20/17
9:22:49.000 AM

08/20/2017 9:22:49 transport=TCP dest_ip=[::] dest_port=63350 pid=6112
host = test01 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/20/17
9:22:49.000 AM

08/20/2017 9:22:49 transport=TCP dest_ip=[::] dest_port=63335 pid=588
host = test01 source = C:\Program Files\SplunkUniversalForwarder\etc\apps\test-app-win_svrs\bin\win_listening_ports.bat sourcetype = Script:ListeningPorts
8/20/17
9:22:49.000 AM

08/20/2017 9:22:49 transpor

Could see different index time and the event time in both the events for the same host. Similarly when I ran the same query for other hosts, I could see this difference in the time.

So in this case, can I use the Props stanza which you had posted along with the source and source type stanza in props.conf as mentioned below.

[source::...win_listening_ports.bat]
sourcetype = Script:ListeningPorts
TIME_PREFIX=^
TIME_FORMAT = %m/%d/%Y %k:%M:%S

Kindly help me on this. Thanks in advance.

[gjanders]

Try

[Script:ListeningPorts]
TIME_PREFIX=^
TIME_FORMAT = %m/%d/%Y %k:%M:%S

In the props.conf of the relevant indexer(s) or heavy forwarder(s)

[prakash007]

An easy way should be searching the index and source with a future date-time range from your time range picker.

[JDukeSplunk]

When I've run into an issue with a log file posting future timestamps, (Wrong timezone, wrong timestamp parsing, etc) an "All Time" search will usually show them. Obviously, make the search as specific as you can to limit the results.

I've not tried it, but the _indextime command might bear some fruit.

[richgalloway]

Try this query.

| metadata type=sources | where recentTime>now() | fieldformat recentTime=strftime(recentTime,"%Y-%m-%d %H:%M")

[DalJeanis]

@richgalloway @JDukeSplunk - you want lasttime rather than recenttime.

recenttime would only show the problem if the buggy event had been the last event processed on its index.

[Hemnaath]

hey richgalloway, i tried the above query but it did not fetch any result, got no result found. I had executed a query by keeping the time frame for last 24 hours.

when same query was executed with time frame for last 7 days, i could see this message in job

Metadata results may be incomplete: 100000 entries have been received from all peers (see parameter maxcount under the [metadata] stanza in limits.conf), and this search will not return metadata information for any more entries. (sid=md_1502460848.256250_8xAD37x6-D2F6-4C43-A22C-66B26D1236F6)

[richgalloway]

To find future events you must search All Time or use something like latest=+2d.

[Hemnaath]

hey i tried to execute the above query by keeping the time frame as "ALL time" but it did not fetch any results and got no result found.

0 results (before 8/11/17 11:11:48.000 AM)

Also getting this popup message in Job.
Metadata results may be incomplete: 100000 entries have been received from all peers (see parameter maxcount under the [metadata] stanza in limits.conf), and this search will not return metadata information for any more entries. (sid=md_1502460848.227250_8xAD37x6-D2F6-4C43-A22C-66B26D1236F6)

[richgalloway]

If you have no events in the future then this query will not return any results. Try omitting the where clause to see what is returned.

[Hemnaath]

Hi Richgalloway, When I had tried to execute the SPL query by omitting the where clause with the time range set as ALL Time, I could see some data being populated in statistics tab but unable to filter out the which source or index is having an issue.

I had tried in another way to find out whether future logs are generated for any index or not by keeping the time frame for future date "16-Aug-2017" and simple search like this

index = windows source=*

Can I check like this also ? is this a right way to find out whether any log sources that are logging with future time stamps.

Kindly guide me please.
thanks in advances.