Failed to start Document-level-monitor: Inconsistency of field data structures across documents for field

Plugins Security Analytics
1

I’m trying to set up Security Analytics on OpenSearch 2.6.0. The index that I’m creating a Detector for is populated by winlogbeat.

I have tried different rules, but currently I’m only using this simple custom one: (all other Windows rules are disabled)

selection:
  winlog-event_id: 4624
  winlog-event_data-TargetUserName|endswith: 'Admin'
condition: selection

I am able to trigger 2 alerts when performing a log in to a Windows machine, which is what the rule is supposed to do, but the alerts have “Error” as “Alert status”.
There are no “Findings” in the UI either.

I found these errors in the OpenSearch log which seems to occur around the same time as the alerts get visible in the UI:

[2023-03-21T13:22:34,152][ERROR][o.o.a.DocumentLevelMonitorRunner] [opensearch-node1] Failed to start Document-level-monitor Windows Admin User Logon Detector. Error: all shards failed
org.opensearch.action.search.SearchPhaseExecutionException: all shards failed
	at org.opensearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:663) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:372) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:698) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.AbstractSearchAsyncAction.onShardFailure(AbstractSearchAsyncAction.java:471) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.AbstractSearchAsyncAction$1.onFailure(AbstractSearchAsyncAction.java:294) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.SearchExecutionStatsCollector.onFailure(SearchExecutionStatsCollector.java:104) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionListenerResponseHandler.handleException(ActionListenerResponseHandler.java:74) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.search.SearchTransportService$ConnectionCountingHandler.handleException(SearchTransportService.java:753) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.transport.TransportService$6.handleException(TransportService.java:794) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.security.transport.SecurityInterceptor$RestoringTransportResponseHandler.handleException(SecurityInterceptor.java:312) ~[?:?]
	at org.opensearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1414) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.transport.TransportService$DirectResponseChannel.processException(TransportService.java:1528) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1502) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:79) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.transport.TransportChannel.sendErrorResponse(TransportChannel.java:71) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.support.ChannelActionListener.onFailure(ChannelActionListener.java:70) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionRunnable.onFailure(ActionRunnable.java:103) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:54) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.threadpool.TaskAwareRunnable.doRun(TaskAwareRunnable.java:78) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:59) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:806) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) ~[opensearch-2.6.0.jar:2.6.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: org.opensearch.index.query.QueryShardException: failed to create query: Inconsistency of field data structures across documents for field [winlog_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d.event_data.param1] of doc [23]. index options: expected 'DOCS_AND_FREQS_AND_POSITIONS', but it has 'NONE'.
	at org.opensearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:482) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:465) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.parseSource(SearchService.java:1229) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.createContext(SearchService.java:978) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.executeQueryPhase(SearchService.java:586) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService$2.lambda$onResponse$0(SearchService.java:559) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:73) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionRunnable$2.doRun(ActionRunnable.java:88) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) ~[opensearch-2.6.0.jar:2.6.0]
	... 8 more
Caused by: java.lang.IllegalArgumentException: Inconsistency of field data structures across documents for field [winlog_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d.event_data.param1] of doc [23]. index options: expected 'DOCS_AND_FREQS_AND_POSITIONS', but it has 'NONE'.
	at org.apache.lucene.index.IndexingChain$FieldSchema.raiseNotSame(IndexingChain.java:1344) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.IndexingChain$FieldSchema.assertSame(IndexingChain.java:1339) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.IndexingChain$FieldSchema.assertSameSchema(IndexingChain.java:1424) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.IndexingChain.processDocument(IndexingChain.java:567) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:242) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:432) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1532) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.apache.lucene.index.IndexWriter.addDocuments(IndexWriter.java:1503) ~[lucene-core-9.5.0.jar:9.5.0 13803aa6ea7fee91f798cfeded4296182ac43a21 - 2023-01-25 16:44:59]
	at org.opensearch.percolator.PercolateQueryBuilderExt.createMultiDocumentSearcher(PercolateQueryBuilderExt.java:578) ~[?:?]
	at org.opensearch.percolator.PercolateQueryBuilderExt.doToQuery(PercolateQueryBuilderExt.java:536) ~[?:?]
	at org.opensearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:116) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.BoolQueryBuilder.addBooleanClauses(BoolQueryBuilder.java:346) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.BoolQueryBuilder.doToQuery(BoolQueryBuilder.java:329) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:116) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.QueryShardContext.lambda$toQuery$3(QueryShardContext.java:466) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:478) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:465) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.parseSource(SearchService.java:1229) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.createContext(SearchService.java:978) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService.executeQueryPhase(SearchService.java:586) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.search.SearchService$2.lambda$onResponse$0(SearchService.java:559) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:73) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.action.ActionRunnable$2.doRun(ActionRunnable.java:88) ~[opensearch-2.6.0.jar:2.6.0]
	at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) ~[opensearch-2.6.0.jar:2.6.0]
	... 8 more

