Weird behaviour with searching the 'user' field in Security WinEventLogs

[althomas]

Hi all,

I'm trying to do a search over some CIM fields in the WinEventLog:Security source (both XML and normal), but encountering some weird behaviour.

If I run the following search it returns 89 results (over a specific one hour period):

index=db_it_windows source=wineventlog:security EventCode=4634 OR EventCode=4647 user="*"

If I run the following search it returns 3,614 results (over the same hour period):

index=db_it_windows source=wineventlog:security EventCode=4634 OR EventCode=4647
| eval user1=user
| search user1=*

Bizarrely enough, evaluating user to itself also works:

index=db_it_windows source=wineventlog:security EventCode=4634 OR EventCode=4647
| eval user=user
| search user=*

I've had a look in the search.log, but I'm not really seeing anything that jumps out at me apart from this:

07-04-2018 16:25:12.064 INFO  SearchOperator:kv - KVSearchExpander::expandSearch: user="*" -> ( user="*" OR sourcetype=hist_unix OR sourcetype="a_sourcetype_1" OR sourcetype="a_sourcetype_2" )

In the second query, where I re-evaluate user to be user1, then I don't see anything of this nature.

Has anyone had issues with this before?

Best regards,
Alex

[woodcock · Accepted solution]

You have to tell the Search Head that these fields are not indexed fields by adding this to fields.conf:

[user]
INDEXED_VALUE = false

See details here:
https://www.splunk.com/blog/2011/10/07/cannot-search-based-on-an-extracted-field.html

[althomas]

So this is the closest thing to the actual solution here.

I've run these queries across multiple search heads now:

index=db_it_windows source=wineventlog:security EventCode=4624  earliest=1549011601 latest=1549012501 _indextime < 1550102400 user=*


index=db_it_windows source=wineventlog:security EventCode=4624  earliest=1549011601 latest=1549012501 _indextime < 1550102400
| eval user1=user
| search user1=*

I've tested this on 7.2.0, for the top query I got 469882 results, for the bottom I got 470174 results. This is with INDEXED_VALUE set to false.

On a freshly upgrade 7.2.4 server without INDEXED_VALUE set to false, I got 324624 results for the top query. Setting that config parameter, then reloading the search head netted 469882 results, the same as the 7.2.0 search head.

There are still some discrepancies, but it's reduced that to 292 differences in half a million results.

[sdesruelles]

Hi @althomas,

We had the same problem as you do but with another field.
First thing to do is check in the search.log of your search to check all the parsing that is applied.

For us, it was not explicit at all and I had to check all the TAs one by one but finally manage to see what happened.
If I can suggest, a first step would be to check all the transforms.conf and see if you have the same source_key and dest_key for a unique stanza:

[<custom_stanza>]
SOURCE_KEY = user
REGEX = ^(\S+)\s+.*$
FORMAT = user::$1

This example is not correct because having the same src and dest creates a loop and somehow messes with other stuff.
The dest can be:

• The DEST_KEY;
• A capturing field in REGEX (?...);
• The left field within the FORMAT.

Hope this will help.

Regards,
S.

[woodcock]

Boolean logic 101: NEVER mix AND and OR without parentheses; try this:

index=db_it_windows AND source=wineventlog:security AND (EventCode=4634 OR EventCode=4647) AND user="*"

[althomas]

Unfortunately it's not my boolean logic that's causing the issue. The extra ANDs and parentheseses are superfluous in SPL as it interprets my query above as though it was written as you wrote it. I did double check and I get the same issue. I picked a random hour and used the query you provided -- 120 results. Without user=* I get 1,704 results.