IndexScopedSearch The search failed. More than 1000000 events were found

[JyPl4wNYu7GV1uL]

I also have this issue:

[idx01,idx02] Error in 'IndexScopeSearch': The search failed. More than 1000000 events found at time 1765170000

This is on a /var/log/audit/audit.log file which fills to 2MB, then rotates to audit.log.1 (which is not indexed).  It happens every night a midnight.  I ran a snapshot script to get the audit.log file every 0.1 seconds around midnight and there are at most a few hundred log messages with the 1765170000 timestamp.

I searched with "| tstats count where index=audit_log by host, status" from 00:00:00 to 00:00:01 and splunk "thinks" there are 4.5 million events there.

Man, I'm stumped.  I opened a splunk ticket, but wanted to track the issue here too.

Moreover, when examining the search with "inspect job" or when querying through the REST interface with curl, the "isFailed=0" is set.  How does that make sense.  You can see the error on the search head in the var/run/splunk/dispatch/<sid>/info.csv file, but that doesn't come back through REST.

[PickleRick]

I'm sorry but I'm lost here. You're listing a message from a search about number of results then jump straight into ingestion issues. How are they connected to each other?

EDIT: OK, I missed the part about all those events being indexed at the same point in time.

This is typically an issue with timestamp recognition/assignment configuration. Check splunkd.log for entries about assuming previous event's time to confirm.

I'd suspect that you're ingesting /var/log recursively en masse with a single sourcetype whereas auditd logs have a different structure.

[JyPl4wNYu7GV1uL]

See my reply below.  I believe I addressed all your suggestions.  For all the other events not at the 00:00:00 timestamp, the timestamp extraction is working just fine.  None of the splunkd.log files show any weirdness around the midnight time.

[PrewinThomas]

@JyPl4wNYu7GV1uL 

How are you rotating your log file? Are you using logrotate.conf with copytruncate or create option?

And what's your inputs.conf and props.conf for this.
Also Is this only for audit.log?

Regards,
Prewin
🌟If this answer helped you, please consider marking it as the solution or giving a Karma. Thanks!

[JyPl4wNYu7GV1uL]

The audit.log is being rotated by settings in auditd.conf.  I'll check those settings and see if any might make the impact.  The config options differ slightly from those in logrotate.conf.

The /var/log/audit/audit.log is fully specified in the monitor statement in inputs.conf.  The props.conf for the audit_log sourcetype is all defaults.  Splunk is extracting the timestamps correctly without any timestamp config settings.  It only hits the error at midnight every day.  This file gets its own sourcetype and index (and, currently, I'm only forwarding from one host).

I ran an inotifywait on the file and there were no anomalies.  As I mentioned I made a copy of the file every 0.1 seconds before, during, and after midnight and there were just a couple hundred at the midnight timestamp (to the second; the timestamps also have ms).  Also, there was no weirdness in the splunkd.log on the forwarder, indexer, or search head around midnight.

Totally stumped.  Also, even though the error is in the UI and in the info.csv file in var/run/splunk/dispatch/<sid>, in the "inspect job" the isFailed is 0.  That's even more concerning.

[PickleRick]

No. It's not "at midnight"

type=SYSCALL msg=audit(1765484778.894:1328591): arch=c000003e syscall=92 success=yes exit=0 a0=55eef5273940 a1=0 a2=0 a3=0 items=1 ppid=1048942 pid=1048943 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts4 ses=557 comm="bash" exe="/usr/bin/bash" subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 key="perm_mod"ARCH=x86_64 SYSCALL=chown AUID="user" UID="root" GID="root" EUID="root" SUID="root" FSUID="root" EGID="root" SGID="root" FSGID="root"

This is a typical auditd event. As you can see, it has a epoch-based timestamp in the msg field. No default definition will catch that. That's why all events are squashed onto the midnight timestamp. They come from different points in time but Splunk assigns them a midnight timestamp because it can't find a better one (and the time config isn't "current").

[JyPl4wNYu7GV1uL]

Yes, exactly, that's the time format I see in the events.  Nonetheless, in a search which avoids the 00:00:00 time, _time values *are* getting the correct value matching the epochSeconds.ms in the log message.  I'll troll around and see if there's some other TIME_FORMAT setting which is making this work, but it's not in my props.conf for the audit_log sourcetype.

Hmm, I see I still have that old all_date_patch_props.xml installed.  I'll check that.

[PickleRick]

Are those correctly parsed and those "stuck" at midnight from the same host?

Did you check the "real" timestamp for any sample of those midnight results? Is there any pattern there?

[JyPl4wNYu7GV1uL]

There's only one host forwarding right now.  Ya, like I say, I ran a script to snapshot the audit.log file every 0.1s before, during, and after midnight and there is only a few hundred events with the 00:00:00 timestamp.

I think I'm on to a solution.  I ran a test on another splunk instance (10.0.1) I have and ingested a one-shot on the audit.log on that server and assigned it the pre-trained linux_audit sourcetype which is defined in system/default/props.conf.  The timestamps were extracted correctly from the $SPLUNK_HOME/etc/datetime.xml config which is also set in etc/system/default/props.conf with a 

DATETIME_CONFIG = /etc/datetime.xml

which has an epoch seconds extractor with sub-seconds.

So I believe my issue on my other instance (9.1.0.2) is that the audit.log was give custom sourcetype of audit_log (which does not have any timestamp config associated with it).  Then when the first event comes in just after 00:00:00, it get assigned the timestamp of index time, and then subsequent events get the prior event's timestamp and that goes on for millions of events.  I can't explain exactly how my search for times after 00:00:01 see events with the correct _time matching the epochSeconds.ms in the log message.  But, there's also this in the system/default/props.conf:

[source::.../var/log/audit/audit.log(.\d+)?]

sourcetype = linux_audit

So, I'm guessing that is getting the default etc/datatime.xml triggered and getting the timestamps extracting properly.

On my 9.1.0.2 instance I'm just going to change the sourcetype to the pre-trained linux_audit and it should fix the problem.  I'll report back on Monday.

[PickleRick]

DATETIME_CONFIG is usually not changed across sourcetypes (it's very rarely touched) except for setting it to CURRENT or - much less often - NONE. It's the other settings which are responsible for timestamp extractions.

Key settings here are

/opt/splunk/etc/apps/TA-linux_auditd/default/props.conf TIME_FORMAT = %s.%3N
/opt/splunk/etc/apps/TA-linux_auditd/default/props.conf TIME_PREFIX = msg=audit\(

That's what I was talking about all along. If Splunk cannot find a timestamp for the event, it assumes current (in this case - midnight) event. Then, until it hits limits for MAX_DAYS_AGO, MAX_DAYS_HENCE, MAX_DIFF_SECS_AGO and MAX_DIFF_SECS_HENCE, it just assumes every subsequent event has the same timestamp since it cannot find a "healthy" timestamp in the event itself.