Custom Application Eventlog not picked up by winlogbeat

Paul_Cadd · February 1, 2018, 10:42pm

Hi,

Wonder if some one could assist with problem I have

Background:
We have logstash 5.4.1 installed on a three node cluster and 80 clients, servers and workstations. All workstations are configured for winlogbeat to pick up the application logs.

It's very locked down desktop. I have had to create an icon on the users desktop for when a bespoke application appears to hang.

The user uses this icon which points to a batch script (Poweshell disabled, I know old technology) which terminates the application and writes a custom entry into the Windows Application Eventlog.

I have set the entry as a level 2 (Error) one, Custom entries must have EventID's of between 900 and 1000... I have chose 910 as that one is free from looking at the other events.

Now the problem:
The script writes to the Evenlog I can see it... I can close the application a number of times via the script and see the entries in the Application Eventlog. However the entry DOES NOT get picked up by winlogbeat. All other entries in the eventlog are picked up.

I have looked in the winlogbeat.log and searched for the entry in the logs folder.. it's not in there.
I have looked at the logstash input, filter and output to see if there's anything being dropped but nothing there.. The fact that it's not even getting to the local log file is concerning me so I am focusing there .

Does anyone have any ideas please?

Many Thanks Paul

andrewkroh · February 1, 2018, 11:13pm

What OS version? How are you writing the event to log? Can you share the Winlogbeat config that you are using?

I recommend running a simple test with the following config. It will read only event ID 910 from Application and write it to a local file instead of LS and enable debug logging.

Stop the Winlogbeat service.
Write this config file to disk as given below.
Run Winlogbeat from the CLI with .\winlogbeat.exe -c winlogbeat-test.yml.
After letting it run for a bit you can stop it.
Check the .\test\winlogbeat-event.json file and the .\test\winlogbeat.log.

# File: C:\Program Files\Winlogbeat\winlogbeat-test.yml

test_dir: '.\test'

winlogbeat.registry_file: '${test_dir}\winlogbeat.yml'

winlogbeat.event_logs:
- name: Application
  event_id: 910
  include_xml: true

output.file:
  path: '${test_dir}'
  filename: winlogbeat-events.json

logging.level: debug
logging.selectors: ["winlogbeat", "eventlog", "eventlog_detail"]
logging.files:
  path: '${test_dir}'
  name: winlogbeat.log

Paul_Cadd · February 2, 2018, 12:45am

HI Andrew.. Thanks for the response. The OS is Windows 7 64bit Pro.

I am using a DOS command behind the shortcut:

IF %ERRORLEVEL% EQU 0 (EVENTCREATE /T ERROR /ID 910 /L APPLICATION /SO Daviz3DDirector.exe /D "Weather Presenter Process was Terminated")

Here is the winlogbeat.yml:

winlogbeat.event_logs:
  - name: Application
    ignore_older: 72h
  - name: System
    ignore_older: 72h
    level: error, critical

#processors:
#  - drop_fields:
#      fields: [Component]

output.logstash:
  # The Logstash hosts
  hosts: ["10.55.209.42:3516","10.94.72.140:3516"]

  # Optional SSL. By default is off.
  # List of root certificates for HTTPS server verifications
  ssl.certificate_authorities: ["C:\\Program Files\\winlogbeat\\cert.crt"]

  # Certificate for SSL client authentication
  #ssl.certificate: "/etc/pki/client/cert.pem"

  # Client Certificate Key
  #ssl.key: "/etc/pki/client/cert.key"

#logging.level: debug

I'll give the script a try and get back to you...

Thanks - Paul

Paul_Cadd · February 2, 2018, 1:08am

Okay I copied the code to winlogbeat-test.yml, stopped the winlogbeat service and started the app from CLI with

winlogbeat.exe -c winlogbeat-test.yml

I got an error message:

C:\Program Files\winlogbeat>winlogbeat.exe -c winlogbeat-test.yml
Exiting: Error reading configuration file. 1 error: Invalid top-level key 'test_
dir' found. Valid keys are bulk_queue_size, fields, fields_under_root, geoip, lo
gging, max_procs, name, output, path, processors, queue_size, refresh_topology_f
req, tags, topology_expire, winlogbeat accessing config

Although it created the test directory and put a log file in there but no .json file.

Any ideas?

Thanks - Paul

andrewkroh · February 2, 2018, 1:20am

You must be on an old version of Winlogbeat. It can be written without the test_dir variable.

