Index not created and more it doesn't open and read the log file to ship logs when starting logstash

cheriemilk · January 17, 2019, 9:16am

I am running to an issue since yesterday that it doesn't open and read the log file when starting logstash. Could you please help take a look what is the problem here?

1. Here is the logstash.conf

input {
        file{
                path => "C:\elkstack\elasticsearch-6.5.1\logs\njson.log"		
                start_position => "beginning"
				sincedb_path => "null"
				codec => "json"
            }
		
      }
                
output {
    elasticsearch {
	 action => "index"
	 hosts  => "localhost:9200"
	 index  => "logstash-talent"
	 }
	 
}

guyboertje · January 17, 2019, 2:25pm

Switch to using the stdout output while debugging...

input {
        file{
                path => "C:\elkstack\elasticsearch-6.5.1\logs\njson.log"    
                start_position => "beginning"
        sincedb_path => "null"
        codec => "json"
            }
    
      }
                
output {
  stdout { rubydebug } }
}

Then Turn on TRACE level logging in config/logstash.yml

Then post the log lines that are printed at TRACE here.

cheriemilk · January 18, 2019, 2:17am

when i pasting the log and save, the page returns me message "Sorry, you can only mention 10 users in a post." and not able to paste the log successfully

cheriemilk · January 18, 2019, 2:41am

sorry , how can I pase the ful log here??

cheriemilk · January 18, 2019, 4:39am

