Shard/Virtualization Issues

Mogwhale commented 5 years ago

Seeing Courier Fetch Shard errors and issues with virtualization for a couple months now following a Wazuh version upgrade.

1) Showing the last 30 minutes of virtualizations is always missing the most recent 15-20 minutes:

2) The elasticsearch log contains many errors

cat elasticsearch.log

[2018-11-02T09:19:58,756][DEBUG][o.e.a.s.TransportSearchAction] [eA47uRs] [wazuh-alerts-3.x-2018.11.01][4], node[eA47uRshSeC7bu7-el4KtA], [P], s[STARTED], a[id=YxqFzs3sRYGBUfjsds4syQ]: Failed to execute [SearchRequest{searchType=QUERY_THEN_FETCH, indices=[wazuh-alerts-3.x-*], indicesOptions=IndicesOptions[id=39, ignore_unavailable=true, allow_no_indices=true, expand_wildcards_open=true, expand_wildcards_closed=false, allow_aliases_to_multiple_indices=true, forbid_closed_indices=true, ignore_aliases=false], types=[], routing='null', preference='1541103521464', requestCache=null, scroll=null, maxConcurrentShardRequests=5, batchedReduceSize=512, preFilterShardSize=25, allowPartialSearchResults=true, source={"size":0,"query":{"bool":{"must":[{"match_all":{"boost":1.0}},{"range":{"@timestamp":{"from":1541101797671,"to":1541103597671,"include_lower":true,"include_upper":true,"format":"epoch_millis","boost":1.0}}},{"match_phrase":{"manager.name":{"query":"monserver.company.com","slop":0,"zero_terms_query":"NONE","boost":1.0}}},{"range":{"rule.level":{"from":12,"to":null,"include_lower":true,"include_upper":false,"boost":1.0}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":[],"excludes":[]},"stored_fields":"*","docvalue_fields":["@timestamp","data.vulnerability.published","data.vulnerability.updated","syscheck.mtime_after","syscheck.mtime_before","data.cis.timestamp"],"script_fields":{},"aggregations":{}}}]
org.elasticsearch.transport.RemoteTransportException: [eA47uRs][127.0.0.1:9300][indices:data/read/search[phase/query]]
Caused by: org.elasticsearch.common.util.concurrent.EsRejectedExecutionException: rejected execution of org.elasticsearch.common.util.concurrent.TimedRunnable@48b72751 on QueueResizingEsThreadPoolExecutor[name = eA47uRs/search, queue capacity = 6650, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task execution EWMA = 461nanos, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@d599829[Running, pool size = 4, active threads = 4, queued tasks = 6779, completed tasks = 135147]]
        at org.elasticsearch.common.util.concurrent.EsAbortPolicy.rejectedExecution(EsAbortPolicy.java:48) ~[elasticsearch-6.3.2.jar:6.3.2]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) ~[?:1.8.0_144]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) ~[?:1.8.0_144]
        at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.doExecute(EsThreadPoolExecutor.java:98) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor.doExecute(QueueResizingEsThreadPoolExecutor.java:88) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.execute(EsThreadPoolExecutor.java:93) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.search.SearchService.lambda$rewriteShardRequest$0(SearchService.java:1011) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:60) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.index.query.Rewriteable.rewriteAndFetch(Rewriteable.java:113) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.index.query.Rewriteable.rewriteAndFetch(Rewriteable.java:86) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.search.SearchService.rewriteShardRequest(SearchService.java:1009) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:329) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.SearchTransportService$6.messageReceived(SearchTransportService.java:372) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.SearchTransportService$6.messageReceived(SearchTransportService.java:369) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler$1.doRun(SecurityServerTransportInterceptor.java:259) ~[?:?]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler.messageReceived(SecurityServerTransportInterceptor.java:317) ~[?:?]
        at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService.sendLocalRequest(TransportService.java:658) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService.access$000(TransportService.java:77) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService$3.sendRequest(TransportService.java:138) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService.sendRequestInternal(TransportService.java:606) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$1.sendRequest(SecurityServerTransportInterceptor.java:139) ~[?:?]
        at org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:526) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService.sendChildRequest(TransportService.java:566) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.transport.TransportService.sendChildRequest(TransportService.java:557) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.SearchTransportService.sendExecuteQuery(SearchTransportService.java:152) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.SearchQueryThenFetchAsyncAction.executePhaseOnShard(SearchQueryThenFetchAsyncAction.java:52) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase.performPhaseOnShard(InitialSearchPhase.java:213) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase.run(InitialSearchPhase.java:158) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.AbstractSearchAsyncAction.executePhase(AbstractSearchAsyncAction.java:155) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.AbstractSearchAsyncAction.start(AbstractSearchAsyncAction.java:115) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.TransportSearchAction$1.run(TransportSearchAction.java:397) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.AbstractSearchAsyncAction.executePhase(AbstractSearchAsyncAction.java:155) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:148) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:249) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase.successfulShardExecution(InitialSearchPhase.java:256) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase.onShardResult(InitialSearchPhase.java:244) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase.access$200(InitialSearchPhase.java:48) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase$2.lambda$innerOnResponse$0(InitialSearchPhase.java:217) ~[elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.action.search.InitialSearchPhase$1.doRun(InitialSearchPhase.java:189) [elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:725) [elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:41) [elasticsearch-6.3.2.jar:6.3.2]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.3.2.jar:6.3.2]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_144]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_144]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144]