# File: C:\Program Files\Winlogbeat\winlogbeat-test.yml
winlogbeat.registry_file: '.\test\winlogbeat.yml'

winlogbeat.event_logs:
- name: Application
  event_id: 910
  include_xml: true

output.file:
  path: '.\test'
  filename: winlogbeat-events.json

logging.level: debug
logging.selectors: ["winlogbeat", "eventlog", "eventlog_detail"]
logging.files:
  path: '.\test'
  name: winlogbeat.log

Paul_Cadd · February 2, 2018, 1:00pm

Hi Andrew,

I ran it as requested and I can see the event_id in both the JSON and winlogbeat.log file... see attached...

So if winlogbeat picks it up in debug mode why doesn't it pick it up in 'normal' or 'standard' mode? Let me know if you need anymore info or the files complete.

First part of winlogbeat.JSON

{"@timestamp":"2018-02-02T00:58:29.000Z","beat":{"hostname":"F1-D0N343695","name":"F1-D0N343695","version":"5.2.2"},"computer_name":"F1-D0N343695.national.core.bbc.co.uk","event_data":{"param1":"Weather Presenter Process was Terminated"},"event_id":910,"keywords":["Classic"],"level":"Error","log_name":"Application","message":"Weather Presenter Process was Terminated","opcode":"Info","record_number":"7331656","source_name":"Daviz3DDirector.exe","type":"wineventlog","user":{"domain":"NATIONAL","identifier":"S-1-5-21-73586283-854245398-682003330-932526","name":"tec-tp-pc","type":"User"},"xml":"\u003cEvent xmlns='http://schemas.microsoft.com/win/2004/08/events/event'\u003e\u003cSystem\u003e\u003cProvider Name='Daviz3DDirector.exe'/\u003e\u003cEventID Qualifiers='0'\u003e910\u003c/EventID\u003e\u003cLevel\u003e2\u003c/Level\u003e\u003cTask\u003e0\u003c/Task\u003e\u003cKeywords\u003e0x80000000000000\u003c/Keywords\u003e\u003cTimeCreated SystemTime='2018-02-02T00:58:29.000000000Z'/\u003e\u003cEventRecordID\u003e7331656\u003c/EventRecordID\u003e\u003cChannel\u003eApplication\u003c/Channel\u003e\u003cComputer\u003eF1-D0N343695.national.core.bbc.co.uk\u003c/Computer\u003e\u003cSecurity UserID='S-1-5-21-73586283-854245398-682003330-932526'/\u003e\u003c/System\u003e\u003cEventData\u003e\u003cData\u003eWeather Presenter Process was Terminated\u003c/Data\u003e\u003c/EventData\u003e\u003cRenderingInfo Culture='en-GB'\u003e\u003cMessage\u003eWeather Presenter Process was Terminated\u003c/Message\u003e\u003cLevel\u003eError\u003c/Level\u003e\u003cTask\u003e\u003c/Task\u003e\u003cOpcode\u003eInfo\u003c/Opcode\u003e\u003cChannel\u003e\u003c/Channel\u003e\u003cProvider\u003e\u003c/Provider\u003e\u003cKeywords\u003e\u003cKeyword\u003eClassic\u003c/Keyword\u003e\u003c/Keywords\u003e\u003c/RenderingInfo\u003e\u003c/Event\u003e\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\

First part winlogbeat.log

2018-02-02T07:39:50Z INFO Metrics logging every 30s
2018-02-02T07:39:50Z INFO Setup Beat: winlogbeat; Version: 5.2.2
2018-02-02T07:39:50Z INFO File output path set to: .\test
2018-02-02T07:39:50Z INFO File output base filename set to: winlogbeat-events.json
2018-02-02T07:39:50Z INFO Rotate every bytes set to: 10485760
2018-02-02T07:39:50Z INFO Number of files set to: 7
2018-02-02T07:39:50Z INFO Activated file as output plugin.
2018-02-02T07:39:50Z INFO Publisher name: F1-D0N343695
2018-02-02T07:39:50Z INFO Flush Interval set to: -1s
2018-02-02T07:39:50Z INFO Max Bulk Size set to: -1
2018-02-02T07:39:50Z INFO State will be read from and persisted to C:\Program Files\winlogbeat\data\test\winlogbeat.yml
2018-02-02T07:39:50Z DBG  Using highest priority API, wineventlog, for event log Application
2018-02-02T07:39:50Z DBG  Initialized EventLog[Application]
2018-02-02T07:39:50Z INFO winlogbeat start running.
2018-02-02T07:39:50Z INFO Creating C:\Program Files\winlogbeat\data\test if it does not exist.
2018-02-02T07:39:50Z DBG  WinEventLog[Application] using subscription query=<QueryList>
  <Query Id="0">
    <Select Path="Application">*[System[EventID=910]]</Select>
  </Query>
</QueryList>
2018-02-02T07:39:50Z DBG  EventLog[Application] opened successfully
2018-02-02T07:39:50Z DBG  WinEventLog[Application] EventHandles returned 2 handles
2018-02-02T07:39:50Z DBG  messageFilesCache[Application] size=1
2018-02-02T07:39:50Z DBG  WinEventLog[Application] XML=<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'><System><Provider Name='Daviz3DDirector.exe'/><EventID Qualifiers='0'>910</EventID><Level>2</Level><Task>0</Task><Keywords>0x80000000000000</Keywords><TimeCreated SystemTime='2018-02-02T00:58:29.000000000Z'/><EventRecordID>7331656</EventRecordID><Channel>Application</Channel><Computer>F1-D0N343695.national.core.bbc.co.uk</Computer><Security UserID='S-1-5-21-73586283-854245398-682003330-932526'/></System><EventData><Data>Weather Presenter Process was Terminated</Data></EventData><RenderingInfo Culture='en-GB'><Message>Weather Presenter Process was Terminated</Message><Level>Error</Level><Task></Task><Opcode>Info</Opcode><Channel></Channel><Provider></Provider><Keywords><Keyword>Classic</Keyword></Keywords></RenderingInfo></Event>

Any idea?

Many Thanks

Paul

andrewkroh · February 2, 2018, 5:01pm

Enabling debug shouldn't change anything. I think you should investigate downstream next. Can you please share the Logstash configuration you are using.

Try running the same test again but with the Logstash output enabled. In Logstash comment out any filters you are using and add this so that the events are also written to stdout.

output { 
  stdout { 
    codec  => rubydebug {
      metadata => true
    }
  }
}

Before running the Winlogbeat test again completely delete the .\test directory.

# File: C:\Program Files\Winlogbeat\winlogbeat-test.yml for Winlogbeat 5.x
winlogbeat.registry_file: '.\test\winlogbeat.yml'

winlogbeat.event_logs:
- name: Application
  event_id: 910
  include_xml: true

output.file:
  path: '.\test'
  filename: winlogbeat-events.json

output.logstash:
  hosts: ["10.55.209.42:3516"] # Choose one server for testing.
  ssl.certificate_authorities: ["C:\\Program Files\\winlogbeat\\cert.crt"]

logging.level: debug
logging.selectors: ["winlogbeat", "eventlog", "eventlog_detail"]
logging.files:
  path: '.\test'
  name: winlogbeat.log

Paul_Cadd · February 5, 2018, 3:11pm

Hi Andrew,

I will give that a try. In the meantime... here are the logstash config files. input, filter and output

Many Thanks

Paul

input {

  beats {
    port => "3516"
    ssl => true
    ssl_verify_mode => "none"
    ssl_certificate => "/etc/logstash/logstash-forwarder.crt"
    ssl_key => "/etc/logstash/logstash-forwarder.key"
  }

#  tcp {
#    codec => json_lines { charset => CP1252 }
#    port => "3515"
#    type => "nxlogs"
#    ssl_cacert => "/etc/pki/tls/certs/ca.crt"
#    ssl_cert => "/etc/pki/tls/certs/nx.crt"
#    ssl_key => "/etc/pki/tls/private/nxlog.key"
#    ssl_enable => true
#    ssl_verify => false
#  }

}



filter {

  if [type] == "syslog" {

    if "/etc/zabbix/zabbix_agentd.d/scripts" in [message] {
      drop {}
    }
    if "auid=4294967295" in [message] {
      drop {}
    }

    grok {
      match => { "message" => "%{SYSLOGTIMESTAMP:syslog_timestamp} %{SYSLOGHOST:syslog_hostname} %{DATA:syslog_program}(?:\[%{POSINT:syslog_pid}\])?:%{GREEDYDATA:syslog_message}" }
    }
      syslog_pri { }
      date {
        match => [ "syslog_timestamp", "MMM d HH:mm:ss", "MMM dd HH:mm:ss"  ]
      }
    if [syslog_program] == "lsyncd" and [syslog_severity] == "notice" {
      drop {}
    }

    if [syslog_program] == "csync2" and [syslog_severity] == "notice" {
      drop {}
    }

  }

  if [type] == "wineventlog" {

    #if ( [beat.hostname] !~ /F1-D0N343/ ){
    #  drop {}
    #}

    json {
      source => "message"
    }

    mutate {
      replace => [ "message", "%{Message}" ]
    }
    mutate {
      remove_field => [ "Message" ]
    }
    mutate {
      remove_field => [ "event_data" ]
    }

    ### grok parsers
    if ( [message] =~ /Playlist\ preparation\ finished\ after/ ){
      grok {
        match => { "message" => "%{NUMBER:PlaylistPrepTime}" }
      }
      mutate {
        convert => { "PlaylistPrepTime" => "float" }
      }
    }

    if ( [message] =~ /Content\ preparation\ finished\ after/ ){
      grok {
        match => { "message" => "%{NUMBER:ContentPrepTime}" }
      }
      mutate {
        convert => { "ContentPrepTime" => "float" }
      }
    }

    if ( [message] =~ /Application\ startup\ finished\ after/ ){
      grok {
        match => { "message" => "%{NUMBER:AppStartupTime}" }
      }
      mutate {
        convert => { "AppStartupTime" => "float" }
      }
    }

    if ( [message] =~ /Retrieved\ user\ details\ from\ Active\ Directory/ ){
      grok {
        match => { "message" => "%{NUMBER:ADResponsTime}" }
      }
      mutate {
        convert => { "ADResponsTime" => "float" }
      }
    }

    if ( [message] =~ /Loading\ playlist\ document/ ){
      grok {
        match => { "message" => "Loading playlist document '%{DATA:PlaylistDoc}'..." }
      }
    }

    if ( [message] =~ /Resolved\ path\ '\$\(DesignModels\)'\ as/ ){
      grok {
        match => { "message" => "Resolved path '\$\(DesignModels\)' as '%{DATA:DesignModelsPath}'.$" }
      }
    }

    if ( [message] =~ /Resolved\ path\ '\$\(VfsConfig\)'\ as/ ){
      grok {
        match => { "message" => "Resolved path '\$\(VfsConfig\)' as '%{DATA:VfsConfigPath}'." }
      }
    }

    if ( [message] =~ /Welcome\ to\ WeatherPresenter\ version/ ){
      grok {
        match => {  "message" => "Welcome to WeatherPresenter version %{DATA:WPVersion}$" }
      }
    }


    #if [level] != "Error" and [source_name] == "WeatherSuite" {
    #  drop {}
    #}

    #mutate {
    #  remove_field => [ "message" ]
    #}

  }

  if [type] == "nxlogs" {
    json {
      source => "message"
    }
    if [SourceModuleName] == "eventlog" {
      mutate {
        replace => [ "message", "%{Message}" ]
      }
      mutate {
        remove_field => [ "Message" ]
      }
      json {
        source => "message"
      }
      if "_jsonparsefailure" not in [tags] {
        mutate {
          remove_field => [ "message" ]
        }
      }
    }
  }

}




output {
  elasticsearch {
    hosts => ["10.55.209.41:9200","10.94.242.141:9200"]
  }

  tcp {
    mode => "client"
            host => "10.55.209.48"
            port => "514"
  }
}

andrewkroh · February 5, 2018, 3:51pm

Thanks for sharing your config. Do the test without filters as I recommended, but here are some notes from looking at this config.

    json {
      source => "message"
    }

    mutate {
      replace => [ "message", "%{Message}" ]
    }
    mutate {
      remove_field => [ "Message" ]
    }

Those three filters appear to be unnecessary (unless you have a message field that is actually JSON).

FYI Your output config doesn't match up with what we recommend. See https://www.elastic.co/guide/en/beats/libbeat/6.1/logstash-installation.html#logstash-setup and Load the template manually. Using a separate index for the Winlogbeat data will help ensure there are no mapping conflicts with data from other sources.

You'd probably want to do something like this so that only data from Beats follows our recommended output config.

output {
  if [beat] {
    elasticsearch {
      hosts => ["10.55.209.41:9200", "10.94.242.141:9200"]
      manage_template => false
      index => "%{[@metadata][beat]}-%{[@metadata][version]}-%{+YYYY.MM.dd}" 
      document_type => "%{[@metadata][type]}" 
    }
  } else {
    elasticsearch {
      hosts => ["10.55.209.41:9200","10.94.242.141:9200"]
    }
  }

  tcp {
    mode => "client"
            host => "10.55.209.48"
            port => "514"
  }
}

system · March 5, 2018, 3:51pm

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