Hi guyboertje,
I use this
input {
file{
path => "C:\elkstack\elasticsearch-6.5.1\logs\app.log"
start_position => "beginning"
sincedb_path => "null"
codec => "json"
}

output {
elasticsearch {
action => "index"
hosts => "localhost:9200"
index => "logstash-scm"
}

stdout {
        codec => rubydebug
		
		}

}

AND I attach a pic of full log,

. Please help advice.

the size of full log trace is too big to post directly in debugmode.

Thanks,
Cherie

cheriemilk · January 18, 2019, 7:23am

Hi guyboertje,

I found this "Found existing elastic template. Skipping". Does this matter?

[2019-01-18T15:19:07,292][INFO ][logstash.outputs.elasticsearch] Attempting to install template {:manage_template=>{"template"=>"logstash-", "version"=>60001, "settings"=>{"index.refresh_interval"=>"5s"}, "mappings"=>{"default"=>{"dynamic_templates"=>[{"message_field"=>{"path_match"=>"message", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false}}}, {"string_fields"=>{"match"=>"", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false, "fields"=>{"keyword"=>{"type"=>"keyword", "ignore_above"=>256}}}}}], "properties"=>{"@timestamp"=>{"type"=>"date"}, "@version"=>{"type"=>"keyword"}, "geoip"=>{"dynamic"=>true, "properties"=>{"ip"=>{"type"=>"ip"}, "location"=>{"type"=>"geo_point"}, "latitude"=>{"type"=>"half_float"}, "longitude"=>{"type"=>"half_float"}}}}}}}}
019-01-18T15:19:07,477][DEBUG][logstash.outputs.elasticsearch] Found existing Elasticsearch template. Skipping template management {:name=>"logstash"}
[2019-01-18T15:19:08,395][INFO ][logstash.pipeline ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x27107877 run>"}

guyboertje · January 18, 2019, 12:37pm

Ok. About posting logs here.
You have some options:

Put triple backticks before and after the log text.```
Use pastebin, github gists or similar and put in a link.

That said, I looked at the image and it looks like you set the logging level to DEBUG but I asked you do set at TRACE...

Then Turn on TRACE level logging in config/logstash.yml
Then post the log lines that are printed at TRACE here.

I don't need all the log lines only the ones at TRACE and only the ones that grep with
grep 'TRACE]\[filewatch' ./logs/logstash-plain.log or similar.

Windows Findstr: Find Specific String In Files With Windows Command (Grep Alternative) TRACE][filewatch

cheriemilk · January 19, 2019, 12:02am

Hi guyboertje,

Sorry , please check below , and observed that "[TRACE][filewatch.discoverer ] discover_files {"count"=>0}". But I do double check that the log file exist in the path and there is one event in the file which is json format.
[2019-01-19T08:22:00,158][DEBUG][logstash.outputs.elasticsearch] Found existing Elasticsearch template. Skipping template management {:name=>"logstash"}
[2019-01-19T08:22:00,898][TRACE][logstash.inputs.file ] Registering file input {:path=>["C:\elkstack\elasticsearch-6.5.1\logs\app.log"]}
[2019-01-19T08:22:01,023][INFO ][logstash.pipeline ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c run>"}
[2019-01-19T08:22:01,082][TRACE][logstash.agent ] Converge results {:success=>true, :failed_actions=>, :successful_actions=>["id: main, action_type: LogStash::PipelineAction::Create"]}
[2019-01-19T08:22:01,164][INFO ][logstash.agent ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>}
[2019-01-19T08:22:01,202][INFO ][filewatch.observingtail ] START, creating Discoverer, Watch with file and sincedb collections
[2019-01-19T08:22:01,229][DEBUG][logstash.agent ] Starting puma
[2019-01-19T08:22:01,256][DEBUG][logstash.agent ] Trying to start WebServer {:port=>9600}
[2019-01-19T08:22:01,295][TRACE][filewatch.sincedbcollection] open: reading from null
[2019-01-19T08:22:01,308][TRACE][filewatch.sincedbcollection] open: count of keys read: 0
[2019-01-19T08:22:01,367][DEBUG][logstash.api.service ] [api-service] start
[2019-01-19T08:22:01,390][TRACE][filewatch.discoverer ] discover_files {"count"=>0}
[2019-01-19T08:22:01,735][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
[2019-01-19T08:22:03,997][DEBUG][logstash.instrument.periodicpoller.cgroup] One or more required cgroup files or directories not found: /proc/self/cgroup, /sys/fs/cgroup/cpuacct, /sys/fs/cgroup/cpu
[2019-01-19T08:22:04,491][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-01-19T08:22:04,493][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-01-19T08:22:06,097][DEBUG][logstash.pipeline ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:09,002][DEBUG][logstash.instrument.periodicpoller.cgroup] One or more required cgroup files or directories not found: /proc/self/cgroup, /sys/fs/cgroup/cpuacct, /sys/fs/cgroup/cpu
[2019-01-19T08:22:09,514][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-01-19T08:22:09,516][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-01-19T08:22:11,107][DEBUG][logstash.pipeline ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:14,007][DEBUG][logstash.instrument.periodicpoller.cgroup] One or more required cgroup files or directories not found: /proc/self/cgroup, /sys/fs/cgroup/cpuacct, /sys/fs/cgroup/cpu
[2019-01-19T08:22:14,534][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-01-19T08:22:14,536][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-01-19T08:22:15,537][TRACE][filewatch.discoverer ] discover_files {"count"=>0}
[2019-01-19T08:22:16,110][DEBUG][logstash.pipeline ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:19,011][DEBUG][logstash.instrument.periodicpoller.cgroup] One or more required cgroup files or directories not found: /proc/self/cgroup, /sys/fs/cgroup/cpuacct, /sys/fs/cgroup/cpu
[2019-01-19T08:22:19,551][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-01-19T08:22:19,552][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-01-19T08:22:21,111][DEBUG][logstash.pipeline ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:24,018][DEBUG][logstash.instrument.periodicpoller.cgroup] One or more required cgroup files or directories not found: /proc/self/cgroup, /sys/fs/cgroup/cpuacct, /sys/fs/cgroup/cpu
[2019-01-19T08:22:24,572][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-01-19T08:22:24,575][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-01-19T08:22:26,112][DEBUG][logstash.pipeline ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:28,462][WARN ][logstash.runner ] SIGINT received. Shutting down.
[2019-01-19T08:22:28,495][DEBUG][logstash.instrument.periodicpoller.os] Stopping
[2019-01-19T08:22:28,520][DEBUG][logstash.instrument.periodicpoller.jvm] Stopping
[2019-01-19T08:22:28,524][DEBUG][logstash.instrument.periodicpoller.persistentqueue] Stopping
[2019-01-19T08:22:28,526][DEBUG][logstash.instrument.periodicpoller.deadletterqueue] Stopping
[2019-01-19T08:22:28,609][DEBUG][logstash.agent ] Shutting down all pipelines {:pipelines_count=>1}
[2019-01-19T08:22:28,623][DEBUG][logstash.agent ] Converging pipelines state {:actions_count=>1}
[2019-01-19T08:22:28,632][DEBUG][logstash.agent ] Executing action {:action=>LogStash::PipelineAction::Stop/pipeline_id:main}
[2019-01-19T08:22:28,655][DEBUG][logstash.pipeline ] Stopping inputs {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:28,662][DEBUG][logstash.inputs.file ] Stopping {:plugin=>"LogStash::Inputs::File"}
[2019-01-19T08:22:28,726][INFO ][filewatch.observingtail ] QUIT - closing all files and shutting down.
[2019-01-19T08:22:28,732][DEBUG][logstash.pipeline ] Stopped inputs {:pipeline_id=>"main", :thread=>"#<Thread:0x1f520e7c sleep>"}
[2019-01-19T08:22:29,588][TRACE][filewatch.sincedbcollection] caller requested sincedb write (tail mode subscribe complete - shutting down)
[2019-01-19T08:22:29,599][TRACE][filewatch.sincedbcollection] sincedb_write: to: null

Badger · January 19, 2019, 12:46pm

[2019-01-19T08:22:00,898][TRACE][logstash.inputs.file ] Registering file input {:path=>["C:\elkstack\elasticsearch-6.5.1\logs\app.log"]}
[2019-01-19T08:22:01,295][TRACE][filewatch.sincedbcollection] open: reading from null
[2019-01-19T08:22:01,308][TRACE][filewatch.sincedbcollection] open: count of keys read: 0
[2019-01-19T08:22:01,390][TRACE][filewatch.discoverer ] discover_files {"count"=>0}

This very much suggests that "C:\elkstack\elasticsearch-6.5.1\logs\app.log" does not exist.

cheriemilk · January 19, 2019, 11:25pm

how come?? I checked again the file does exist.

and the file path in logstash is path => "C:\elkstack\elasticsearch-6.5.1\logs\app.log".

even I change the file path to path => "C:\elkstack\elasticsearch-6.5.1\logs\*.log", it still says "[TRACE][filewatch.discoverer ] discover_files {"count"=>0}"

Thanks,
Cherie

Badger · January 20, 2019, 12:15am

Can you try replacing the backslashes with forward slashes?

path => "C:/elkstack/elasticsearch-6.5.1/logs/app.log"

cheriemilk · January 20, 2019, 12:41am

it discover the file now. But still doesn't process the content in app.log and index logstash-talentaudit not created as well.

[2019-01-20T08:40:54,239][TRACE][filewatch.sincedbcollection] open: reading from null
[2019-01-20T08:40:54,256][TRACE][filewatch.sincedbcollection] open: count of keys read: 0
[2019-01-20T08:40:54,324][DEBUG][logstash.api.service ] [api-service] start
[2019-01-20T08:40:54,353][TRACE][filewatch.discoverer ] discover_files {"count"=>1}
[2019-01-20T08:40:54,568][TRACE][filewatch.discoverer ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='app.log', @state='watched', @recent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='1501', last_stat_size='1501', file_open?='false', @initial=true, @sincedb_key='unknown 0 0'>"}
[2019-01-20T08:40:54,585][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"unknown", "path"=>"C:/elkstack/elasticsearch-6.5.1/logs/app.log"}
[2019-01-20T08:40:54,598][TRACE][filewatch.sincedbcollection] associate: unmatched
[2019-01-20T08:40:54,745][TRACE][filewatch.tailmode.processor] Delayed Delete processing
[2019-01-20T08:40:54,765][TRACE][filewatch.tailmode.processor] Watched + Active restat processing
[2019-01-20T08:40:54,828][TRACE][filewatch.tailmode.processor] Rotation In Progress processing
[2019-01-20T08:40:54,845][TRACE][filewatch.tailmode.processor] Watched processing
[2019-01-20T08:40:54,884][TRACE][filewatch.tailmode.handlers.createinitial] handling: app.log
[2019-01-20T08:40:54,923][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
[2019-01-20T08:40:54,925][TRACE][filewatch.tailmode.handlers.createinitial] opening app.log
[2019-01-20T08:40:54,973][TRACE][filewatch.tailmode.handlers.createinitial] handle_specifically opened file handle: 100689, path: app.log
[2019-01-20T08:40:55,039][TRACE][filewatch.tailmode.handlers.createinitial] add_new_value_sincedb_collection {"position"=>0, "watched_file details"=>"<FileWatch::WatchedFile: @filename='app.log', @state='active', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='1501', current_size='1501', last_stat_size='1501', file_open?='true', @initial=true, @sincedb_key='unknown 0 0'>"}
[2019-01-20T08:40:55,097][TRACE][filewatch.tailmode.processor] Active - file grew: app.log: new size is 1501, bytes read 0
[2019-01-20T08:40:55,109][TRACE][filewatch.tailmode.handlers.grow] handling: app.log
[2019-01-20T08:40:55,242][TRACE][filewatch.tailmode.handlers.grow] reading... {"iterations"=>1, "amount"=>1501, "filename"=>"app.log"}
[2019-01-20T08:40:55,264][DEBUG][filewatch.tailmode.handlers.grow] read_to_eof: get chunk
[2019-01-20T08:40:55,308][TRACE][filewatch.tailmode.handlers.grow] buffer_extract: a delimiter can't be found in current chunk, maybe there are no more delimiters or the delimiter is incorrect or the text before the delimiter, a 'line', is very large, if this message is logged often try increasing the file_chunk_size setting. {"delimiter"=>"\n", "read_position"=>0, "bytes_read_count"=>1501, "last_known_file_size"=>1501, "file_path"=>"C:/elkstack/elasticsearch-6.5.1/logs/app.log"}
[2019-01-20T08:40:55,328][DEBUG][filewatch.sincedbcollection] writing sincedb (delta since last write = 1547944855)
[2019-01-20T08:40:55,334][TRACE][filewatch.sincedbcollection] sincedb_write: to: null
[2019-01-20T08:40:56,433][TRACE][filewatch.tailmode.processor] Delayed Delete processing
[2019-01-20T08:40:56,435][TRACE][filewatch.tailmode.processor] Watched + Active restat processing
[2019-01-20T08:40:56,441][TRACE][filewatch.tailmode.processor] Rotation In Progress processing
[2019-01-20T08:40:56,443][TRACE][filewatch.tailmode.processor] Watched processing

Thanks,
Cherie

Badger · January 20, 2019, 1:26am

OK, so having inode be "unknown" is a bug (wildcards that match multiple files will not work), but that's not hurting you yet.

The second message is telling you that it has read the entire 1501 characters from the file and it has not found the end of a line yet. If you open the file in notepad does it appear to have multiple lines?

cheriemilk · January 20, 2019, 1:37am

I opened with notepad. and the whole event(json format) is into two lines. what should I do?

cheriemilk · January 20, 2019, 2:38am

Hi Badger,

I manually input "enter" at the end of the file, and it create index and start parse the json event now. But still have 2 questions

Why in 6.5.1, it's forwardslash works? In logstash6.2.4, I use backslahs and it did work.
For file input, everytime should I input 'enter' to start a new line in log file?

Regards,
Cherie

Badger · January 20, 2019, 5:31pm

Each line of the file needs a line terminator, yes.

system · February 17, 2019, 5:31pm

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