Some initial status commands:

curl -XGET localhost:9200/_cat/templates?v

name                          index_patterns             order      version
security-index-template       [.security-*]              1000
.triggered_watches            [.triggered_watches*]      2147483647
.ml-anomalies-                [.ml-anomalies-*]          0          6030299
wazuh                         [wazuh-alerts-3.x-*]       0
.monitoring-es                [.monitoring-es-6-*]       0          6020099
.ml-state                     [.ml-state]                0          6030299
security_audit_log            [.security_audit_log*]     1000
.ml-meta                      [.ml-meta]                 0          6030299
.watches                      [.watches*]                2147483647
.watch-history-7              [.watcher-history-7*]      2147483647
.ml-notifications             [.ml-notifications]        0          6030299
.monitoring-beats             [.monitoring-beats-6-*]    0          6020099
.monitoring-alerts            [.monitoring-alerts-6]     0          6020099
logstash                      [logstash-*]               0          60001
kibana_index_template:.kibana [.kibana]                  0
wazuh-agent                   [wazuh-monitoring-3.x-*]   0
logstash-index-template       [.logstash]                0
wazuh-kibana                  [.kibana*]                 0
.monitoring-logstash          [.monitoring-logstash-6-*] 0          6020099
.monitoring-kibana            [.monitoring-kibana-6-*]   0          6020099

cat /usr/share/kibana/plugins/wazuh/package.json

{
    "name": "wazuh",
    "version": "3.5.0",
    "revision": "0402",
    "kibana": {
        "version": "6.3.2"
    },
    "description": "Wazuh app",
    "main": "index.js",
    "keywords": [
        "kibana",
        "wazuh",
        "ossec"
    ],
    "author": "Wazuh, Inc",
    "license": "GPL-2.0",
    "repository": {
        "type": "git",
        "url": "https://github.com/wazuh/wazuh-kibana-app.git"
    },
    "bugs": {
        "url": "https://github.com/wazuh/wazuh-kibana-app/issues"
    },
    "homepage": "https://www.wazuh.com/",
    "dependencies": {
        "angular-animate": "1.6.5",
        "angular-cookies": "1.6.5",
        "angular-material": "1.1.10",
        "dom-to-image": "^2.6.0",
        "install": "^0.10.1",
        "js2xmlparser": "^3.0.0",
        "json2csv": "^4.1.2",
        "needle": "^2.0.1",
        "node-cron": "^1.1.2",
        "pdfmake": "^0.1.37",
        "querystring-browser": "1.0.4",
        "simple-tail": "^1.1.0",
        "timsort": "^0.3.0",
        "winston": "3.0.0"
    }
}

jesusgn90 commented 5 years ago

Hi @Testbono ,

I'm sorry you are having troubles. First of all, I want to say we are now supporting up to Wazuh 3.6.1 plus Kibana 6.4.2, your version is missing lot of improvements and a few of bug fixes.

Courier fetch errors:

From your logs my bet is about the Elasticsearch queue size, please increase it as follow:

Please open with your desired text editor the file located at /etc/elasticsearch/elasticsearch.yml and copy/paste the following lines:

thread_pool:
  search:
    queue_size: 10000

Respect the indentation since it's a .yml file. Also, take care of the "_" character. Save the file and close it.

Restart Elasticsearch:

# systemctl restart elasticsearch

Elasticsearch usually takes 7-15 seconds to be ready, check if it's up using the next curl command:

$ curl "http://<elastic_ip>:9200/?pretty"

Regarding the mismatching between time filter and last events, it may be caused by differences between the Kibana instance, the Elasticsearch instance, and your own browser. Using the Discover you can see the exact timestamp for each alert, but keep in mind that Kibana filter is based in the timestamp from the events, so it literally can't show events in a different time range.

More Elasticsearch tuning can be found here: https://documentation.wazuh.com/current/installation-guide/optional-configurations/elastic-tuning.html

