Logging

From CRIU
Revision as of 12:05, 5 February 2020 by Dsafonov (talk | contribs) (Add some drops about early logging)
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to navigation Jump to search

Overview

When run CRIU can generate a lot of messages. By default CRIU only prints only critical messages on the screen, but using only these messages can make debugging impossible. On the other hand, increasing the verbosity can easily flood the output.

Verbosity

There are 4 types of messages CRIU can print

Errors
These show that something goes really wrong. If an error message appears on the screen CRIU doesn't complete the operation and exits with an error. At the same time, if CRIU's exit code is not 0, there should be an error message. Typically there are several of them, but only the first one denotes the real obstacle CRIU has hit, all subsequent ones can be due to this first.
Warnings
These are printed if something goes not the way CRIU expects, but still there's a way to handle the situation. Sometimes warnings show that the kernel functionality might not be enough to perform the requested operation, but whether or not it will be really required will be found out later.
Info-s
These are just messages with which CRIU shows what it's doing and why.
Debug
Debug messages show some technical details about CRIU workflow.

Log message

Messages have specific format.

Timestamps
Some lines start with numbers in brackets (like this (12.345678)) which denote the time in msec-s passed since CRIU start
PIE
Code blobs have troubles generating sane logs and precede lines with the pie: prefix
PID-s
Log lines generated by non-CRIU processes (during restore) show their pids right after timestamp and/or PIE prefix in the PID: format.

Below are examples of all these types of messages

(00.000116) Version: 2.6 (gitid v2.6-205-ga66ed95)         # CRIU message
(00.004837)     39: Restoring 39 to 39 sid                 # Message from process 39
pie: 39: Switched to the restorer 39                       # Message from PIE-context of process 39

Controlling the verbosity

The messages to be printed by CRIU are controlled by -v option. There are two ways of using it.

The first is to specify as many -v's as high level you want. One -v means there will be only errors printed, 4 -v's (-vvvv or -v -v -v -v) will make CRIU print everything.

The second option is to specify the log level with the number, e.g. -v3 will make CRIU print errors, warnings and info-s, but not debugs (which are of log level 4).

Telling -v0 will shut CRIU up, but that's really not recommended.

Early logging

During CRIU initialization some things can fail, i.e., reading the kerndat file. Those failures may happen before the logging is set up (log file descriptors open etc.). The failures might even happen while setting up the logging. For all those nuisances, there is a static buffer that stores everything until logging has successfully initialized. The buffer has compile-time size of EARLY_LOG_BUF_LEN and serves only on early CRIU initialization. Afterwards, it always flushes: if the logging was set up successfully, to the corresponding logs; to stderr in case CRIU caught early fault and is about to exit.

Log files

If requesting high log level you can get tons of logs on the screen. It's usually unwanted and hard to save (for further analyzes), so it's possible to ask CRIU write the logs into a log file. This is done by --log-file option. The log file will be created and truncated in the working directory, all messages will appear in it.

Per-pid logs

During restore, log entries are emitted for each process being restored. To make logs analysis easier, one can make CRIU generate separate per-process log files by using --log-pid option.

See also