The param1 field mentioned in the error is not always included in the logs from winlogbeat, so I’m wondering if that triggers the issue.
param1 is included in the logstash-master-winlogbeat-rollover-000001 index though and it is also mapped in the Security Analytics Detector.

Any help would be greatly appreciated.

2

hi @nielsek , it looks like a Percolate Query Execution error.

org.opensearch.percolator.PercolateQueryBuilderExt.doToQuery(PercolateQueryBuilderExt.java:536) ~[?:?]

is it possible for you to share the mappings for the index? Get mapping API | Elasticsearch Guide [8.6] | Elastic

also, if possible can you please share 2 records, one with param1 field & other without it.
This will help in reproducing the issue.

3

Hi @sbcd90 - thanks for the reply!

Since my first post I have done a re-installation of the test environment, and the error has changed
from: index options: expected 'NONE', but it has 'DOCS_AND_FREQS_AND_POSITIONS'
to: index options: expected 'DOCS_AND_FREQS_AND_POSITIONS', but it has 'NONE'

I have updated the error message in the original post and will keep the environment stable now.

Here’s the mappings for logstash-master-winlogbeat-rollover-000001: winlogbeat mapping · GitHub (I was not able to post them here directly due to body char limits on the forum)

It might be off-topic for this issue, but I do not understand where/how the Percolate Query is running exactly. If I look at the query in .opensearch-sap-windows-detectors-queries-000001 then it seems to use fields called winlog-event_id_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d and winlog-event_data-TargetUserName_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d. But the aliases created on the logstash-master-winlogbeat-rollover-000001 index are called winlog-event_id and winlog-event_data-TargetUserName according to the mapping.

GET .opensearch-sap-windows-detectors-queries-000001/_search?pretty
 {
    "query": {
        "match_all": {}
    }
}

{
  "took" : 1,
  "timed_out" : false,
  "_shards" : {
    "total" : 1,
    "successful" : 1,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : {
      "value" : 1,
      "relation" : "eq"
    },
    "max_score" : 1.0,
    "hits" : [
      {
        "_index" : ".opensearch-sap-windows-detectors-queries-000001",
        "_id" : "Si5NBIcBRjuaqsfbZpGE_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d",
        "_score" : 1.0,
        "_source" : {
          "query" : {
            "query_string" : {
              "query" : "(winlog-event_id_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d: 4624) AND (winlog-event_data-TargetUserName_logstash-master-winlogbeat-rollover-000001_NC5UBIcBRjuaqsfbGL2d: *Admin)"
            }
          },
          "monitor_id" : "NC5UBIcBRjuaqsfbGL2d",
          "index" : "logstash-master-winlogbeat-rollover-000001"
        }
      }
    ]
  }
}
4

I’ve found some event samples, first one with param1 then one without it:

