fluentd windows_log crash "undefined method `chop!' for nil:NilClass"

Question

fluentd windows_log crash "undefined method `chop!' for nil:NilClass"

philipsabri opened this issue 5 years ago · 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

Answer 1 · 2020-01-22T15:57:24.000Z

Could you share us an example evtx file which causes NoMethod error?

Answer 2 · 2020-01-24T11:28:34.000Z

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

Answer 3 · 2020-01-24T12:43:56.000Z

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!

Answer 4 · 2020-01-24T15:07:19.000Z

@flurreN Could you share your code change with diff format (diff -urpN oldfile newfile)?

Answer 5 · 2020-01-25T17:29:28.000Z

@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.

Answer 6 · 2020-01-27T02:52:06.000Z

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.

Answer 7 · 2020-01-27T08:26:45.000Z

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....

Answer 8 · 2020-01-27T09:23:02.000Z

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 ?

Answer 9 · 2020-01-27T12:57:43.000Z

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!