fluentd windows_log crash "undefined method `chop!' for nil:NilClass"
philipsabri opened this issue · 9 comments
Describe the bug
When using im using parse_description true
the bug occurs after a while, then it will occurs everytime I load the same storage path file. When putting parse_description false
everything works fine, but I really need that parse_description to be true.
Running the same config on another computer works fine.
Environment
- Fluentd 1.7.4
- Operating system: Windows Server 2019 17763
Configuration
<source>
@type windows_eventlog2
@id windows_eventlog2
channels security
read_interval 2
tag winevt.raw
render_as_xml true
rate_limit 200
parse_description true
<storage>
@type local
persistent true
path c:/opt/tmp/storage.json
</storage>
<parse>
@type winevt_xml
</parse>
</source>
Error Log
2020-01-22 13:31:03 +0100 [error]: #0 [windows_eventlog2] Unexpected error raised. Stopping the timer. title=:in_windows_eventlog_security error_class=NoMethodError error="undefined method `chop!' for nil:NilClass"
2020-01-22 13:31:03.294861000 +0100 fluent.error: {"title":"in_windows_eventlog_security","error":"#<NoMethodError: undefined method `chop!' for nil:NilClass>","message":"[windows_eventlog2] Unexpected error raised. Stopping the timer. title=:in_windows_eventlog_security error_class=NoMethodError error=\"undefined method `chop!' for nil:NilClass\""}
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:212:in `block (2 levels) in parse_desc'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:206:in `each'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:206:in `block in parse_desc'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:204:in `each'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:204:in `parse_desc'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:142:in `block (2 levels) in on_notify_xml'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-parser-winevt_xml-0.2.0/lib/fluent/plugin/parser_winevt_xml.rb:35:in `parse'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:123:in `block in on_notify_xml'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:122:in `each'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:122:in `on_notify_xml'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.4.3/lib/fluent/plugin/in_windows_eventlog2.rb:106:in `block (2 levels) in start'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/timer.rb:80:in `on_timer'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run_once'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2020-01-22 13:31:03 +0100 [error]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2020-01-22 13:31:03 +0100 [error]: #0 [windows_eventlog2] Timer detached. title=:in_windows_eventlog_security
2020-01-22 13:31:03.310476000 +0100 fluent.error: {"title":"in_windows_eventlog_security","message":"[windows_eventlog2] Timer detached. title=:in_windows_eventlog_security"}
Additional context
Could you share us an example evtx file which causes NoMethod error?
Could you share us an example evtx file which causes NoMethod error?
I cant do that, but the EventID is 6416 and Task Category is Plug and Play Events. Seemse to be about printer queues, print to pdf and so on. Some of the logdata has { } in them, not sure if that causes the problem.
Also updated the plugin to 0.4.4, but still the same
Im no ruby pro but I used the code from c7ae0d9 and put it in the windows-eventlog2 and its working! I would commit something but it would probably be bad code as I dont really know ruby, but I think its an easy fix for you!
@flurreN Could you share your code change with diff format (diff -urpN oldfile newfile)?
@cosmo0920 After some more digging we found out that on the "Vendor IDs:" Key it all gets messed up. Printed Keys + R just to see how it looked, and the last 3 rows doesnt seemse to have any keys
https://www.ultimatewindowssecurity.com/securitylog/encyclopedia/event.aspx?eventid=6416
Here is how it would look like in eventviewer
My first "fix" was just to add another rescue to skip these logs
Line: 152
rescue Winevt::EventLog::Query::Error => e
log.warn "Invalid Hash data", error: e
log.warn_backtrace
+ rescue => e
+ log.warn "Invalig Log", error: e
end
sorry dont know "diff format (diff -urpN oldfile newfile)" ??
Then I started to try to make it switch out the broken log description, but I noticed some new stuff I gotta change so that will have to wait for monday.
sorry dont know "diff format (diff -urpN oldfile newfile)" ??
This is your using format where creating with diff command (git diff is also OK for me).
Then I started to try to make it switch out the broken log description, but I noticed some new stuff I gotta change so that will have to wait for monday.
Sure. I'll wait for your new report.
I'd checking with Event which is eventID 6416 (e.g. http://eventopedia.cloudapp.net/EventDetails.aspx?id=17ef124e-eb89-4c01-9ba2-d761e06b2b68), but I got no error....
I've sent a PR to confirm EventID 6416's description format parsing: #37
In that PR, I introduced a plain text file to use testcase for eventID 6416 event.
Could you replace the plain text file contents with your problematic eventlog and try to execute tests with bundle exec rake test
, @flurreN ?
I did not manage to run the tests, but I managed to short down the fix to just a one liner. + your additional code in that pull request which fixed some additional problems.
Hope this is good enough!