Kolibri: Update logging + implement log rotation

[benjaoming]

Observed behavior

When kolibri starts, the following message is received:

INFO     Going to daemon mode, logging to /home/benjamin/.kolibri/server.log

However server.log is not the main log anymore.

Currently, we have:

• kolibri.log for general INFO level from Python
• debug.log for general DEBUG level (if switched on?)
• server.log for crash outputs when deamonized

Related issue: Icecube logging is noisy #2212

Changes to this have to be consolidated with docs.

Expected behavior

I would suggest the following naming for an easier user experience and for UIs that want to integrate a log view (highly recommended)

• log/daemon.log for sporadic crash output produced by the daemon and uncaught by other loggers
• log/kolibri.log for the latest log output
• log/kolibri-YYYY-MM-DD.log for log rotation (dates provided kindly by built-in log rotation, see KA Lite)
• log/debug.log for the latest debug output, not rotated to avoid accumulating huge logs

Icecube issue: Possibly solved by only logging Icecube progress etc. as debug output and accepting that it's noisy.

User-facing consequences

Makes it easier to dig out logs and finalizes how we want to do logging so we don't have to change it further down the road.

Readiness for UI implementation.

Means we can also amend the issue template regarding where to find the logs.

Updates

• ~Changed file extensions from .log to .txt -- will make it easier for users on Windows to open the files~. Moved: Follow-up from https://github.com/learningequality/kolibri/issues/2512
• ~Suggestion to put rotated log files in log/archive/ to reduce user confusion~ Not easy to implement, needs modification of built-in Python logging class.

[lyw07]

One question I have is about the log/daemon.log. We currently don't make the process in macosx go daemon, so the name daemon.log may not cover all the platforms we have.

Never mind. I think I misunderstood the question.

[rtibbles]

I wonder if it would be helpful to have a single log file, but then add rotation?

[lyw07]

@rtibbles do you mean getting rid of the server.log file?

[rtibbles]

Yeah, given that server.log doesn't contain much, I'm not sure I see a reason for keeping it separate, as long as the log messages are clearly differentiated?

[lyw07]

Thank you! I think one thing different from server.log and kolibri.log is that kolibri.log does not contain the stderr messages as server.log? I'm wondering if @benjaoming has some thoughts on this.

[rtibbles]

Yeah - this was mostly some input based on my experience trying to get logs from people - normally one of the log files gets forgotten because there are two :)

[indirectlylit]

definitely agreed on a single file. even as an "advanced user" I've never understood the difference, and never know where to look.

[lyw07]

makes sense to me. I will merge the two log files into one kolibri.log and add rotation based on days.

[benjaoming]

The current logging is error-prone, the intention of how to design logging is in the issue description :arrow_double_up:

@lyw07 rotation also has options for log length IIRC, so we could rotate based on some different parameters.

Regarding the talk of a single log, be mindful that logging is initiated at a certain point in our load stack and we want to probably keep the daemon.log for other purposes. I think this is related to the way that Windows handles file objects. See the first set of error messages here: https://github.com/learningequality/kolibri-installer-windows/issues/76#issuecomment-488579820

As suggested, I would locate all the log files in a sub-directory log, making it easier for users on Windows to spot that a file is a log file, since the file extension .log probably gives them issues understanding the file. I'd also suggest to use .txt as extension instead (amending the issue description).

[benjaoming]

Oh a perhaps related issue @lyw07 -- it would seem it might be convenient to implement now -- I would like to add this issue in the mix, since it might provide more value to the daemon.txt log: https://github.com/learningequality/kolibri/issues/4652

[rtibbles]

I think as far as possible we should put stuff into a single file - for the user related issue I highlight above.

We should only put stuff into separate files if there are systematic, unresolvable technical issues that prevent this, as @benjaoming suggests above.

Agree with logging from commands - but couldn't that still go into the main log file?

[lyw07]

Thank you @benjaoming I will change the extension to .txt and put the files in a specific log directory based on your issue description.
I will also look into putting command outputs into log file.

