The log files are automatically rotated each time you restart the server. But after you already have 7 log files for a given day, if you then restart the server, then it will not create a DATE-8.log.gz, it will instead save it as DATE-7.log.gz, and then move DATE-7.log.gz into DATE-6.log.gz, and DATE-6.log.gz into DATE-5.log.gz, and so on, in the end resulting in DATE-1.log.gz being deleted.
Blindly deleting log files is problematic, and if the amount of log files is to be limited, it should at least be made into an option (allowing for unlimited log files as well.)
Comments 15
Confirmed for 1.10-pre2. This is kinda a serious bug IMO, because chatlogs in particular are important.
Editing the log4j config to include <DefaultRolloverStrategy max="999999"/> seems to fix it. See wiki.vg's debugging article for info on editing that config as a user (but mojang should add really put that into the default config).
Looks like this is deliberate behavior in log4j (see LOG4J2-435), though why they chose a default max of 7 I don't know.
Thanks for that workaround Pokechu, it works to solve the problem, but I haven't been able to set it to replicate vanilla behavior, for example I can't get it to print stuff to stdout any longer. Also it seems to take significantly longer for a server to start when adding a log4j configuration.
Any chance of posting a config that works as vanilla?
That config should work with vanilla, dunno why it isn't. I was using it with the client, though, not the server - the config might behave slightly different between the two. Also, note that wiki.vg's config is one that has a bunch of packet debug stuff enabled - you probably don't want all of that (and writing all that stuff to the console would create a lot of lag).
I'm not sure why it would take longer for it to start with a custom log4j config, but I do notice a slight increase in length (about a second or two). And it is logging to the console for me... odd that it isn't working for you.
You can see the default configuration if you just look for log4j2.xml within the server jar. In fact, you can also edit that configuration without the jar redownloading itself (the client would redownload itself but the server wouldn't).
—
Actually, I did just manage to reproduce that long startup time (though it's still printing to stdout); investigating.
Hm. Found a bit of info on LOG4J2-531. Specifically, the following comment from Remko Popma:
Geoff, just a preliminary update (still investigating):
becauseDefaultRolloverStrategyis configured withmax="999999", the rollover logic will allow for up to 1 million files with the same timestamp (but a different %i index if the rollover was triggered by the size threshold). Within the same time window, the rollover logic will then ensure that no more thanmaxfiles are created, and if the max has been reached, then the logic will remove the oldest file and rename all other indexed files to make room for the new one.
(See DefaultRolloverStrategy.)Why is this relevant? The logic above is implemented as a loop that will count down from 999999 to 1 (almost 1 million times), and call
if (new File(format(pattern, i)).exists())... in order to check if such a file exists and needs to be renamed.I suspect that accessing the disk so often will take significant time, and that the first rollover action is not complete yet when other threads have logged enough to trigger the next rollover, and that these overlapping rollover actions cause the problem you are seeing.
If I am correct, the problem can be worked around by creating a smaller time window, configuring a larger size for SizeBasedTriggeringPolicy so you can configure a smaller value for max in DefaultRolloverStrategy.
So, max=999999 would create a lot of lag. Yikes, didn't realize that. A smaller value would still work and give less lag (though when it does have to overwrite, it would have to rename all the files, which would also be laggy. max=999 would probably work well enough for most cases (unlikely to be run into, but about 1000 times faster than max=999999).
While most of LOG4J2-531 was resolved (that bug itself was caused by the date in a log getting incremented while it was doing that calculation for %i), the linear time searching still is happening.
I'm not sure why it isn't logging to the console. That's very weird.
Still present in current versions. Note that the "new" launcher (a few years late on that) lets you specify a log4j configuration in the UI, so this can be worked around for the client that way. For the server you'd still need to use a command-line argument.
It doesn't look like the default configuration has any size limits though, so it can still use arbitrary amounts of disk space.
Only recently discovered this. Running a public server this is a real nuisance. Was unable to check out a report of a player misbehaving. It is essential to be able to check the full logs.
Confirmed. I never noticed that there's a maximum of 7 logs per day... \:P