Logstash 6.5.1 : undefined method `path' for nil:NilClass

gfigoni · November 29, 2018, 8:18am

I have an ELK stack installed on my workstation (windows 10).
I recently migrated my ELK stack from v6.3.2 to the latest v6.5.1.

On this local stack, I daily handle a fair amount of log files throw Logstash to Elastic.

I had no problem with Logstash 6.3.2, but using Logstash 6.5.1 generate this error repeatedly : the input file plugin crashes and reboot all the time during the process :

[2018-11-28T09:48:02,531][ERROR][logstash.pipeline        ] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:main
  Plugin: <LogStash::Inputs::File mode=>"read", path=>["D:/path/**/file*"], codec=><LogStash::Codecs::Multiline pattern=>"^%{LOGLEVEL}\\|", charset=>"Windows-1252", what=>"previous", id=>"9ecca431-85c4-4be7-bc85-b7a5802e1d55", max_lines=>1000000000, negate=>true, enable_metric=>true, multiline_tag=>"multiline", max_bytes=>10485760>, add_field=>{"type"=>"ate-bootstrap"}, file_sort_by=>"path", id=>"d004ada1a7083053ed9583a14313b887d99e0160fcaa208b6dae8adbe1ac3aad", sincedb_path=>"D:/path/sincedb", file_completed_action=>"log", file_completed_log_path=>"D:/path/conf.log", enable_metric=>true, stat_interval=>1.0, discover_interval=>15, sincedb_write_interval=>15.0, start_position=>"end", delimiter=>"\n", close_older=>3600.0, sincedb_clean_after=>1209600.0, file_chunk_size=>32768, file_chunk_count=>140737488355327, file_sort_direction=>"asc">
  Error: undefined method `path' for nil:NilClass
  Exception: NoMethodError
  Stack: C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/sincedb_value.rb:71:in `reading_completed'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/sincedb_collection.rb:165:in `reading_completed'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/handlers/read_file.rb:22:in `handle_specifically'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/handlers/base.rb:26:in `handle'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/processor.rb:35:in `read_file'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/processor.rb:102:in `block in process_active'
org/jruby/RubyArray.java:1734:in `each'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/processor.rb:86:in `process_active'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/read_mode/processor.rb:45:in `process_all_states'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/watch.rb:67:in `iterate_on_state'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/watch.rb:45:in `subscribe'
C:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/filewatch/observing_read.rb:12:in `subscribe'
c:/tools/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.6/lib/logstash/inputs/file.rb:339:in `run'
c:/tools/logstash/logstash-core/lib/logstash/pipeline.rb:409:in `inputworker'
c:/tools/logstash/logstash-core/lib/logstash/pipeline.rb:403:in `block in start_input'
[2018-11-28T09:48:03,562][INFO ][filewatch.observingread  ] QUIT - closing all files and shutting down.
[2018-11-28T09:48:03,562][INFO ][filewatch.observingread  ] START, creating Discoverer, Watch with file and sincedb collections

I adapted my Logstash conf to use the recent "read mode" feature.

Here is my 6.3.2 conf part for the input plugin :

    file {
		path => "D:/path/**/file.*"
		sincedb_path => "D:/path/sincedb"
		start_position => "beginning"
		ignore_older => 0
		close_older => 10
		
		codec => multiline {
			max_lines => 1000000000
			pattern => "^%{LOGLEVEL}\|"
			negate => true
			what => previous
			charset => "Windows-1252"
		}
	}

And the adaptation for v6.5.1 :

	file {
		path => "D:/path/**/file.*"
		sincedb_path => "D:/path/sincedb"
		mode => "read"
		file_completed_action => "log"
		file_completed_log_path => "D:/path/logstash.log"
		file_sort_by => "path"

		codec => multiline {
			max_lines => 1000000000
			pattern => "^%{LOGLEVEL}\|"
			negate => true
			what => previous
			charset => "Windows-1252"
		}
	}

The rest of the configuration is unchanged.

I had to fallback to my previous logstash version, the 6.5.1 is unusable in my context.

Thanks for your help!

Eniqmatic · November 29, 2018, 8:23am

Have you tried removing the wildcard star at the end of the file (assuming that its not just redacted) and putting that actual extension just for a test?

gfigoni · November 29, 2018, 9:38am

the path is not really the one I quoted... I obfuscated some data, but I have to handle files following this pattern : xxx[.yyyy-mm-dd-hh]?
So the '*' at the end of my path is required.

Eniqmatic · November 29, 2018, 9:59am

I know I'm asking if you can test it without the wildcard, so an absolute path, just to test!

gfigoni · November 29, 2018, 5:13pm

The problem is that in fact, logstash manages to handle my files, but once a while (several times per treatment), the file plugin crashes and reboots... but if it crashes too often, it slows down the process significantly.
It seems the crash is not tied to a specific file: I enabled a debug log level, and the plugin crashes while handling different files each time I launch the treatment on the same set of log files.

As you asked, I tried with an absolute path:
path => "D:/absolute/path/file.log"
but doing this it handles only one file... And the plugin didn't crash.

Eniqmatic · November 30, 2018, 8:09am

OK, so we have established that a newer version of logstash does not appear to like the wildcard option anymore, perhaps you should raise a bug ticket for this?

Another option would be filebeat, have you considered using it?

gfigoni · November 30, 2018, 8:17am

I don't really see the correlation: the file plugin seems to crash randomly when handling lots of files. The fact it doesn't crash on just one unique file doesn't imply the problem is linked to the wildcard option?
However, I'll raise a bug.

Filebeat could be an option, but it complicates my architecture: the files are all local to the machine where ELK is installed.

Eniqmatic · November 30, 2018, 8:20am

