Status | ACCEPTED |
---|---|
Stakeholders | |
Outcome |
|
Due date | |
Owner |
Background
To make logging process consistent across Iroha applications logging process should be introduced and logging format should be defined.
Action items
- Nikita Puzankov write RFC
- DevOps team - review it
- Nikita Puzankov move RFC to ADR
Problem
Unstructured logs are hard to monitor, analyze and process automatically.
- Logs should be printed to stdout and stderr.
- Log-level (verbosity) should be changeable in runtime, example: system signal (e.g., SIGUSR1, SIGHUP) to reread configs(env variable) and change the log-level.
Solution
Log macros can log function arguments and result, using https://tools.ietf.org/html/rfc5424 or newer. Nowadays de facto standard for log is JSON.
LEVEL DATE_TIME function_name[start]: arguments LEVEL DATE_TIME function_name[end]: result
Example:
DEBUG - 2020-08-04 08:09:40:759899847 - request[start]: DEBUG - 2020-08-04 08:09:40:759961514 - self = Client { public_key: PublicKey { digest_function: "ed25519", payload: "[1E, 0, 33, 8A, D, 96, B, B4, 4D, 9E, 7F, 3A, C1, 3C, A, 5D, 89, BF, 31, 8A, F8, 76, E2, FD, 15, 50, EE, 28, C5, EE, 9E, 63]" }, torii_url: "127.0.0.1:45371" },
Decisions
- Use tracing as a logging facade.
- Provide a `/configure` endpoint for changing the log-level at run-time. The request should be provided in terms of a JSON file.
- Each function should be instrumented to provide vital (determined on a case-by-case basis) information.
- Errors must be either handled, or logged as `warn` or `error` level messages.
- Use tracing_bunyan_formatter to provide efficient machine readable logging. The destination is set at run-time and log rotation is the administrator's responsibility.
- Fields and their values should be recorded directly, preferably (unless otherwise specified), using their names in the source code.
- Logging that is done unconditionally upon entering/exiting a function is given the TRACE level.
- Logging that is done upon completion of some or part of a function is given a DEBUG level or higher.
Concerns
- Implementation of loggers could affect performance (tracing is one of the fastest)
- Log rotation can become an issue.
Assumptions
- We do not depend on any implementation, only on format
Risks
- Format will be inefficient for automatic monitoring `[1;8]`
- Logging will slow down performance `[4;7]`
- Log messages format will not help in issues discovery `[2;8]`
7 Comments
Nikita Puzankov
Implementation inspired by https://github.com/tokio-rs/tracing/blob/master/tracing-attributes/src/lib.rs
Nikita Puzankov
As was discussed with Makoto Takemiyawe can adopt some existing library for this functionality.
Bulat Saifullin
Hi,
Nikita Puzankov
Thanks Bulat Saifullin, logs can contain multi-line messages for errors, all other messages are formated as one line.
Bulat Saifullin
Nikita Puzankov , can you show here the example of such log?
also multiline log should be easily distinguished, one solution is to start every log with number e.g date, every new line that started not from the number is the same event:
example:
Nikita Puzankov
These logs possible only if application crashes and was launched with `RUST_BACKTRACE=1` environment variable, so I think we have no easy way to work with it's format:
We do not produce such kind of logs from our application in usual cases (even when Internal Error occurs).
Is it okay to do not touch this case?
Bulat Saifullin
Yes, it's okay. let's just change the format, as I proposed, put the date at the beginning of the log, as you can see all strings in you example start from word (`test`, `note:` ) or space (` 0:`, ` at `), it will be easier to parse logs if real logs start from date.
DATE_TIME LEVEL function_name[start]: arguments
DATE_TIME LEVEL function_name[end]: result