{
  "_index": "logstash-master-winlogbeat-rollover-000002",
  "_id": "6KBULIcBwr7R9753B6Xm",
  "_version": 1,
  "_score": null,
  "_source": {
    "host": {
      "hostname": "CERTAUTH01",
      "name": "CERTAUTH01",
      "os": {
        "family": "windows",
        "version": "10.0",
        "name": "Windows Server 2019 Standard",
        "build": "17763.3232",
        "platform": "windows",
        "kernel": "10.0.17763.3232 (WinBuild.160101.0800)"
      },
      "id": "1a2bf5c9-9c28-4592-a099-76b19b54a9dc",
      "ip": [
        "fe80::c85:9d14:7a8f:8129",
        "10.230.80.124"
      ],
      "mac": [
        "0c:75:e6:52:00:00"
      ],
      "architecture": "x86_64"
    },
    "ecs": {
      "version": "1.5.0"
    },
    "message": "The Microsoft Account Sign-in Assistant service entered the running state.",
    "tags": [
      "beats_input_codec_plain_applied"
    ],
    "agent": {
      "version": "7.9.1",
      "hostname": "CERTAUTH01",
      "ephemeral_id": "19708ce1-fcb3-43b1-847e-e6cee9548721",
      "name": "CERTAUTH01",
      "id": "2c79c5e9-6f66-42b0-80ad-525e9e8ff72d",
      "type": "winlogbeat"
    },
    "winlog": {
      "record_id": 41377,
      "keywords": [
        "Classic"
      ],
      "provider_guid": "{555908d1-a6d7-4695-8e1e-26931d2012f4}",
      "channel": "System",
      "process": {
        "pid": 676,
        "thread": {
          "id": 3260
        }
      },
      "computer_name": "CERTAUTH01",
      "task": "",
      "api": "wineventlog",
      "event_id": 7036,
      "event_data": {
        "param1": "Microsoft Account Sign-in Assistant",
        "Binary": "77006C00690064007300760063002F0034000000",
        "param2": "running"
      },
      "provider_name": "Service Control Manager"
    },
    "event": {
      "kind": "event",
      "code": 7036,
      "original": "<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'><System><Provider Name='Service Control Manager' Guid='{555908d1-a6d7-4695-8e1e-26931d2012f4}' EventSourceName='Service Control Manager'/><EventID Qualifiers='16384'>7036</EventID><Version>0</Version><Level>4</Level><Task>0</Task><Opcode>0</Opcode><Keywords>0x8080000000000000</Keywords><TimeCreated SystemTime='2023-03-29T07:45:14.850700200Z'/><EventRecordID>41377</EventRecordID><Correlation/><Execution ProcessID='676' ThreadID='3260'/><Channel>System</Channel><Computer>DKVS3CERTAUTH01.DKVS3.POWERPLANT.GREEN</Computer><Security/></System><EventData><Data Name='param1'>Microsoft Account Sign-in Assistant</Data><Data Name='param2'>running</Data><Binary>77006C00690064007300760063002F0034000000</Binary></EventData><RenderingInfo Culture='en-US'><Message>The Microsoft Account Sign-in Assistant service entered the running state.</Message><Level>Information</Level><Task></Task><Opcode></Opcode><Channel></Channel><Provider>Microsoft-Windows-Service Control Manager</Provider><Keywords><Keyword>Classic</Keyword></Keywords></RenderingInfo></Event>",
      "created": "2023-03-29T07:45:15.902Z",
      "provider": "Service Control Manager"
    },
    "@timestamp": "2023-03-29T07:45:14.850Z",
    "@version": "1",
    "log": {
      "level": "information"
    }
  },
  "fields": {
    "@timestamp": [
      "2023-03-29T07:45:14.850Z"
    ],
    "event.created": [
      "2023-03-29T07:45:15.902Z"
    ]
  },
  "sort": [
    1680075914850
  ]
}

