Windows: Add log file rotation support

[skizunov]

What does this PR do?

An external log file rotation tool, such as logrotate will not work
with an operating system such as Windows. From the Python documentation
for WatchedFileHandler (which is used for log files in Salt):

"This handler is not appropriate for use under Windows, because under
Windows open log files cannot be moved or renamed - logging opens the
files with exclusive locks - and so there is no need for such a handler.
Furthermore, ST_INO is not supported under Windows; stat() always returns
zero for this value."

This also describes the problem with why an external utility such as
logrotate will not work for Windows, because files cannot be renamed
while in use, unlike on other operating systems, such as Linux.

Due to the above, the strategy for this change is to use the
RotatingFileHandler logger (when log file rotation is enabled) and to
allow only one process to do the file logging. Previously on Windows,
there was a file logger installed in the main process and another in the
logging listener process. This change changes the architecture in the
following way (on Windows only):

• Added two new configuration options, log_rotate_max_bytes and
  log_rotate_backup_count. They both default to 0. When
  log_rotate_max_bytes is non-zero, the RotatingFileHandler will be
  used for file logging instead of the WatchedFileHandler.
• The only process that does file logging is the logging listener process
  (if it exists)
• When the logging listener process does not exist, only the main process
  does file logging.
• When the logging listener process exists, the main process will now set
  up multiprocessing logging (which is the client to the logging listener).
• Since the logging listener does logging for extended logging, console,
  and log file logging, do not use these types of logging in the main process
  when there is a logging listener.

There is one observed caveat: when the log file is in use, and it is time
to rollover (rename the file), the rollover will fail. This has been
obversed when salt-call is running and has the minion log file open
for its own logging uses while the salt-minion is trying to rollover.
Luckily, it will recover and try to rollover again on the next log write,
and if the file is no longer in use, it will succeed this time. Hence,
having a log file open somewhere else will delay rollover until the file
is closed.

Tests written?

No

Signed-off-by: Sergey Kizunov sergey.kizunov@ni.com

[damon-atkins]

Fantastic.

This change changes the architecture in the following way (on Windows only)

Can I suggest its available to all platforms but only enabled on Windows and other platforms which do not have a log rotation tool. i.e. Should the architecture be the same for all platforms.

Whats the impact of minion multiprocessing option on this change, if any?

[skizunov]

Can I suggest its available to all platforms but only enabled on Windows and other platforms which do not have a log rotation tool. i.e. Should the architecture be the same for all platforms.