In addition, our guide for upgrading: https://documentation.wazuh.com/current/installation-guide/upgrading/index.html

Regards

Mogwhale commented 5 years ago

Hi @jesusgn90

I'm sorry you are having troubles. First of all, I want to say we are now supporting up to Wazuh 3.6.1 plus Kibana 6.4.2, your version is missing lot of improvements and a few of bug fixes.

Planning on upgrading once this issue is resolved =)

Courier fetch errors:

From your logs my bet is about the Elasticsearch queue size, please increase it as follow[...]:

The queue size was already configured as follows:

thread_pool:
  search:
    queue_size: 10000

This was done a few weeks ago and hasn't resolved the issue (the server and all kibana/elastic services have been restarted since)

Regarding the mismatching between time filter and last events, it may be caused by differences between the Kibana instance, the Elasticsearch instance, and your own browser. Using the Discover you can see the exact timestamp for each alert, but keep in mind that Kibana filter is based in the timestamp from the events, so it literally can't show events in a different time range.

The Kibana instance and Elasticsearch instance are on the same server so no time difference there and my browser uses the exact same times (same NTP server)

The Discover events all have the correct times as expected.

jesusgn90 commented 5 years ago

Hi @Testbono ,

Let's dig a bit more into your Elasticsearch cluster status, please paste the output from the next commands here:

How is your cluster

$ curl -X GET "localhost:9200/_cluster/health?pretty"

Specific index state

$ curl -X GET "localhost:9200/_cluster/state/_all/wazuh-alerts-3.x-2018.11.05"

Some useful stats about your cluster

$ curl -X GET "localhost:9200/_cluster/stats?human&pretty"

The above commands may produce a long output, it's not a problem. You can also attach as text files.

Best regards, Jesús

Mogwhale commented 5 years ago

Hi @jesusgn90

curl -X GET "localhost:9200/_cluster/health?pretty"

{
  "cluster_name" : "elasticsearch",
  "status" : "yellow",
  "timed_out" : false,
  "number_of_nodes" : 1,
  "number_of_data_nodes" : 1,
  "active_primary_shards" : 4333,
  "active_shards" : 4333,
  "relocating_shards" : 0,
  "initializing_shards" : 0,
  "unassigned_shards" : 4332,
  "delayed_unassigned_shards" : 0,
  "number_of_pending_tasks" : 0,
  "number_of_in_flight_fetch" : 0,
  "task_max_waiting_in_queue_millis" : 0,
  "active_shards_percent_as_number" : 50.005770340450084
}

curl -X GET "localhost:9200/_cluster/state/_all/wazuh-alerts-3.x-2018.11.05"

curl -X GET "localhost:9200/_cluster/stats?human&pretty"

