Usage of pattern yyyy-ww does not change index every 7 days #50
Comments
|
Hi @vesselinn. I can't reproduce it. Are the logs in your indices have correct |
|
Hi @rfoltyns. Let me give you examples from our kibana:
Date: 2020-06-22 14:59:07.986
Date: 2020-07-04 23:59:13.271
Date: 2020-07-05 00:00:13.572 Thanks |
|
How consistently does that happen? Does it happen right after the deployment or after few weeks of JVM running? How many documents do you send to ES per day? Do you send logs immediately after they're produced or do you replay/re-process them? Do you have any post processing defined in ES? Pipelines? Do you have any index management defined in ES? Can you reproduce this in a test? |
|
Hi, When we noticed the problem we left one server (JVM) to run without restart for 3 weeks (you can see the result). |
|
I've also found log4j2 ticket mentioned in org.apache.logging.log4j.core.appender.rolling.PatternProcessor.getNextTime() / log4j-core-2.11.1jar. Could it be something related to the issue? |
|
Given a fairly constant daily rate, sth apparently went wrong on 22nd June. Could send me the output of this query? Ticket you mentioned describes issues on year change, but maybe it's worth looking into it. BTW, If you're transforming the logs from java logging, you can actually use |
|
Hello @rfoltyns , We are also using this project and we've come across the same problem. Here is a unit test to reproduce the issue and I guess I have found why the problem happens. @Test
public void testWeeklyRollingIndexPattern() {
Long sundayBeforeMidnight = LocalDateTime.of(2020, 9, 20, 23, 59, 59)
.atZone(ZoneId.of("GMT"))
.toInstant().toEpochMilli();
RollingIndexNameFormatter.Builder builder = spy(RollingIndexNameFormatter.newBuilder());
when(builder.getInitTimeInMillis()).thenReturn(sundayBeforeMidnight);
builder.withIndexName("index");
builder.withPattern("yyyy-ww");
builder.withSeparator("-");
builder.withTimeZone("GMT");
RollingIndexNameFormatter formatter = builder.build();
LogEvent logEvent = mock(LogEvent.class);
when(logEvent.getTimeMillis()).thenReturn(sundayBeforeMidnight);
String formattedIndexName = formatter.format(logEvent);
Assert.assertEquals("index-2020-38", formattedIndexName);
Long mondayAfterMidnight = LocalDateTime.of(2020, 9, 21, 0, 0, 1)
.atZone(ZoneId.of("GMT"))
.toInstant().toEpochMilli();
when(builder.getInitTimeInMillis()).thenReturn(mondayAfterMidnight);
LogEvent newWeekEvent = mock(LogEvent.class);
when(newWeekEvent.getTimeMillis()).thenReturn(mondayAfterMidnight);
String nextWeekIndex = formatter.format(newWeekEvent);
Assert.assertEquals("index-2020-38", nextWeekIndex); // should have failed and produced index-2020-39
formatter = builder.build(); // creating a new formatter instance
nextWeekIndex = formatter.format(newWeekEvent);
Assert.assertEquals("index-2020-39", nextWeekIndex);
} |
|
Thank you @cuneytcalishkan! Looks like a bug. If you'd like to solve it, I'm more than happy to accept your help 👍 I haven't thought about any concrete solutions yet, but there are few things to have in mind:
|
|
Hello @rfoltyns, So far I've managed to debug a little bit and understand what is going on behind the scenes of PatternProcessor that is created at initialization time, which actually calculates the next rollover time. What I've found out is that, this depends on the system settings about the country/region where the first day of the week changes depending on the locale. e.g. United States, first day of the week is Sunday whereas for France it is Monday. You can see in the below 2 unit tests which demonstrate this. In order for @Test
public void returnsWeeklyRolloverIndexNameWithFrance() {
final String timezone = "Europe/Paris";
long loggerInitMillis = LocalDateTime.of(2020, 10, 8, 21, 48, 35)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
RollingIndexNameFormatter.Builder builder = spy(RollingIndexNameFormatter.newBuilder());
when(builder.getInitTimeInMillis()).thenReturn(loggerInitMillis);
builder.withIndexName("index");
builder.withPattern("yyyy-ww");
builder.withSeparator("-");
builder.withTimeZone(timezone);
RollingIndexNameFormatter formatter = builder.build();
long sundayBeforeMidnight = LocalDateTime.of(2020, 10, 11, 23, 59, 59)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
LogEvent thisWeekEvent = mock(LogEvent.class);
when(thisWeekEvent.getTimeMillis()).thenReturn(sundayBeforeMidnight);
String formattedIndexName = formatter.format(thisWeekEvent);
Assert.assertEquals("index-2020-41", formattedIndexName);
long nextWeekMondayAfterMidnight = LocalDateTime.of(2020, 10, 12, 0, 0, 1)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
LogEvent nextWeekEvent = mock(LogEvent.class);
when(nextWeekEvent.getTimeMillis()).thenReturn(nextWeekMondayAfterMidnight);
String nextWeekIndex = formatter.format(nextWeekEvent);
Assert.assertEquals("index-2020-42", nextWeekIndex);
}
@Test
public void returnsWeeklyRolloverIndexNameWithUS() {
final String timezone = "Europe/Paris";
long loggerInitMillis = LocalDateTime.of(2020, 10, 8, 21, 48, 35)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
RollingIndexNameFormatter.Builder builder = spy(RollingIndexNameFormatter.newBuilder());
when(builder.getInitTimeInMillis()).thenReturn(loggerInitMillis);
builder.withIndexName("index");
builder.withPattern("yyyy-ww");
builder.withSeparator("-");
builder.withTimeZone(timezone);
RollingIndexNameFormatter formatter = builder.build();
long sundayBeforeMidnight = LocalDateTime.of(2020, 10, 10, 23, 59, 59)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
LogEvent thisWeekEvent = mock(LogEvent.class);
when(thisWeekEvent.getTimeMillis()).thenReturn(sundayBeforeMidnight);
String formattedIndexName = formatter.format(thisWeekEvent);
Assert.assertEquals("index-2020-41", formattedIndexName);
long nextWeekMondayAfterMidnight = LocalDateTime.of(2020, 10, 11, 0, 0, 1)
.atZone(ZoneId.of(timezone))
.toInstant().toEpochMilli();
LogEvent nextWeekEvent = mock(LogEvent.class);
when(nextWeekEvent.getTimeMillis()).thenReturn(nextWeekMondayAfterMidnight);
String nextWeekIndex = formatter.format(nextWeekEvent);
Assert.assertEquals("index-2020-42", nextWeekIndex);
}I am currently checking with our operation team about this country/region setting of the machines. |
|
Thank you @cuneytcalishkan. Great findings! 👍 I had a look at it as well and also found those Locale-based week ends. I've made a few tweaks during formatter initialization that gets your test to pass. Have a look here. I'll do some more testing today. Also @vesselinn, It seems like the issue is caused by premature rollover. Initialising the formatter with Would you like to test the behaviour of |
|
@rfoltyns that would be great to test it with these changes if possible. Thank you very much. |
|
Done. Add the repo to your <repositories>
<repository>
<id>oss.sonatype.org-snapshot</id>
<url>http://oss.sonatype.org/content/repositories/snapshots</url>
<releases>
<enabled>false</enabled>
</releases>
<snapshots>
<enabled>true</enabled>
</snapshots>
</repository>
</repositories> |
|
Hello @rfoltyns , |
|
Ok. If you're getting just a few events per day, could you create a test that reproduces it with exact timestamps? |
|
@cuneytcalishkan I've uploaded another snapshot with isses/50 to This one looks a bit more promising. Rolling formatter test gets green once
|
|
@cuneytcalishkan Did you have a chance to test the latest snapshot? |
|
Hello @rfoltyns, we actually deployed new version of the code with the latest snapshot and it seems to be even worse. |
|
@cuneytcalishkan I got similar results in tests if |
Description
Hello,
For couple of months we are using your app to send log events to ELK,
but for some reason it is not changing weekly index.
What we see actually is that the index stay for more than 10 days and when it change the index it neither Sunday nor Monday.
Configuration
`
Runtime (please complete the following information):
Additional context
Trying with daily or hourly pattern it is ok.
The text was updated successfully, but these errors were encountered: