Filebeat - 10000s of messages "Reader was closed. Closing.#011" flooding log

Alex_Stuck · April 1, 2023, 12:18am

Hey there
Subject says it all. I have a simple filebeat agent pointing to some other team's LS that I don't control. I get spammed with the following line at a rate of up to 1000/minute and it doesn't stop. Here an example of 10 within 1 second.

2023-03-31T23:57:49.607784+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.607Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.628766+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.628Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.628785+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.628Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.630121+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.630Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.631337+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.631Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.632751+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.632Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.634455+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.634Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.639994+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.639Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.641195+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.641Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}
2023-03-31T23:57:49.642599+00:00 syslog-c01n01 filebeat[25349]: 2023-03-31T23:57:49.642Z INFO [input.filestream] map[file.line:321 file.name:filestream/input.go] Reader was closed. Closing.#011{"ecs.version": "1.6.0"}

What does this mean ?
Why is it always "#011"
What does #011 refer to ?

thx

leandrojmp · April 1, 2023, 3:15am

The beats are pretty noisy and will spam your system logs since per default they log to stdout.

My suggestion is to edit your filebeat.yml to log to a file and change the log level to warning with the following config.

logging.level: warning
logging.to_files: true
logging.files:
  path: /var/log/filebeat
  name: filebeat
  keepfiles: 7
  permissions: 0640

If I'm not wrong I tink that your log basically means that it finished reading a file.

The #011 part is just the ASCII code for the tab character in octal.

Alex_Stuck · April 1, 2023, 5:35am

Only one problem. This also disables the monitoring json output that u get every 30s under log level info. I'm using that to graph all the beats stats
This #011 bit looks like it should be only part of debug logging in my opinion.

stephenb · April 1, 2023, 6:16am

Interesting here is the line of code.

Looks like this should be classified as an ERROR...

github.com

elastic/beats/blob/df59745ee01a9ffd86387160c0d63a7a4b5d8f5c/filebeat/input/filestream/input.go#L321


      
          	path string,
          	s state,
          	p loginp.Publisher,
          ) error {
          	for ctx.Cancelation.Err() == nil {
          		message, err := r.Next()
          		if err != nil {
          			if errors.Is(err, ErrFileTruncate) {
          				log.Infof("File was truncated. Begin reading file from offset 0. Path=%s", path)
          			} else if errors.Is(err, ErrClosed) {
          				log.Info("Reader was closed. Closing.")
          			} else if errors.Is(err, io.EOF) {
          				log.Debugf("EOF has been reached. Closing.")
          			} else {
          				log.Errorf("Read line error: %v", err)
          			}
          			return nil
          		}
          
          
		s.Offset += int64(message.Bytes)

@andrewkroh ^ Looks like ERROR Message as INFO also is this an actual error or just normal closing of files.

andrewkroh · April 4, 2023, 11:55am

That looks like a message relating to the normal operation of the input. The input will close the reader for several reason such as the file has been inactive for a period of time (it will reopen after it sees changes). I think it would be better to have that a the debug level (and perhaps have some metrics related to the reader instances that can show what's happening over time).

Can you open a github issue for log spam problem coming from this line.

Filebeat has an HTTP API that can return metrics if you don't want to (or can't) scrape them from logs. See Configure an HTTP endpoint for metrics | Filebeat Reference [8.11] | Elastic.

Alex_Stuck · April 5, 2023, 5:31am

Done

github.com/elastic/beats

input.filestream spams info log with "Reader was closed"

opened 05:30AM - 05 Apr 23 UTC

stucky101

needs_team

Hey there I was asked to file an issue regarding this discussion: https://di…scuss.elastic.co/t/filebeat-10000s-of-messages-reader-was-closed-closing-011-flooding-log/329088 Filebeat agent version 8.6.2 Simple config example ``` logging.level: info logging.to_syslog: true filebeat.config.modules: path: ${path.config}/modules.d/*.yml reload.enabled: false filebeat.inputs: - type: filestream id: log enabled: true paths: - /log/**/* output.logstash: hosts: ["beats-host.domain.com:5044"] ssl.enabled: true processors: - add_fields: target: "@socat" fields: token: "1234zxc" ``` thx

thx

system · May 3, 2023, 7:32am

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