{
  "_nodes" : {
    "total" : 1,
    "successful" : 1,
    "failed" : 0
  },
  "cluster_name" : "elasticsearch",
  "timestamp" : 1541443954777,
  "status" : "yellow",
  "indices" : {
    "count" : 869,
    "shards" : {
      "total" : 4333,
      "primaries" : 4333,
      "replication" : 0.0,
      "index" : {
        "shards" : {
          "min" : 1,
          "max" : 5,
          "avg" : 4.9861910241657075
        },
        "primaries" : {
          "min" : 1,
          "max" : 5,
          "avg" : 4.9861910241657075
        },
        "replication" : {
          "min" : 0.0,
          "max" : 0.0,
          "avg" : 0.0
        }
      }
    },
    "docs" : {
      "count" : 62926315,
      "deleted" : 1
    },
    "store" : {
      "size" : "35gb",
      "size_in_bytes" : 37673542536
    },
    "fielddata" : {
      "memory_size" : "16.7kb",
      "memory_size_in_bytes" : 17120,
      "evictions" : 0
    },
    "query_cache" : {
      "memory_size" : "0b",
      "memory_size_in_bytes" : 0,
      "total_count" : 0,
      "hit_count" : 0,
      "miss_count" : 0,
      "cache_size" : 0,
      "cache_count" : 0,
      "evictions" : 0
    },
    "completion" : {
      "size" : "0b",
      "size_in_bytes" : 0
    },
    "segments" : {
      "count" : 25274,
      "memory" : "342mb",
      "memory_in_bytes" : 358714611,
      "terms_memory" : "282mb",
      "terms_memory_in_bytes" : 295728557,
      "stored_fields_memory" : "23.9mb",
      "stored_fields_memory_in_bytes" : 25155216,
      "term_vectors_memory" : "0b",
      "term_vectors_memory_in_bytes" : 0,
      "norms_memory" : "21mb",
      "norms_memory_in_bytes" : 22121728,
      "points_memory" : "1.3mb",
      "points_memory_in_bytes" : 1385686,
      "doc_values_memory" : "13.6mb",
      "doc_values_memory_in_bytes" : 14323424,
      "index_writer_memory" : "0b",
      "index_writer_memory_in_bytes" : 0,
      "version_map_memory" : "0b",
      "version_map_memory_in_bytes" : 0,
      "fixed_bit_set" : "0b",
      "fixed_bit_set_memory_in_bytes" : 0,
      "max_unsafe_auto_id_timestamp" : 1541376005474,
      "file_sizes" : { }
    }
  },
  "nodes" : {
    "count" : {
      "total" : 1,
      "data" : 1,
      "coordinating_only" : 0,
      "master" : 1,
      "ingest" : 1
    },
    "versions" : [
      "6.3.2"
    ],
    "os" : {
      "available_processors" : 2,
      "allocated_processors" : 2,
      "names" : [
        {
          "name" : "Linux",
          "count" : 1
        }
      ],
      "mem" : {
        "total" : "11.5gb",
        "total_in_bytes" : 12430954496,
        "free" : "519.4mb",
        "free_in_bytes" : 544694272,
        "used" : "11gb",
        "used_in_bytes" : 11886260224,
        "free_percent" : 4,
        "used_percent" : 96
      }
    },
    "process" : {
      "cpu" : {
        "percent" : 12
      },
      "open_file_descriptors" : {
        "min" : 46036,
        "max" : 46036,
        "avg" : 46036
      }
    },
    "jvm" : {
      "max_uptime" : "7.9d",
      "max_uptime_in_millis" : 690238265,
      "versions" : [
        {
          "version" : "1.8.0_144",
          "vm_name" : "OpenJDK 64-Bit Server VM",
          "vm_version" : "25.144-b01",
          "vm_vendor" : "Oracle Corporation",
          "count" : 1
        }
      ],
      "mem" : {
        "heap_used" : "2.8gb",
        "heap_used_in_bytes" : 3071537672,
        "heap_max" : "3.9gb",
        "heap_max_in_bytes" : 4277534720
      },
      "threads" : 113
    },
    "fs" : {
      "total" : "159.9gb",
      "total_in_bytes" : 171763044352,
      "free" : "80gb",
      "free_in_bytes" : 85958529024,
      "available" : "80gb",
      "available_in_bytes" : 85958529024
    },
    "plugins" : [ ],
    "network_types" : {
      "transport_types" : {
        "security4" : 1
      },
      "http_types" : {
        "security4" : 1
      }
    }
  }
}

Thanks again for your assistance so far

jesusgn90 commented 5 years ago

Hello again @Testbono ,

From your report, I can see a few things telling us where to go:

"number_of_nodes" : 1, you should increase the number of nodes for your Elasticsearch cluster, it's exhausted, one more node would leverage the number of tasks and would reduce the high load on your master node.
""shards" : { "total" : 4333 and "docs" : { "count" : 62926315 this is a huge amount of shards and documents for a single node Elasticsearch cluster.
"mem" : { "free" : "519.4mb", it's also low in RAM, a small number of tasks may get all the RAM quickly.

Definitively I think you should make some modifications in your architecture.

Separate Kibana from Elasticsearch:

I don't know if you have a one-in-all instance including Kibana, Logstash and Elasticsearch, if so, my suggestion is to have a dedicated instance for Logstash + Elasticsearch and moving Kibana to a separated instance.

Fewer shards:

Reduce number of shards (from 5 to 2 or 3 for example) at template level for future indices.

Reduce the number of indices without losing data:

If you have very old indices that you don't need to search in, you can close them using the close API from Elasticsearch, they won't be lost from disk, but they won't be considered for searching purposes.

Cluster nodes:

This is an important thing here. You can try to give more resources to your single node (I'm mainly talking about more RAM) and try to make some adjustments following https://documentation.wazuh.com/current/installation-guide/optional-configurations/elastic-tuning.html
My suggestion is to add more nodes to your cluster. Here are some possible ways to achieve this:
- Add only one more node, a dedicated data node for ingesting. We can't have only two masters due to the split brain problem (a known problem in Elasticsearch where you end having two clusters).
- Add two more nodes: one master node and one data node. This adds HA for your cluster.

Ideally the master nodes should not manage searching and indexing procedures, they should only take decissions, set the cluster state, allocations, etc. The data nodes should be dedicated to store data and manage searching and indexing procedures. The ingest nodes can be mainly used for ingesting purposes. Also there is one more node type named tribe, these are desired for cross-cluster operations, not the case here.

You can read more in deep about it here: https://www.elastic.co/guide/en/elasticsearch/reference/current/modules-node.html

Let me know how it looks for you.

Best regards, Jesús

wazuh / wazuh-dashboard-plugins