Possible race condition causing Elasticsearch output plugin to overwrite supplied index with rollover alias

andreastoom · August 2, 2022, 5:53am

Hi,

Since migrating to using data streams we have started to see that a subset of our data all of a sudden are being written to an index called "logstash" instead of the data stream. After a bit of digging around it seems to be related to the ILM functionality of the Elasticsearch output plugin. We have explicitly disabled ILM on all of our index outputs and if I understand the code of the plugin correctly ILM will always be disabled for data stream configurations.

The only explanation I can come up with is that the internal state of the plugin somehow gets mixed up during pipeline startup/reload. We have about 15 pipelines and each pipeline consists of 1 kafka input and 2 elasticsearch outputs where the different elasticsearch outputs are used based on runtime conditionals.

input {

    kafka {
        bootstrap_servers => "kafka-elk-test-1.company.net:9093,kafka-elk-test-2.company.net:9093,kafka-elk-test-3.company.net:9093"
        topics => "metrics.java.apps"
        group_id => "logstash"
        client_id => "logstash-metrics.java.apps"
        codec => "json"
        ssl_keystore_location => "/opt/company/logstash-test/config/cert/kafka-keystore.p12"
        ssl_keystore_password => "xxx"
        ssl_keystore_type => "PKCS12"
        ssl_truststore_location => "/opt/company/logstash-test/config/cert/kafka-truststore.jks"
        ssl_truststore_password => "xxx"
        ssl_truststore_type => "JKS"
        ssl_endpoint_identification_algorithm => ""
        security_protocol => "SSL"
        session_timeout_ms => "30000"
    }

}

filter {

   ...

}

output {

    if [@metadata][version] == "7.17.0" {
        elasticsearch {
            id => "output_elasticsearch_data_stream"
            hosts => ["vfin7018.company.net:9200","vfin7019.company.net:9200","vfin7020.company.net:9200"]
            data_stream => "true"
            data_stream_type => "metrics"
            data_stream_dataset => "all"
            data_stream_namespace => "7.17.0"
        }
    }
    else {
        elasticsearch {
            id => "output_elasticsearch_default"
            hosts => ["vfin7018.company.net:9200","vfin7019.company.net:9200","vfin7020.company.net:9200"]
            index => "metrics-java-%{[@metadata][version]}-%{+YYYY.MM.dd}"
            ilm_enabled => "false"
        }
    }

}

Below is a small subset from our startup logs during startup (the full log exceeded the max character limit for this post)