You don't see the correlation? With wildcard you said logstash was not starting in the first example, with a single file it works?

I wouldn't call filebeat a complication, its tiny and performs extremely well. However I can understand.

charlesqwsmith · December 7, 2018, 1:33pm

Hi, Gilles. I am getting the same stack trace. I suspect a bad interaction between mode -> "read" and sincedb database updates. Specifically, I think that the mode -> "read" feature is closing a file and setting @watched_file to null just before a sincedb database update.

Your path etc. are all fine. I believe that it is indeed supposed to be an array, but seems to work either way. And for sure this is NOT the cause of the problem.

One more observation from my environment: when the plugin crashes, it does not restart gracefully and leaves plenty of files unprocessed. This may be why you are being led to believe there is a problem with your file paths. Again, your file path is NOT the problem.

I am able to work around it in my environment by effectively turning off sincedb using this in my config:
file {
...
sincedb_write_interval => 157680000
}

I agree that filebeat is not necessary for your use case and adds unnecessary complexity. I was facing the same choice and I am going out of my way to avoid using it because it's not necessary now that the mode -> "read" feature exists.

Good luck.

ylasri · December 10, 2018, 10:34am

I am getting the same error when using read mode with logstash 6.5.2
The input is a folder with many files
The error occure when a file is closed to process the next file

[2018-12-10T11:34:11,401][ERROR][logstash.pipeline        ] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:main
  Plugin: <LogStash::Inputs::File start_position=>"end", mode=>"read", path=>["/data/UnProcessed/*.csv"], id=>"762db17bc413ff065e337013d441705f6ea3d6f22430824f7b419c3e63bb35dc", sincedb_path=>"/data/Logs/since_db.db", file_completed_action=>"log", file_completed_log_path=>"/data/Logs/files.log", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_8a44568b-6c4f-4cbe-8657-4d92007a343e", enable_metric=>true, charset=>"UTF-8">, stat_interval=>1.0, discover_interval=>15, sincedb_write_interval=>15.0, delimiter=>"\n", close_older=>3600.0, sincedb_clean_after=>1209600.0, file_chunk_size=>32768, file_chunk_count=>140737488355327, file_sort_by=>"last_modified", file_sort_direction=>"asc">
  Error: undefined method `path' for nil:NilClass
  Exception: NoMethodError
  Stack: C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/sincedb_value.rb:71:in `reading_completed'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/sincedb_collection.rb:165:in `reading_completed'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/handlers/read_file.rb:22:in `handle_specifically'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/handlers/base.rb:26:in `handle'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/processor.rb:35:in `read_file'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/processor.rb:104:in `block in process_active'
org/jruby/RubyArray.java:1734:in `each'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/processor.rb:88:in `process_active'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/read_mode/processor.rb:45:in `process_all_states'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/watch.rb:67:in `iterate_on_state'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/watch.rb:45:in `subscribe'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/filewatch/observing_read.rb:12:in `subscribe'
C://logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-file-4.1.8/lib/logstash/inputs/file.rb:339:in `run'
C://logstash/logstash-core/lib/logstash/pipeline.rb:409:in `inputworker'
C://logstash/logstash-core/lib/logstash/pipeline.rb:403:in `block in start_input'
[2018-12-10T11:34:12,486][INFO ][filewatch.observingread  ] QUIT - closing all files and shutting down.
[2018-12-10T11:34:12,518][INFO ][filewatch.observingread  ] START, creating Discoverer, Watch with file and sincedb collections

PiersB · December 13, 2018, 8:41pm

I had similar problem. I think it may be related to Windows and using drive letters (i.e. "D:") in the filename or pattern. I was battling a similar problem with the "path.config" configuration value not being accepted if it contained a drive letter. Making everything on the same drive, I was able to eliminate the drive letter from the configuration file and no longer encounter the exception. It appears to be a defect in some areas of the code when dealing with Windows paths.

BrianZimmel · December 21, 2018, 6:15pm

I am experiencing the same issue. What's frustrating is I have another pipeline configured a similar way, just different folder paths and processing, and it works. For the config that errors, it outputs only the first file. I have the sincedb_path specified and it lists the file with an "unknown" in the first field for the inode number:

unknown 0 0 32708 1545414892.656 c:/users/me/downloads/weekly_sync/extract/text/2018-01/folder1/folder2/folder3/file.xml

In the pipeline that works the inode number exists:

1587843519-1908013-131072 0 0 46049 1545414350.077 c:/users/me/downloads/weekly_sync/extract/text-jp/2018-01-JP/folder1/folder2/folder3/wo-file-application-body.xml

Here is my config

    path => "c:/users/zimmelb/downloads/wipo_weekly_sync/extract/text/**/DOC/**/**/*.xml"
    file_sort_by => "path"
    mode => "read"
    file_completed_action => "log"
    file_completed_log_path => "c:/programs/logstash/logs/logstash-wipo-text-completed.log"
    sincedb_path => "c:/programs/logstash/logs/logstash-wipo-text-sincedb.log"

If I set the path to a specific file with the directory names listed, I still get "unknown" in the sincedb. My guess is that this is the issue but I don't know what to do about it,

ylasri · December 26, 2018, 11:31am

Under windows try to use /users/zimmelb ...... instead of c:/users/zimmelb ........

BrianZimmel · December 26, 2018, 2:40pm

Thank you @ylasri that fixed my problem! I first only set the path as "/users/...", leaving the file_complete_log_path and sincedb_path with "c:/programs/..." and it picked up the files successfully. I then removed the drive letter from all paths in my config and it ran successfully as well. Dealing with paths in Windows has been a painful learning experience with Logstash!

system · January 23, 2019, 2:40pm

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