Filebeat: Unexpected file opening error: file info is not identical with opened file. Aborting harvesting and retrying file later again

Elastic Stack Beats
,
1

Hello,

We have ELK 7.8.1 stack running in K8 cluster. Filebeat on one of the node is not able to keep up with the logs generated by one MS. This was working fine until couple of days.

Missing logs are from a container for which there are below errors in filebeat logs:

**2020-12-10T17:12:04.980Z	ERROR	log/input.go:501	Harvester could not be started on new file: /var/lib/docker/containers/<container-id>-json.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**

This particular container is logging approx. 8.4 M per hour.

Tried restarting filebeat and it transfer logs for few minutes but then it starts to lag again. Also observed that the memory for this filebeat is gradually increasing and CPU is higher as compared to other filebeats.

image
image781×204 23.3 KB

Have gone through all older post but couldn't find any solution.

Any suggestions/workaround would be greatly appreciated.

TIA.

Regards,

2

Hi @elk_follower,

Is this happening always with the same file? If it is maybe you can try to stop filebeat on this machine and manually edit the registry to remove this file.

3

Thanks @jsoriano for instant response.

This was working fine until filebeat was restarted few days back and after that it's not able process the file. I wont be able to manually edit the registry file as this is production setup with no access to VMs.

The other workaround would be to restart the MS to that the json docker file name changes.
But what if this happens again?

Any insight why this error is logged?

TIA.

4

From what I see in other discussions about this, this can happen very very rarely. If it happens again in your case it'd be interesting to investigate it more. I wonder in any case why the memory usage increases so much after this happens.

This looks like some kind of corruption of the registry. The state the harvester sees in the system and the state it sees in the registry don't match.

5

@jsoriano, Thanks for you reply.

Filebeat is still lagging by a lot. Let me try to get the filebeat registry entry for that file. Please let me know if you need any more information.

The only difference about the MS is that its logging very fast and might be rotating the file very often. Let me confirm this as well.

Thanks for your help.

6

@jsoriano, some new findings and this is really interesting. The MS was restarted and it hoped onto another node and we see the same behavior with filebeat - Lagging in sending the logs and high memory usage. Also i checked the registry file and could see almost 1400 entries for the same docker log file.

Below is the snippet of the filebeat registry:

{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":5794,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594813,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":89770,"timestamp":"2020-12-11T19:32:30.255940657Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192576924,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":109156,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594803,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":122407,"timestamp":"2020-12-11T19:32:30.255940657Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":191900463,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":104687,"timestamp":"2020-12-11T19:32:30.255940657Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594809,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":76602,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594804,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":43748,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594799,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":71828,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594800,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":70528,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594801,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":73526,"timestamp":"2020-12-11T19:32:30.255940657Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594808,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":75172,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594807,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":74640,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594798,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":39145,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594788,"device":51713}},{"source":"/var/lib/docker/containers/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66-json.log","offset":62258,"timestamp":"2020-12-11T19:32:30.255940657Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":181545470,"device":51713}},{"source":"/var/lib/docker/containers/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66-json.log","offset":172264,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":181545469,"device":51713}},{"source":"/var/lib/docker/containers/35eccdfcf168f9b29ac29d020e1b218d906a06a52ea477bba83a675355008a68/35eccdfcf168f9b29ac29d020e1b218d906a06a52ea477bba83a675355008a68-json.log","offset":606467,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":72534560,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":41430,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594805,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":38894,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594820,"device":51713}},{"source":"/var/lib/docker/containers/30a7261e488a8e5f49f9573da9425cc1dba55ab990bd3f4857a8a68356cb645e/30a7261e488a8e5f49f9573da9425cc1dba55ab990bd3f4857a8a68356cb645e-json.log","offset":4096944,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":62411037,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":49098,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594811,"device":51713}},{"source":"/var/lib/docker/containers/85d114a07f433105f589503ad94d2da5c621d11acbdb1cf174c3a1bf512b827b/85d114a07f433105f589503ad94d2da5c621d11acbdb1cf174c3a1bf512b827b-json.log","offset":108,"timestamp":"2020-12-11T19:32:06.056064115Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":161524435,"device":51713}},{"source":"/var/lib/docker/containers/3818a56348c22d4baa9b9c3ec7896924723d4099422d8e758b37f5e643a8d3a8/3818a56348c22d4baa9b9c3ec7896924723d4099422d8e758b37f5e643a8d3a8-json.log","offset":0,"timestamp":"2020-12-11T19:32:11.756035621Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":9233079,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1927,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594806,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":7221,"timestamp":"2020-12-11T19:32:29.755990878Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192594812,"device":51713}},{"source":"/var/lib/docker/containers/eb4e923eaa947b3929217a1114b201f83421c92540bef9ff5aa1fcaaf1372b81/eb4e923eaa947b3929217a1114b201f83421c92540bef9ff5aa1fcaaf1372b81-json.log","offset":1641,"timestamp":"2020-12-11T19:31:27.65609737Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":70256873,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":0,"timestamp":"2020-12-11T19:32:28.556177141Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":192576925,"device":51713}}]

image
image741×202 25.6 KB

Red one is the old filebeat where this MS was running and Green is the filebeat where the MS moved and as we can see the memory usage just spiked and reached the resource limit set to 500 MB, may be it would have OOM.

7

I don't think this should happen in any case :confused:

@elk_follower do you see the same errors about not identical files in the logs of the other host affected?

Would you have the chance to upgrade Filebeat to 7.9 or 7.10? Registry was refactored on 7.9, maybe this issue was already fixed, if not, we should open an issue for further investigation.

Thanks!

8

@jsoriano, Appreciate your help on this.

do you see the same errors about not identical files in the logs of the other host affected?

Yes, I see the same error for this log file and there are still 1400 entries in registry.

2020-12-12T18:01:02.958Z	ERROR	log/input.go:501	Harvester could not be started on new file: /var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.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

@jsoriano, I cleaned up the registry and still multiple entries for the same file are getting inserted into the registry.

{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":4005089,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890596,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":3152466,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890175,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":3132644,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890171,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":2898989,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890131,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":2372841,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890134,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":2295384,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890135,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1957936,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890169,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1672870,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890173,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1476202,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890594,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1389742,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890597,"device":51713}},{"source":"/var/lib/docker/containers/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66/62942ffec42be013af6960a0155d1d36dd391d89361481a254318004b2245b66-json.log","offset":2906917,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":181551995,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":1107893,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890598,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":948091,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890601,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":860598,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890602,"device":51713}},{"source":"/var/lib/docker/containers/884961415f0bf6eedaf202595500ec9054c9987556e9530737a950d79c904db9/884961415f0bf6eedaf202595500ec9054c9987556e9530737a950d79c904db9-json.log","offset":335597,"timestamp":"2020-12-16T20:33:27.155982721Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":910495,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":649432,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890603,"device":51713}},{"source":"/var/lib/docker/containers/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0/063548b2ae270dfd4379290ede37e7c2897f99501a243bd3442283495ba39dd0-json.log","offset":570529,"timestamp":"2020-12-16T20:34:03.716504976Z","ttl":1800000000000,"type":"container","meta":null,"FileStateOS":{"inode":191890604,"device":51713}}]

Will just update the filebeat and see if that helps.

Regards,

10

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