Duplicate Winlogbeat Events - (Logstash publishing events twice)


(Alexey Khudyakov) #1

Dear Community,

I'm evaluating Winlogbeat-5.0.0 alpha 1 and noticed that all events shipped to elasticsearch were duplicated. This issue appears on all events shipped from my Windows servers.
I don't know if it bug of winlogbeat or elasticsearch, so please help me to find out the cause of the issue.

This is my winlogbeat.yml

winlogbeat:
  registry_file: C:/ProgramData/winlogbeat/.winlogbeat.yml
  event_logs:
    - name: Security
      ignore_older: 48h
      event_id: 4720,1102,4625,4725,4740
output:
  logstash:
    hosts: ["xxxx.xxx:9998"]
    tls:
      certificate_authorities: 
        - "c://Program Files//ELK//logstash-forwarder.crt"

(Andrew Kroh) #2

Winlogbeat and Filebeat have at-least-once delivery semantics. Delivery of duplicates to Logstash should only occur when there are connection problems to Logstash. For example, if the connection to Logstash is severed while sending a batch of events, the whole batch must be resent even though it is possible that part of the batch was delivered. If the Beat does not receive the acknowledgement from Logstash it must resend the whole batch. This enhancement request to add a UUID to events will help prevent duplicates in this scenario.

I recommend checking all of your logs for issues (WInlogbeat, Logstash, Elasticsearch).

Duplicates can also occur if you delete/modify the registry file used by Winlogbeat or run multiple instances on the same machine.

Could you attach (or post to pastebin) the output of the following query?

curl 'http://elasticsearch:9200/winlogbeat-*/_search?pretty' -d '
{
  "size": 0,
  "aggs": {
    "hosts": {
      "terms": {
        "field": "beat.hostname",
        "size": 10,
        "order": {
          "_count": "desc"
        }
      },
      "aggs": {
        "logs": {
          "terms": {
            "field": "log_name",
            "size": 0,
            "order": {
              "_count": "desc"
            }
          },
          "aggs": {
            "duplicate_record_numbers": {
              "terms": {
                "field": "record_number",
                "size": 0,
                "min_doc_count": 2,
                "order": {
                  "_count": "desc"
                }
              }
            }
          }
        }
      }
    }
  }
}'

(Alexey Khudyakov) #3

Hi Andrew,

Thank you for your answer.
In my case Filebeat is working normal without duplicates. The issue is only with Winlogbeat. I don't have multiple instances of winlogbeat on my servers.
I've just checked logs of Elasticsearch and Logstash and have not found any errors.

Output of the query is here I couldn't upload to pastebin because it is too large.

As you can see, all events shipped from the servers using winglobeat are duplicated. I tried to delete indexes winlogbeat-* but it didn't help.


(Andrew Kroh) #4

Please post the config file that you are using for Winlogbeat. Thanks


(Alexey Khudyakov) #5
# cat /etc/logstash/conf.d/logstash-winlogbeat.conf
input {
  beats {
    port => 9998
    ssl => true
    ssl_certificate => "/etc/pki/tls/certs/logstash-forwarder.crt"
    ssl_key => "/etc/pki/tls/private/logstash-forwarder.key"
  }
}

filter{
   if ([host] == "srv-fs-0") and ("ReadData" in [message] or "WriteAttributes" in [message] or ".tmp" in [message] or ":Zone.Identifier" in [message] or "Thumbs.db" in [message] or "~$" in [message] or ".partial" in [message] or "WRITE_DAC" in [message])
   {
      drop{}
   }
}

output {
   if [type] == "wineventlog"{
      elasticsearch {
         hosts => ["localhost:9200"]
         index => "winlogbeat-%{+YYYY.MM.dd}"
      }
   }
}

(Andrew Kroh) #6

That's a Logstash config... Post your winlogbeat.yml please.


(Alexey Khudyakov) #7

I posted the winlogbeat.yml in my first message :slight_smile:


(Andrew Kroh) #8

haha sorry, I guess I'm losing my mind.

I'm surprised that in the elasticsearch output that the log name is "security", but in your configuration it is "Security". I'm still not sure what's going on. Can you collect some debug logs from Winlogbeat? Let it run for a bit while it's producing duplicates then upload the logs, the config, and the registry file. And I'll take a look and see if there or any clues.

