# Duplicates events when file rotation occurs - Windows
**URL:** https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315
**Category:** Beats
**Tags:** filebeat
**Created:** [June 20, 2016, 1:30pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315 "2016-06-20T13:30:42Z")
**Posts on this page:** 19
**Page:** 1
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 20, 2016, 1:30pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/1 "2016-06-20T13:30:42Z")
Hello,
We're in some strange behavior with our Filebeat.
Here the facts:
- filebeat 1.2.3
- windows server (2012 r2 I think)
- we use log4j2 for logging
- current/active logging file is named like this: acces.log, audit.log, application.log
- each file is rotated based on size (25mb) or day change
- when rotated, file moved to subfolder named YYYY-MM, and filename prefixed with YYYY-MM-DD and appended %i where %i is a daily sequence number
- each file is rotated when we cross the day at midnight, so each file contains only event from its tagged day in name
Last week we were hit by file modification date not changing for hours or at worst not changing from 00:00 (midnight).
Some search brought us to this known problem:
> [@Filebeat Not harvesting, file didn't change - do not use modification time](https://discuss.elastic.co/t/filebeat-not-harvesting-file-didnt-change-do-not-use-modification-time/49834):
>
> My understanding is that filebeat will look at the modification timestamp provided by the OS to determine if the file has been modified and then the harvester will try and read from where it left off, correct? There is a [bug in the Windows 2008 R2](https://social.technet.microsoft.com/Forums/office/en-US/2b8baca2-9c1b-4d80-80ed-87a3d6b1336f/file-timestamp-not-updating-on-2008-but-does-on-2003?forum=winservergen) that manifests itself in not updating the modification time. Wouldn't it be a better strategy to compare the offset from the last read to the filesize and see if it has grown, instead of only relying on the OS mod time? This could be an option like: โฆ
So we increased our close\_older setting from 1h to 30h to easily cover our worst case of single daily moddate (00:00).
Also, we always ensured that our globs covers current files as rotated ones.
One of our prospector config:
```
filebeat:
prospectors:
-
paths:
# CURRENT FILES: d:\logs\[domain]\[managed server]\[application name]\
- d:\logs\*\*\*\acces.log
# ROTATED FILES: d:\logs\[domain]\[managed server]\[application name]\YYYY-MM\
- d:\logs\*\*\*\*\*-acces-*.log
document_type: acces
encoding: iso8859-1
input_type: log
ignore_older: 168h
close_older: 30h
scan_frequency: 10s
force_close_files: false
```
We though it will fix everything, but looking at logs surrounding midnight I can see a lot of event sent when rotation occurs. Our spool size (4096) is flushed many times, a sign that something odd is occuring.
Here's the filebeat log at midnight: [filebeat-midnight-rotation-log ยท GitHub](https://gist.github.com/blavoie/9b060b918cb4bee8fe78c86df63a441d)
When looking at Elasticsearch, I can see duplicates for the same events.
Easy to confirm the duplicates as:
- we're on very low activity at midnight, and spool size never hit the day on our summer load
- events are timestamped at milisecond level
So, is it a bug or misconfiguration on our side?
Thanks
Bruno
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [June 20, 2016, 3:05pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/2 "2016-06-20T15:05:36Z")
Thanks for sharing all the details. I had a quick look at the log:
`Not resuming rotated file:`: This is good even though it is a little bit misleading. It means it found the same filename again, but it is a new file (which I think is the case.
What worries me are the following lines:
```auto
2016-06-20T00:00:06-04:00 INFO Harvester started for file: d:\logs\mpo-prod\mpo-web2-cluster-ms1\set\2016-06\2016-06-19-application-1.log
2016-06-20T00:00:06-04:00 INFO Harvester started for file: d:\logs\mpo-prod\mpo-web1-cluster-ms1\mpo-portail\2016-06\2016-06-19-application-1.log
2016-06-20T00:00:06-04:00 INFO Registry file updated. 592 states written.
2016-06-20T00:00:06-04:00 INFO Registry file updated. 593 states written.
```
First it starts a new harvester on a file it should already know and then it adds one more state to the registry file (instead of updating the old one). My initial guess here is that somehow the identifiers changed. How do you exactly move / rename the files? Can you check if the identifiers and the device id are identical after moving the files?
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 20, 2016, 3:30pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/3 "2016-06-20T15:30:48Z")
Thanks for your fast reply.
I asked operations to send me registry file this morning, and I'll do the same this afternoon and tomorrow morning to check files identifiers.
Current FileStateOS of my audit.log file:
```
"FileStateOS": {
"idxhi": 327680,
"idxlo": 24804,
"vol": 1549167686
}
```
Is the "vol" value the most important one? (kind of inode under windows?)
I don't know exactly how rotation works, as it uses LOG4J2.
Rollover strategies in documentation [https://logging.apache.org/log4j/2.x/manual/appenders.html#RolloverStrategies](https://logging.apache.org/log4j/2.x/manual/appenders.html#RolloverStrategies) always talks about renaming...
I'm not developer on this but can ask for pointers...
I can't imagine that it does anything else than a rename, a copy incurs a lot of overhead.
Bruno
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [June 20, 2016, 4:05pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/4 "2016-06-20T16:05:16Z")
Under windows the combination of `idxhi, idxlo, vol` must be unique (on linux it is `inode, device`). So in case one of the three changes, filebeat assumes it is a new. Based on your config I would assume the volume id should not change. Is `d:` a shared/mounted drive or a local disk?
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 20, 2016, 4:07pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/5 "2016-06-20T16:07:05Z")
Filebeat is deployed locally on each server, then D: is a local drive.
Remote mounts are hell..... ๐
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 21, 2016, 1:40pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/6 "2016-06-21T13:40:46Z")
Hello,
Updates from this morning, at first, everything seems ok.
I have compared registrar files from yesterday and this morning
From yesterday registry, current audit.log file:
```
"d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\audit.log": {
"source": "d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\audit.log",
"offset": 485303,
"FileStateOS": {
"idxhi": 327680,
"idxlo": 24804,
"vol": 1549167686
}
},
```
From today registry, current audit.log file (state info changed):
```
"d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\audit.log": {
"source": "d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\audit.log",
"offset": 22887,
"FileStateOS": {
"idxhi": 720896,
"idxlo": 24914,
"vol": 1549167686
}
},
```
From today registry, rotated file kept the same state informations (state info hasn't changed on rollover):
```
"d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\2016-06\\2016-06-20-audit-1.log": {
"source": "d:\\logs\\mpo-prod\\mpo-web1-cluster-ms1\\mpo-audit\\2016-06\\2016-06-20-audit-1.log",
"offset": 809742,
"FileStateOS": {
"idxhi": 327680,
"idxlo": 24804,
"vol": 1549167686
}
},
```
As always, we can see a lot of filebeat activity at midnight:
>
First: are my settings appears OK?
Second: should I enable debug logging? Which level? how?
Thanks
Bruno
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 23, 2016, 4:13pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/7 "2016-06-23T16:13:10Z")
Hello @ruflin, any new tips on this?
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [June 28, 2016, 10:20am UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/8 "2016-06-28T10:20:27Z")
@Bruno_Lavoie Sorry for the late reply. In general everything looks fine. To enable debug logging, you must start filebeat with `-e -d "*"`.
It seems like for the file you posted above, also the harvesting didn't continue (no duplicated events). It would be interesting to compare the state for one that did, for example `2016-06-20-application-1.log`.
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 28, 2016, 7:57pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/9 "2016-06-28T19:57:22Z")
Ok,
I activated debug level logging and this makes a lot of output because a lot of Publish output.
Any way to disable only publish events?
Also, we have multiple 2016-06-20-application-1.log files, from multiple applications.
They all seems to have the same problem.
Look for yesterday:
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [June 29, 2016, 6:41am UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/10 "2016-06-29T06:41:24Z")
There are different selectors which can be set for the debug output. I set all above as I'm not sure yet which one will be needed. Unfortunately it is only whitelisting and not blacklisting.
Any chance to share the ids for a file that has duplicates as you did previously above?
Alternatively you could try 5.0.0-alpha3 to see if there is still the same behaviour. Quite a few improvements were made in the registry management.
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [June 30, 2016, 3:17pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/11 "2016-06-30T15:17:12Z")
Hello,
Sorry for delay, my turn!
I've put in place scheduled jobs to capture registry and log files automatically before and after midnigth.
Also, I put my efforts on a acces.log for which I have a unique request identifier for each line. With this I can be out of doubt about duplicates.
When crawling logs, they're all duplicated, because it happens at each file rollover.
Yesterday afternoon:
Rollover from yesterday to today (midnight).
**2016-06-29 23:59:45 Snapshot**
Current
```
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\acces.log": {
"FileStateOS": {
"idxhi": 851968,
"idxlo": 26050,
"vol": 3995102152
},
"offset": 12258620,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\acces.log"
},
```
Rotated
```
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-1.log": {
"FileStateOS": {
"idxhi": 65536,
"idxlo": 26032,
"vol": 3995102152
},
"offset": 26214552,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-1.log"
},
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-2.log": {
"FileStateOS": {
"idxhi": 983040,
"idxlo": 26044,
"vol": 3995102152
},
"offset": 26214523,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-2.log"
},
```
**2016-06-30 00:00:15 Snapshot**
Current file
```
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\acces.log": {
"FileStateOS": {
"idxhi": 720896,
"idxlo": 26060,
"vol": 3995102152
},
"offset": 5352,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\acces.log"
},
```
Rotated
```
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-1.log": {
"FileStateOS": {
"idxhi": 65536,
"idxlo": 26032,
"vol": 3995102152
},
"offset": 26214552,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-1.log"
},
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-2.log": {
"FileStateOS": {
"idxhi": 983040,
"idxlo": 26044,
"vol": 3995102152
},
"offset": 26214523,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-2.log"
},
"d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-3.log": {
"FileStateOS": {
"idxhi": 851968,
"idxlo": 26050,
"vol": 3995102152
},
"offset": 90461,
"source": "d:\\depot_journal\\mpo-prod\\mpo-web1-cluster-ms3\\mpo-portail\\2016-06\\2016-06-29-acces-3.log"
},
```
**Then Info Log**
[https://gist.githubusercontent.com/blavoie/3a5eb40d0924b06d8a4d24e472475317/raw/ed39f52a6bd0ff87baf336c8e733a9367734f8c3/info-log](https://gist.githubusercontent.com/blavoie/3a5eb40d0924b06d8a4d24e472475317/raw/ed39f52a6bd0ff87baf336c8e733a9367734f8c3/info-log)
Am I dreaming that file state doesn't change on rotate?
I'm trying to reproduce with a tiny program using same logging library to see if I can reproduce on my workstation.
If not, then I'll try to convince OPs to put latest version.
Thanks, more on that later.
Bruno
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [July 4, 2016, 1:47pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/12 "2016-07-04T13:47:18Z")
Hello,
Good news, I've reproduced the behavior under Win7 with my little sample program.
Then, with 5.0.0-alpha4 this does't duplicate data on rollover.
๐
If you want code to reproduce:
[https://github.com/blavoie/filebeat-rotate-test](https://github.com/blavoie/filebeat-rotate-test)
I will send the latest binary file to ops to make the update on each servers.
Just to be safe, as stated here:
> [@Filebeat Not harvesting, file didn't change - do not use modification time](https://discuss.elastic.co/t/filebeat-not-harvesting-file-didnt-change-do-not-use-modification-time/49834/11):
>
> @logstash_oz @wmcdonald The newest version of filebeat (5.0.0-alpha3) now relies much less on the modification date for harvesting. Could you try out if this version resolves the above issues?
And seen here:
>
The harvester doesn't monitor file based on moddate but now on size?
Is it safe to make close\_older to something more appropriate? 30h --\> 1h
Thanks
Bruno Lavoie
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [July 4, 2016, 8:14pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/13 "2016-07-04T20:14:48Z")
Hi Bruno
I still have to take a closer look into the data above to better understand why this happened with alpha3 and not alpha4. I just wanted you to briefly notify about this issue here as I felt it could be related: [https://github.com/elastic/beats/pull/1954](https://github.com/elastic/beats/pull/1954) (not merged yet).
About your other questions will get back to you later / tomorrow.
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [July 5, 2016, 7:51am UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/14 "2016-07-05T07:51:59Z")
@Bruno_Lavoie I now had a closer look. I still don't understand to 100% what caused the issue above and how it was resolved in alpha4.
The size of the file is now used to decide if a harvester should continue harvesting a file or not. This was missing previously so I have the suspicion that this caused some double harvesting.
It is save to set `close_older` also to a much lower value, like 1 minute or 5 min. We are currently discussing it to set it a lower default value. The only side affect is that file which were closed and changed, will only be picked up again after `scan_frequency`. But normally log files which were closed, do not change over time and are only rotated.
Thanks for doing all the investigations. Please ping me if the problem occurs again.
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [July 5, 2016, 2:35pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/15 "2016-07-05T14:35:14Z")
Hello,
The bug is reroductible with FB 1.2.3, not with latest alpha.
Sorry for the confusion.
BL
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [July 6, 2016, 6:50am UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/16 "2016-07-06T06:50:56Z")
@Bruno_Lavoie It seems like your issue is the same that was fixed here: [https://github.com/elastic/beats/pull/1954](https://github.com/elastic/beats/pull/1954) It is not part of the nightlies: [https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/](https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/)
The problem is that if a file rotation happens during a scan, there is some race between the file state and the file path. The probability that this happens on 1.2.3 is much higher then it was on 5.0.0-\* because the state is read much more often. With the most recent fix it cannot happen anymore, because after opening the file, it is checked if the correct file was opened.
---
### Author:  [@Bruno\_Lavoie](https://discuss.elastic.co/u/Bruno_Lavoie)
#### Post date: [July 6, 2016, 1:10pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/17 "2016-07-06T13:10:43Z")
@ruflin
Such un nightmare for you all this logrotate stuff!
On the good news: using FB5-alpha4 doesn't send duplicate events on rollover anymore. ๐
IIRC, there's a chance of problems on rollover?
As you mentionned about [https://github.com/elastic/beats/pull/1954](https://github.com/elastic/beats/pull/1954), it's not in current alpha builds?
Target version for theses fixes?
Thanks again for you support
---
### Author:  [@ruflin](https://discuss.elastic.co/u/ruflin)
#### Post date: [July 11, 2016, 8:30am UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/18 "2016-07-11T08:30:59Z")
Glad to hear it works now. There is still a chance for the race condition in alpha4, but to reproduce it I had to rotate 100 files multiple times in 1 second ๐ It should completely fixed in the latest nightly build [https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/](https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/) Let me know in case you hit any issues with the nightly build.
This is planned to ship with the 5.0.0-beat1 release in a few weeks.
---
### Author:  [@system](https://discuss.elastic.co/u/system)
#### Post date: [July 11, 2016, 1:30pm UTC](https://discuss.elastic.co/t/duplicates-events-when-file-rotation-occurs-windows/53315/19 "2016-07-11T13:30:54Z")
This topic was automatically closed after 21 days. New replies are no longer allowed.