{
  "_index": "logstash-master-winlogbeat-rollover-000002",
  "_id": "7KBULIcBwr7R9753B6Xm",
  "_version": 1,
  "_score": null,
  "_source": {
    "host": {
      "hostname": "CERTAUTH01",
      "name": "CERTAUTH01",
      "os": {
        "family": "windows",
        "version": "10.0",
        "name": "Windows Server 2019 Standard",
        "build": "17763.3232",
        "platform": "windows",
        "kernel": "10.0.17763.3232 (WinBuild.160101.0800)"
      },
      "id": "1a2bf5c9-9c28-4592-a099-76b19b54a9dc",
      "ip": [
        "fe80::c85:9d14:7a8f:8129",
        "10.230.80.124"
      ],
      "mac": [
        "0c:75:e6:52:00:00"
      ],
      "architecture": "x86_64"
    },
    "ecs": {
      "version": "1.5.0"
    },
    "message": "Credential Manager credentials were read.  Subject: Security ID:S-1-5-18 Account Name:CERTAUTH01$ Account Domain:DKVS3 Logon ID:0x3E7 Read Operation:Enumerate Credentials  This event occurs when a user performs a read operation on stored credentials in Credential Manager.",
    "tags": [
      "beats_input_codec_plain_applied"
    ],
    "agent": {
      "version": "7.9.1",
      "hostname": "CERTAUTH01",
      "ephemeral_id": "19708ce1-fcb3-43b1-847e-e6cee9548721",
      "name": "CERTAUTH01",
      "id": "2c79c5e9-6f66-42b0-80ad-525e9e8ff72d",
      "type": "winlogbeat"
    },
    "winlog": {
      "keywords": [
        "Audit Success"
      ],
      "channel": "Security",
      "record_id": 415889,
      "provider_guid": "{54849625-5478-4994-a5ba-3e3b0328c30d}",
      "process": {
        "pid": 684,
        "thread": {
          "id": 5672
        }
      },
      "computer_name": "CERTAUTH01",
      "task": "User Account Management",
      "api": "wineventlog",
      "opcode": "Info",
      "event_data": {
        "TargetName": "WindowsLive:target=virtualapp/didlogical",
        "Type": "0",
        "ProcessCreationTime": "2023-01-11T20:12:37.561760200Z",
        "CountOfCredentialsReturned": "0",
        "ClientProcessId": "68",
        "ReturnCode": "3221226021",
        "SubjectUserName": "CERTAUTH01$",
        "SubjectUserSid": "S-1-5-18",
        "SubjectLogonId": "0x3e7",
        "SubjectDomainName": "DKVS3",
        "ReadOperation": "%%8100"
      },
      "event_id": 5379,
      "activity_id": "{04a5b98a-25f9-0000-4dbb-a504f925d901}",
      "provider_name": "Microsoft-Windows-Security-Auditing"
    },
    "event": {
      "action": "User Account Management",
      "outcome": "success",
      "kind": "event",
      "original": "<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'><System><Provider Name='Microsoft-Windows-Security-Auditing' Guid='{54849625-5478-4994-a5ba-3e3b0328c30d}'/><EventID>5379</EventID><Version>0</Version><Level>0</Level><Task>13824</Task><Opcode>0</Opcode><Keywords>0x8020000000000000</Keywords><TimeCreated SystemTime='2023-03-29T07:45:14.865261000Z'/><EventRecordID>415889</EventRecordID><Correlation ActivityID='{04a5b98a-25f9-0000-4dbb-a504f925d901}'/><Execution ProcessID='684' ThreadID='5672'/><Channel>Security</Channel><Computer>CERTAUTH01</Computer><Security/></System><EventData><Data Name='SubjectUserSid'>S-1-5-18</Data><Data Name='SubjectUserName'>CERTAUTH01$</Data><Data Name='SubjectDomainName'>DKVS3</Data><Data Name='SubjectLogonId'>0x3e7</Data><Data Name='TargetName'>WindowsLive:target=virtualapp/didlogical</Data><Data Name='Type'>0</Data><Data Name='CountOfCredentialsReturned'>0</Data><Data Name='ReadOperation'>%%8100</Data><Data Name='ReturnCode'>3221226021</Data><Data Name='ProcessCreationTime'>2023-01-11T20:12:37.561760200Z</Data><Data Name='ClientProcessId'>68</Data></EventData><RenderingInfo Culture='en-US'><Message>Credential Manager credentials were read.\r\n\r\nSubject:\r\n\tSecurity ID:\t\tS-1-5-18\r\n\tAccount Name:\t\tCERTAUTH01$\r\n\tAccount Domain:\t\tDKVS3\r\n\tLogon ID:\t\t0x3E7\r\n\tRead Operation:\t\tEnumerate Credentials\r\n\r\nThis event occurs when a user performs a read operation on stored credentials in Credential Manager.</Message><Level>Information</Level><Task>User Account Management</Task><Opcode>Info</Opcode><Channel>Security</Channel><Provider>Microsoft Windows security auditing.</Provider><Keywords><Keyword>Audit Success</Keyword></Keywords></RenderingInfo></Event>",
      "code": 5379,
      "created": "2023-03-29T07:45:16.543Z",
      "provider": "Microsoft-Windows-Security-Auditing"
    },
    "@timestamp": "2023-03-29T07:45:14.865Z",
    "@version": "1",
    "log": {
      "level": "information"
    }
  },
  "fields": {
    "@timestamp": [
      "2023-03-29T07:45:14.865Z"
    ],
    "event.created": [
      "2023-03-29T07:45:16.543Z"
    ]
  },
  "sort": [
    1680075914865
  ]
}
5

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.