Things become a bit complicated on other platforms due to the behavior of fork(). There was a few big PRs that I submitted earlier to get logging working properly at all on Windows (eg PR #34895, #29957, #29871). The original author of the logging system relied heavily on fork() behavior which doesn't work on Windows and hence caused me to come up with an alternative architecture specific for Windows. Given the difference in fork() behavior, it would be a non-trivial amount of work to move to this architecture on other platforms, but is definitely tenable. This PR gets you closer. I welcome anyone to try if they see benefit in it.

To me, non-Windows use of this architecture is not a necessity. Other platforms can use the logrotate utility which is the standard method to do this type of thing everywhere but on Windows. And logrotate has many more options and hence is more powerful than what is offered here (I am limited to the options that Python offers). logrotate does not exist on Windows and cannot exist because of the difference in the way the Windows filesystem works (eg can't rename an open file on Windows but you can on other platforms, which is what logrotate relies on in concert with WatchedFileHandler).

Whats the impact of minion multiprocessing option on this change, if any?

Excellent question. As you will notice, there are very different code paths for when the multi-processing logging listener is running and when it is not. It isn't running when multiprocessing is False and there are no Engines (in which case it runs in a special optimized single process mode). I locally tested both cases (currently we use single process mode to cut down on memory usage, but we understand that we need to ensure that the standard case works as well).

[cachedout]

I agree that the proper case for this is Windows. I'm not terribly excited to introduce log rotation for other platforms, especially given the availability of third-party tools which handle rotation elegantly. This has been discussed a number of times already in other GH issues.

@s0undt3ch Would you mind taking a look here as well before we get this in?

[isbm]

It supposed to be a subject to a garbage collector, no need to delete this. Also t, v, tb can be None. Also t, v and tb could have a better variable names, at least three characters.

[skizunov]

The variable names are exactly the same as used in Python 3.5's built in code as well as the del behavior. This code was based on Python 3.5's built-in code since it aims to do something similar. That code may be found in logging/__init__.py: Handler.handleError(). If you look there, you will see a striking similarity.

[isbm]

That's fine, but in Salt we actually are trying not to use one char vars. And I still don't get why these needs to be del'ed. Using del in memory intensive calculations yes, but here?..

[skizunov]

Since we are overriding default Python behavior, I thought it would be prudent to do exactly what they do. I don't completely understand why they use del, but they do use it and I think it is safer to do exactly what they do since we are overriding what they usually would do.

[skizunov]

Normally, I would use more descriptive variable names, but this is an override to an existing built-in function and so I wanted to keep it as similar as possible to the original so that it would be easier to compare the two.

[isbm]

OK, I know why del in this case: since you assigned to the traceback return value to a local variable in a function that is handling an exception, that might cause a circular reference, although Python 2.2 can resolve this, however it is still recommended. I would still suggest to rename variables.

[skizunov]

@isbm : I pushed a new commit that renames the variables and also adds a comment as to why the 'del' is necessary.

[isbm]

@skizunov Saw that, replied below, thanks! Not really necessary but rather recommended, as GC will eventually remove them. You do not refer these variables anywhere else anyway. But that's OK.

[isbm]

@cachedout I would vote against this. Because Windows has log rotation for ages. Or tools, like logrotatewin.

My point is, this is up to the OS admin how to rotate the logs.

[skizunov]

@isbm : The log rotation that you are referring to is in the Windows Event Viewer. Salt does not log to this mechanism and instead opts to use its own log files. When using your own log files, I do not believe there is any built-in log rotation in Windows.

[cachedout]

I am not a fan of applications doing their own log rotation normally but in this case, @skizunov is correct. IMHO, this should be merged.

[skizunov]

@isbm : I have examined 3rd party tools such as logrotatewin before working on this code. logrotatewin will not work if the log file is currently open (for reasons I already described above), which is the primary use case of ours since we want logs to be rotated while Salt is running.

[isbm]

@skizunov @cachedout Well, but how about logrotatewin and logwot8? I think this is better that trying to fix the world where we should not, unless we want to be another Tomcat.

[skizunov]

@isbm : I already talked about logrotatewin not being adequate. logwot8 will only work in the cygwin subsystem that emulates Linux behavior. We don't run Salt in cygwin. Neither is adequate. Please re-read earlier posts that describe why, in general, no 3rd party log rotation is adequate on Windows due to differences in Windows filesystem behavior vs other OSes. I think I already explained this thoroughly.

If you have a reason why the underlying theory presented of why external logrotate tools can't work on Windows is flawed, I am all ears.

[isbm]

Ah, sorry, didn't see your post. Well, that's sad. And I would agree with you that this is not necessary for non-Windows. OK, than I don't have any objections in this case.

[isbm]

P.S. Except the code comment I've made. 😆

[isbm]

@skizunov LGTM, thanks.

[s0undt3ch]

👏

[cachedout]

Thank you, everyone, for the robust discussion. This is now merged. :]

[yur4enko]

When will it roll to release?

[cachedout]

@yur4enko This will be in the next major release of Salt, due sometime this spring.

[yur4enko]

@cachedout Good to hear it, thanks

[beakerman29]

Just bumping to see if there is an anticipated release date for this.

[Hitamashi]

Sorry, but do you have any plan to release this PR?

[rallytime]

@Hitamashi This has already been released in the 2017.7.x and 2018.3.x releases.

[Hitamashi]

@rallytime I can not find any docs related to this PR so I have assumed it is not released. Anyway, thank you.