I think the interesting debug selectors (without producing too much data) would be "winlogbeat" , "eventlog", and "checkpoint". But if that doesn't produce any clues to the problem then we might need to try selectors: ["*"].

logging:
  to_files: true
  files:
    path: C:/ProgramData/winlogbeat/Logs
  level: debug
  selectors: [winlogbeat, eventlog, checkpoint]

(Alexey Khudyakov) #9

Done.

Please, find the winlogbeat.log here

The registry file contains this information:

update_time: 2016-05-06T13:29:19.2615248Z
event_logs:
- name: Security
  record_number: 1700879517
  timestamp: 2016-05-06T13:29:16.0739498Z

(Andrew Kroh) #10

That output looks normal. I think we need selectors: ["*"].

And it would be useful to see which events are duplicated during the test period so either run the query below and adjust the time window, or delete the daily index before the test and run the query without the filter.

POST winlogbeat-2016.05.06/_search?pretty
{
  "filter": {
    "range": {
      "timestamp": {
        "gt": "now-10m"
      }
    }
  },
  "size": 0,
  "aggs": {
    "hosts": {
      "terms": {
        "field": "beat.hostname",
        "size": 10,
        "order": {
          "_count": "desc"
        }
      },
      "aggs": {
        "logs": {
          "terms": {
            "field": "log_name",
            "size": 0,
            "order": {
              "_count": "desc"
            }
          },
          "aggs": {
            "duplicate_record_numbers": {
              "terms": {
                "field": "record_number",
                "size": 0,
                "min_doc_count": 2,
                "order": {
                  "_count": "desc"
                }
              }
            }
          }
        }
      }
    }
  }
}

(Andrew Kroh) #11

Another test you could perform would be to use the file output in Winlogbeat and see if you get duplicates.


(Alexey Khudyakov) #12

Andrew, it was a good idea to use the file output.
After the test I found duplicates in the file.
Please, find the response of POST query and part of the file output here


(Andrew Kroh) #13

All of the events in the output file are unique based on their record_numbers.

$ jq . file-output.json  | grep record_number | sort | wc -l
      11
$ jq . file-output.json  | grep record_number | sort | uniq | wc -l
      11

Is there more to your Logstash config than you posted? Are there more files in /etc/logstash/conf.d/? Could there be something else in your Logstash configuration that is causing the event to be posted to Elasticsearch twice? Do you have any other output blocks that are possibly missing an if conditional?

How about outputting the data coming into Logstash to a file then checking it for duplicates.

output {
  file {
    path => "/path/to/output.json"
  }
}

(Andrew Kroh) #14

If we make the assumption that Winlogbeat is not sending duplicates, then by adding a unique document ID in Logstash it should stop the duplicate events from appearing in Elasticsearch. If this stops the problem then it points to a problem in the Logstash config.

For example:

filter {
  uuid {
    target => "[@metadata][document_id]"
  }
}

output {
  elasticsearch {
    hosts => "localhost:9200"
    manage_template => false
    index => "%{[@metadata][beat]}-%{+YYYY.MM.dd}"
    document_type => "%{[@metadata][type]}"
    document_id => "%{[@metadata][document_id]}"
  }
}

(Alexey Khudyakov) #15

Hi Andrew,

Sorry for the late answer - I had a vacation.
I've changed my config as you suggested. It did not help.

After that I've tried to start logstash using the only winlogbeat config:
logstash -f /etc/logstash/conf.d/logstash-winlogbeat.conf
In that case all worked fine. There was not duplicated events.

You were right about over config files in /etc/logstash/conf.d/. I also have the filebeat.conf that contains this lines:

output {
   elasticsearch {
      hosts => ["localhost:9200"]
      sniffing => true
      manage_template => false
      index => "%{[@metadata][beat]}-%{+YYYY.MM.dd}"
      document_type => "%{[@metadata][type]}"
   }
}

And like as you suggested, the events were posted to logstash twice. I've just commented output section in the winlogbeat.conf and now all work perfectly!

Thank you very much for your help!


(Andrew Kroh) #16