I agree with @rtibbles that it may be better to put the logs into a single file from a user's perspective.
Similarly, I feel that rotating the log file based on the date, like what we do in KA Lite, seems to be easier for users to understand and for us to debug issues than based on log length.
Thanks!

[benjaoming]

Agree with logging from commands - but couldn't that still go into the main log file?

Sure! But it should ALSO go into log/daemon.txt such that we know what is being run in case of crashes.

[benjaoming]

Similarly, I feel that rotating the log file based on the date, like what we do in KA Lite, seems to be easier for users to understand and for us to debug issues than based on log length.

Ah yes, sorry, I thought that the time-based and size-based behaviors could be combined. I agree @lyw07 to just use TimedRotatingFileHandler

[lyw07]

For the command logging, do we just want to see what commands the users have invoked, or a bit beyond that, the output of the commands?

[rtibbles]

I think capturing their logging output would be useful too.

[benjaoming]

It's a bit dangerous to log/intercept the stdout of a command because it can potentially interfere with streaming output to other pipes... or I dunno, it's just Windows would seem to be a big reason to keep things really simple :)

[rtibbles]

Right - not their stdout, but if they are using logging statements, shouldn't it get captured by our logging?

[benjaoming]

@rtibbles yes, that would be nice :)

[lyw07]

For the rotation filenames, is it okay that we keep the default name log/kolibri.txt.YYYY-MM-DD instead of log/archive/kolibri-YYYY-MM-DD.txt?

we can definitely change the name to log/archive/kolibri-YYYY-MM-DD.txt, but that will require creating a custom handler class and overriding the methods of the TimedRotatingFileHandler. For example, to determine which rotation files to delete when the number of backups exceeds the number we set and when do the rollover.

[rtibbles]

I guess the only issue is the windows concern where not having a .txt extension is difficult because it won't show/open in text messages by default?

[indirectlylit]

Right. at that point we might as well use kolibri-log-YYYY-MM-DD or something.

Recommend opening a follow-up issue to add the .txt extension, since ~it's out of scope of this issue~ the most important thing is log rotation.

[benjaoming]

I don't think @lyw07 meant that the .txt extension was the issue, but that the archive/ sub directory was? But I get that it would mean to move existing log files and update documentation, so fine to skip for now.

[rtibbles]

I am pretty sure that renaming the log files to all end in . txt is the issue, as the current log handler relies on the last part of the name to identify the historical logs? Obviously, surmountable, but not trivial necessarily.

[benjaoming]

@rtibbles I've updated the description and opened a new issue about the whole extension thing :)

[lyw07]

thanks! the main issue I mentioned above is related to the rotation filename. By default, the rotation filename will be kolibri.log.YYYY-MM-DD. If we want to change it to kolibri-YYYY-MM-DD.log or .txt, we will need to overwrite some functions in TimedRotatingFileHandler.

Changing kolibri.log to kolibri.txt can be done by changing the definition of it and updating the documentation. I was mainly hesitated about whether we would like to override the methods of the logging handler to change the name of the rotation file to kolibri-<YMD>.extension from kolibri.extension-<YMD>.

[benjaoming]

@lyw07 sounds good if you think it's uncomplicated -- I think we can manage any follow-up documentation migration of existing log files, too :)

[benjaoming]

This slipped my radar: The milestone here is 0.12.4 and the PR was targeted for 0.12.x -- I don't think that we should change locations of the log files in a patch release. That's way beyond what a patch release should do. Implementing log rotation would pass as a kind of important bug fix (to avoid eternally appending the log and consuming disk space).

[indirectlylit]

Note that 0.12.4 is not a normal patch release. It includes new features, updated translation strings, and a complete integration testing pass

[indirectlylit]

the PR was targeted for 0.12.x

0.12.y, not 0.12.x

[benjaoming]

I concede that I found the patch release confusing and haven't understood quite what the scope of 0.12.4 was, but let's get this improvement out there to the users :ship: