Unexpected file opening error: File info is not identical with opened file

Elastic Stack Beats
1

I'm trying to collect smtp logs of a windows system environment using filbeat, but I don't get any data because the logfile change very quickly

This is the error in filbeat log:

2017-04-28T11:47:02-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170428.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.

What option could I use to fix this behavior?

Here is my environment:

  • Filebeat 5.3 for windows
  • Windows 2012 with SMTP service Enable
  • Logfile size >= 50MB

Filebeat YML config file:

filebeat_content_yml: |
  filebeat:
    prospectors:
      - input_type: log
        paths:
          - C:\Windows\System32\LogFiles\SMTPSVC1\in*
        document_type: smtp-relay-log
        ignore_older: 24h
        fields_under_root: true
        fields:
          env: prd
        tags: ["smtp-relay"]
  output:
    logstash:
      hosts: ["{{ logstash_server }}:5044"]
      timeout: 15
  logging:
    level: info

Thanks

2

What kind of logging schedule in windows you have configured. I assume it's daily. Is the timestamp modified after the log was changed? Filebeat use os.SameFile to compare if two files are the same. On windows it uses GetFileInformationByHandle and compare the volume serial number and the high-order and the low-order part of a unique identifier that is associated with a file. See here for more information about this. What kind of filesystem you use?

3

The logging schedule is daily (default), and the filesystem is NTFS (Default too). I will see your link. Thanks

4

Can you post the complete filebeat.log.

5

Sure! Here is an example

Logfile Filebeat 5.3.0 - Windows

6

Same error happened with filebeat 5.3.2, recently installed.

2017-05-02T10:54:21-03:00 INFO Home path: [C:\Program Files\Filebeat] Config path: [C:\Program Files\Filebeat] Data path: [C:\\ProgramData\\filebeat] Logs path: [C:\Program Files\Filebeat\logs]
2017-05-02T10:54:21-03:00 INFO Setup Beat: filebeat; Version: 5.3.2
2017-05-02T10:54:21-03:00 INFO Max Retries set to: 3
2017-05-02T10:54:21-03:00 INFO Activated logstash as output plugin.
2017-05-02T10:54:21-03:00 INFO Publisher name: eridanus
2017-05-02T10:54:21-03:00 INFO Flush Interval set to: 1s
2017-05-02T10:54:21-03:00 INFO Max Bulk Size set to: 2048
2017-05-02T10:54:21-03:00 INFO filebeat start running.
2017-05-02T10:54:21-03:00 INFO Registry file set to: C:\ProgramData\filebeat\registry
2017-05-02T10:54:21-03:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry
2017-05-02T10:54:21-03:00 INFO States Loaded from registrar: 5
2017-05-02T10:54:21-03:00 INFO Loading Prospectors: 1
2017-05-02T10:54:21-03:00 INFO Prospector with previous states loaded: 5
2017-05-02T10:54:21-03:00 INFO Starting prospector of type: log; id: 17305170178307357983 
2017-05-02T10:54:21-03:00 INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2017-05-02T10:54:21-03:00 INFO Starting Registrar
2017-05-02T10:54:21-03:00 INFO Start sending events to output
2017-05-02T10:54:21-03:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2017-05-02T10:54:21-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T10:54:31-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
7

Is it possible that you can move the smtp logfile to another folder, maybe c:\temp. Or better to another drive and then try again.

8

Sure. I moved the smtp logfile to E:\ drive, but It didn't work. Here are the logs. Also changed the directory permissions, but it don't resolve.

2017-05-02T14:53:21-03:00 INFO Metrics logging every 30s
2017-05-02T14:53:21-03:00 INFO Setup Beat: filebeat; Version: 5.3.2
2017-05-02T14:53:21-03:00 INFO Max Retries set to: 3
2017-05-02T14:53:21-03:00 INFO Activated logstash as output plugin.
2017-05-02T14:53:21-03:00 INFO Publisher name: eridanus
2017-05-02T14:53:21-03:00 INFO Flush Interval set to: 1s
2017-05-02T14:53:21-03:00 INFO Max Bulk Size set to: 2048
2017-05-02T14:53:21-03:00 INFO filebeat start running.
2017-05-02T14:53:21-03:00 INFO Registry file set to: C:\ProgramData\filebeat\registry
2017-05-02T14:53:21-03:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry
2017-05-02T14:53:21-03:00 INFO States Loaded from registrar: 6
2017-05-02T14:53:21-03:00 INFO Loading Prospectors: 1
2017-05-02T14:53:21-03:00 INFO Prospector with previous states loaded: 0
2017-05-02T14:53:21-03:00 INFO Starting prospector of type: log; id: 11639715767759128819 
2017-05-02T14:53:21-03:00 ERR Harvester could not be started on new file: E:\SMTPLogs\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T14:53:21-03:00 INFO Starting Registrar
2017-05-02T14:53:21-03:00 INFO Start sending events to output
2017-05-02T14:53:21-03:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2017-05-02T14:53:21-03:00 INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2017-05-02T14:53:31-03:00 ERR Harvester could not be started on existing file: E:\SMTPLogs\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T14:53:41-03:00 ERR Harvester could not be started on existing file: E:\SMTPLogs\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T14:53:51-03:00 INFO Non-zero metrics in the last 30s: publish.events=6 registrar.states.current=6 registrar.states.update=6 registrar.writes=3
2017-05-02T14:53:51-03:00 ERR Harvester could not be started on existing file: E:\SMTPLogs\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
9

Can you stop the SMTP server and then try to start filebeat.

10

Yes, but in this time, I can't. We have many applications using this smtp-relay. At non-business hours I could stop it for a fews minutes.

11

Ok. I think it has to do that the SMTP server has open a handle to the file while filebeat also trying to access it. @andrewkroh, do you have any idea?

12

I think that you're right, but If it's the problema, How filebeat could deal the matter? Exist another alternative for services that has blocking files?

13

Hi maddin2016, Recently, I stopped my smtp server. In this condition, the filebeat haven't problem in read the file, and logstash work without any problems. But when I started the smtp server, the problem appear again. Could be it a filebeat bug, and it can't read windows logfile management by windows services like smtp?

2017-05-02T23:50:48-03:00 INFO Home path: [C:\Program Files\Filebeat] Config path: [C:\Program Files\Filebeat] Data path: [C:\\ProgramData\\filebeat] Logs path: [C:\Program Files\Filebeat\logs]
2017-05-02T23:50:48-03:00 INFO Setup Beat: filebeat; Version: 5.3.2
2017-05-02T23:50:48-03:00 INFO Max Retries set to: 3
2017-05-02T23:50:48-03:00 INFO Activated logstash as output plugin.
2017-05-02T23:50:48-03:00 INFO Publisher name: eridanus
2017-05-02T23:50:48-03:00 INFO Flush Interval set to: 1s
2017-05-02T23:50:48-03:00 INFO Max Bulk Size set to: 2048
2017-05-02T23:50:48-03:00 INFO filebeat start running.
2017-05-02T23:50:48-03:00 INFO Registry file set to: C:\ProgramData\filebeat\registry
2017-05-02T23:50:48-03:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry
2017-05-02T23:50:48-03:00 INFO States Loaded from registrar: 7
2017-05-02T23:50:48-03:00 INFO Loading Prospectors: 1
2017-05-02T23:50:48-03:00 INFO Prospector with previous states loaded: 6
2017-05-02T23:50:48-03:00 INFO Starting prospector of type: log; id: 17305170178307357983 
2017-05-02T23:50:48-03:00 INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2017-05-02T23:50:48-03:00 INFO Starting Registrar
2017-05-02T23:50:48-03:00 INFO Start sending events to output
2017-05-02T23:50:48-03:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2017-05-02T23:50:48-03:00 INFO Harvester started for file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log
2017-05-02T23:51:18-03:00 INFO Non-zero metrics in the last 30s: filebeat.harvester.open_files=1 filebeat.harvester.running=1 filebeat.harvester.started=1 libbeat.logstash.call_count.PublishEvents=37 libbeat.logstash.publish.read_bytes=336 libbeat.logstash.publish.write_bytes=3734167 libbeat.logstash.published_and_acked_events=73721 libbeat.publisher.published_events=75769 publish.events=73728 registrar.states.current=7 registrar.states.update=73728 registrar.writes=35
2017-05-02T23:51:38-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T23:51:48-03:00 INFO Non-zero metrics in the last 30s: libbeat.logstash.call_count.PublishEvents=3 libbeat.logstash.publish.read_bytes=36 libbeat.logstash.publish.write_bytes=146495 libbeat.logstash.published_and_acked_events=5085 libbeat.publisher.published_events=3037 publish.events=5087 registrar.states.update=5087 registrar.writes=6
2017-05-02T23:51:48-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2017-05-02T23:51:58-03:00 ERR Harvester could not be started on existing file: C:\Windows\System32\LogFiles\SMTPSVC1\in170502.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: File info is not identical with opened file. Aborting harvesting and retrying file later again.
2
14

One more thing. Can you post what is inside your registry file and maybe registry.old. Just to check if idxhi, idxlo and vol are the same.

15

Sure!. Here are the files:

https://raw.githubusercontent.com/jenciso/logs/master/registry
https://raw.githubusercontent.com/jenciso/logs/master/registry.old

16

I haven't checked the whole thread but the error you see is something that should only happen in very rare cases. For it to happen lots of files have to be rotated at the same time with a potentially low scan_frequency. Strangely in your case it happens quite often.

The error shows when a file name changes between the time it was found during a scan and a harvester tries to open it.

How many files are in the directory to be harvested by filebeat?

17

I ruflin. I have six files

image.png802×320 30.5 KB

I tried using one file only (without regexp) in filebeat yaml file

18

Hi @ruflin. The filename doesn't change during the scan. I think the error comes from here. And at this point it doesn't check if the name has changed. It validates the file https://github.com/elastic/beats/blob/master/filebeat/harvester/log.go#L261. And the fact that it works if the smtp service is stopped shows that it has to do that the service maybe change the fileid or something else while it has access to it.

19

And if you look at the last modification date its always after it has closed the file. for example in170502 (the log for 02/05/2017) was closed on 03/05/2017 00:00. So the smtp service had an open handle to the file all the day.

20

@ruflin This maybe a complete red herring, but I wanted to add a data point. While running the Filebeat system tests on Windows I see the same error message in the output of most test cases. Although, I am running the test cases in our win2012 vagrant VM which means these tests execute on a network share.

1 Like