[2022-08-02T06:14:29,106][INFO ][logstash.runner          ] Log4j configuration path used is: /opt/company/logstash-test/config/log4j2.properties
[2022-08-02T06:14:29,124][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"7.17.0", "jruby.version"=>"jruby 9.2.20.1 (2.5.8) 2021-11-30 2a2962fbd1 OpenJDK 64-Bit Server VM 17.0.2+8-LTS on 17.0.2+8-LTS +indy +jit [linux-x86_64]"}
[2022-08-02T06:14:29,128][INFO ][logstash.runner          ] JVM bootstrap flags: [-Xms512m, -Xmx2g, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djruby.compile.invokedynamic=true, -Djruby.jit.threshold=0, -Djruby.regexp.interruptible=true, -XX:+HeapDumpOnOutOfMemoryError, -Djava.security.egd=file:/dev/urandom, -Dlog4j2.isThreadContextMapInheritable=true, --add-opens=java.base/java.security=ALL-UNNAMED, --add-opens=java.base/java.io=ALL-UNNAMED, --add-opens=java.base/java.nio.channels=ALL-UNNAMED, --add-opens=java.base/sun.nio.ch=ALL-UNNAMED, --add-opens=java.management/sun.management=ALL-UNNAMED]
[2022-08-02T06:14:33,916][INFO ][logstash.monitoring.internalpipelinesource] Monitoring License OK
[2022-08-02T06:14:33,918][INFO ][logstash.monitoring.internalpipelinesource] Validated license for monitoring. Enabling monitoring pipeline.
[2022-08-02T06:14:34,135][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600, :ssl_enabled=>false}
[2022-08-02T06:14:42,965][INFO ][org.reflections.Reflections] Reflections took 517 ms to scan 1 urls, producing 119 keys and 417 values
[2022-08-02T06:14:47,611][INFO ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearchMonitoring", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:47,678][INFO ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:47,717][WARN ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:47,728][INFO ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:47,728][WARN ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:48,108][WARN ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:48,232][WARN ][logstash.outputs.elasticsearchmonitoring][.monitoring-logstash] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
2022-08-02T06:14:48,273][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:48,292][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:48,325][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:48,627][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:48,628][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:48,785][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:48,841][INFO ][logstash.outputs.elasticsearch][metrics_java_system] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:48,845][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:48,855][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:48,865][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:48,873][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:48,876][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:48,882][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:48,883][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:48,899][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:48,921][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:48,922][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:48,923][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:48,936][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:48,962][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:48,970][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:48,971][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:48,979][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:48,982][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,001][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,002][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,008][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,014][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,045][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,047][INFO ][logstash.outputs.elasticsearch][metrics_java_http] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,055][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,063][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,074][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,080][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,105][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,105][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,111][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,120][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,133][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,134][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,133][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,155][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,169][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,169][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,265][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,270][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,275][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,278][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,290][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,291][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,291][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,294][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,296][INFO ][logstash.outputs.elasticsearch][metrics_java_system] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,302][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,304][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,304][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,311][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,319][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,319][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,319][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,325][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,325][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,343][WARN ][logstash.outputs.elasticsearch][metrics_java_apps] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,391][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,393][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,426][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,426][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,426][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,433][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,437][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,442][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,444][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,470][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,482][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,482][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,530][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,542][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,543][INFO ][logstash.outputs.elasticsearch][metrics_java_http] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,548][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,549][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Config is not compliant with data streams. `data_stream => auto` resolved to `false`
[2022-08-02T06:14:49,552][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,554][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,549][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//host1.company.net:9200", "//host2.company.net:9200", "//host3.company.net:9200"]}
[2022-08-02T06:14:49,573][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,577][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,577][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://host1.company.net:9200/, http://host2.company.net:9200/, http://host3.company.net:9200/]}}
[2022-08-02T06:14:49,585][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,585][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,623][INFO ][logstash.outputs.elasticsearch][metrics_java_apps] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,640][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host1.company.net:9200/"}
[2022-08-02T06:14:49,647][WARN ][logstash.outputs.elasticsearch][metrics_java_system] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,647][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Elasticsearch version determined (7.17.0) {:es_version=>7}
[2022-08-02T06:14:49,650][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>7}
[2022-08-02T06:14:49,656][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,665][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,694][INFO ][logstash.javapipeline    ][metrics_java_apps] Starting pipeline {:pipeline_id=>"metrics_java_apps", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_java_apps.conf"], :thread=>"#<Thread:0x3cbefd7d run>"}
[2022-08-02T06:14:49,700][INFO ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,723][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Overwriting supplied index metrics-all-7.17.0 with rollover alias logstash
[2022-08-02T06:14:49,738][INFO ][logstash.javapipeline    ][metrics_java_thirdsparty] Starting pipeline {:pipeline_id=>"metrics_java_thirdsparty", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_java_thirdparty.conf"], :thread=>"#<Thread:0x492b21b5 run>"}
[2022-08-02T06:14:49,783][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host2.company.net:9200/"}
[2022-08-02T06:14:49,794][WARN ][logstash.outputs.elasticsearch][metrics_windows_sql] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,910][INFO ][logstash.outputs.elasticsearch][metrics_java_system] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:49,915][WARN ][logstash.outputs.elasticsearch][metrics_windows_system] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,943][WARN ][logstash.outputs.elasticsearch][metrics_java_http] Restored connection to ES instance {:url=>"http://host3.company.net:9200/"}
[2022-08-02T06:14:49,932][INFO ][logstash.javapipeline    ][metrics_java_system] Starting pipeline {:pipeline_id=>"metrics_java_system", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_java_system.conf"], :thread=>"#<Thread:0x6ede9fde run>"}
[2022-08-02T06:14:50,070][INFO ][logstash.javapipeline    ][metrics_windows_sql] Starting pipeline {:pipeline_id=>"metrics_windows_sql", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_windows_sql.conf"], :thread=>"#<Thread:0x2cbc7379 run>"}
[2022-08-02T06:14:50,077][INFO ][logstash.outputs.elasticsearch][metrics_windows_sql] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:50,203][INFO ][logstash.javapipeline    ][metrics_java_http] Starting pipeline {:pipeline_id=>"metrics_java_http", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_java_http.conf"], :thread=>"#<Thread:0x2c64054 run>"}
[2022-08-02T06:14:50,240][INFO ][logstash.outputs.elasticsearch][metrics_java_http] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:50,352][INFO ][logstash.outputs.elasticsearch][metrics_windows_system] Using a default mapping template {:es_version=>7, :ecs_compatibility=>:disabled}
[2022-08-02T06:14:50,506][INFO ][logstash.javapipeline    ][metrics_windows_system] Starting pipeline {:pipeline_id=>"metrics_windows_system", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>1000, "pipeline.sources"=>["/opt/company/logstash-test/config/pipelines/metrics_windows_system.conf"], :thread=>"#<Thread:0x423611ec run>"}
[2022-08-02T06:14:55,607][INFO ][logstash.javapipeline    ][metrics_java_apps] Pipeline Java execution initialization time {"seconds"=>5.91}
[2022-08-02T06:14:55,614][INFO ][logstash.javapipeline    ][metrics_java_thirdsparty] Pipeline Java execution initialization time {"seconds"=>5.87}
[2022-08-02T06:14:55,825][INFO ][logstash.javapipeline    ][metrics_java_system] Pipeline Java execution initialization time {"seconds"=>5.88}
[2022-08-02T06:14:55,836][INFO ][logstash.javapipeline    ][metrics_windows_sql] Pipeline Java execution initialization time {"seconds"=>5.77}
[2022-08-02T06:14:55,844][INFO ][logstash.javapipeline    ][metrics_java_http] Pipeline Java execution initialization time {"seconds"=>5.64}
[2022-08-02T06:14:55,939][INFO ][logstash.javapipeline    ][metrics_windows_system] Pipeline Java execution initialization time {"seconds"=>5.43}
[2022-08-02T06:14:56,958][INFO ][logstash.javapipeline    ][metrics_java_apps] Pipeline started {"pipeline.id"=>"metrics_java_apps"}
[2022-08-02T06:14:56,958][INFO ][logstash.javapipeline    ][metrics_java_thirdsparty] Pipeline started {"pipeline.id"=>"metrics_java_thirdsparty"}
[2022-08-02T06:14:56,959][INFO ][logstash.javapipeline    ][metrics_windows_sql] Pipeline started {"pipeline.id"=>"metrics_windows_sql"}
[2022-08-02T06:14:56,992][INFO ][logstash.javapipeline    ][metrics_windows_system] Pipeline started {"pipeline.id"=>"metrics_windows_system"}
[2022-08-02T06:14:57,086][INFO ][logstash.javapipeline    ][metrics_java_system] Pipeline started {"pipeline.id"=>"metrics_java_system"}
[2022-08-02T06:14:57,117][INFO ][logstash.javapipeline    ][metrics_java_http] Pipeline started {"pipeline.id"=>"metrics_java_http"}

Some highlights

[2022-08-02T06:14:49,723][WARN ][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Overwriting supplied index metrics-all-7.17.0 with rollover alias logstash - This should not be triggered since we do not have ILM configured
Config is not compliant with data streams. data_stream => auto resolved to false - This is because one of our two Elasticsearch output configurations do not use data streams

As a temporary workaround we have disabled the following line in the Elasticsearch output plugin

github.com

logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch.rb#L319


      
              @logger.warn("Elasticsearch Output configured with `ecs_compatibility => v8`, which resolved to an UNRELEASED preview of version 8.0.0 of the Elastic Common Schema. " +
                           "Once ECS v8 and an updated release of this plugin are publicly available, you will need to update this plugin to resolve this warning.")
            end
          end
          
          
# @override post-register when ES connection established
          def finish_register
            assert_es_version_supports_data_streams if data_stream_config?
            discover_cluster_uuid
            install_template
            setup_ilm if ilm_in_use?
            super
          end
          
          
# @override to handle proxy => '' as if none was set
          def config_init(params)
            proxy = params['proxy']
            if proxy.is_a?(String)
              # environment variables references aren't yet resolved
              proxy = deep_replace(proxy)
              if proxy.empty?

Does anyone have any input on this or should I go ahead and open a GitHub issue ?

Best regards,
Andreas

Badger · August 2, 2022, 4:57pm

No, it is not. For your first output the index name will be metrics-all-7.17.0 (type-dataset-namespace) which is exactly the index name that is getting overwritten.

Enable --log.level debug, then the code will log why it thinks it cannot use data streams. (Please let us know the result.)

andreastoom · August 3, 2022, 5:18am

Debug logging reveal the reason for data_stream => auto resolved to false

[2022-08-03T06:03:40,586][DEBUG][logstash.outputs.elasticsearch][metrics_java_thirdsparty] Not eligible for data streams because ecs_compatibility is not enabled. Elasticsearch data streams require that events adhere to the Elastic Common Schema. While `ecs_compatibility` can be set for this individual Elasticsearch output plugin, doing so will not fix schema conflicts caused by upstream plugins in your pipeline. To avoid mapping conflicts, you will need to use ECS-compatible field names and datatypes throughout your pipeline. Many plugins support an `ecs_compatibility` mode, and the `pipeline.ecs_compatibility` setting can be used to opt-in for all plugins in a pipeline.

I have tried to do an analysis to come up with an explanation/deeper understanding - but perhaps I am too novice to see the whole picuture, anyways here is my take

From the log is not easy to determine for which of the two elasticsearch output instances the different log messages belongs since the plugin id is not included in the log statement. But from my understanding of the plugin code/call hierarchy the output is generated by the non data-stream configured elasticsearch output instance (see https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch/data_stream_support.rb#L89 and https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch/data_stream_support.rb#L154. When I add an explicit data_stream => "false" to that elasticserach output configuration the log messages goes away.

The connection between data-stream configuration and ILM bootstraping is a bit tricky to follow in the code but from my understanding the data-stream configuration will override the @index instance variable (and freeze) it (https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch.rb#L299) which will cause ilm_alias_set? to return false later on in the initialization (https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch/ilm.rb#L34).

So given our configuration it should not be possible to be in a state where the Elasticsearch output plugin should override the @index instance variable based on ILM configuration. And it should also not be technically possible since the variable has been frozen ? Given that we have multiple pipelines and multiple outputs in each pipeline and where some of the initialization code is running in a separate thread (see https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/main/lib/logstash/outputs/elasticsearch.rb#L281) perhaps a race condition could be the root cause ?

system · August 31, 2022, 5:19am

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

Topic		Replies	Views
Logstash sometimes ignoring datastream configuration in elasticsearch output Logstash	2	671	December 23, 2022
Logstash - Elastichsearch Output - ILM Logstash	1	230	March 9, 2021
Output Elasticsearch index name error Logstash	4	307	June 1, 2021
[Logstash-ilm-elasticsearch-output] ERROR - ilm settings in Logstash Elasticsearch output filter Logstash ilm-index-lifecycle-management	7	930	November 3, 2020
Problem with ILM Elasticsearch ilm-index-lifecycle-management	5	361	December 29, 2020

Possible race condition causing Elasticsearch output plugin to overwrite supplied index with rollover alias

Related Topics