# Log - Console Logger This library is inspired by Java's `slf4j` and similar logging systems providing a simple console logger with the following features: * Consistent logging information * Configurable log level support from TRACE to FATAL * Configurable logging formats * Multiple logging formats * Basic logging * Color logging for WARN, ERROR and FATAL log levels * `syslog` compatible logging * JSON logging * slf4j-style parameterised messages * [Call line tracing](#call-line-tracing) * Customisable * Logging functions * Logging patterns ## Using the Logger The log message can be supplied in 2 formats: * String (`10h`) * Generic list (`0h`) * Supports [slf4j-style parameterised logging](http://www.slf4j.org/faq.html#logging_performance) - `{}` to indicate parameters within the log message to replace with the objects * Format: `("string with curly brackets for each object to print: {} {} (2)"; object-1; object-2)` * See [Parameterised Logging](#parameterised-logging) below for more detail It is recommended to use the generic list when passing objects to print. There is a signficant performance improvement when logging is disabled for the level. An example informational message: ```q / Basic string logging q) .log.info "An info message" 2017.03.06 15:23:41.453 INFO pid-14448 jasra_000 0 An info message / Parameterised logging q) .log.info ("A random symbol - {}"; rand `4) 2021.01.30 14:49:35.821 INFO pid-402 jas 0 A random symbol - milg ``` ## Configuring the Logger ### Log Format In its default mode, the library uses an optimised code path and logs with the following elements: * Date and time (`.time.today[]` and `.time.nowAsTime[]`) * Log level (one of `TRACE`, `DEBUG`, `INFO`, `WARN`, `ERROR`, `FATAL`) padded to 5 characters * Process identifier (`pid-*pid*` via `.log.process`) * Current user (`.z.u`) * Current handle (`.z.w`) A custom logging format can be specified if desired. Note the current limitations: * Each pattern must be prefixed with a `%` * All elements are always space separated unless a custom logger is used * Performance impact (see original [pull request](https://github.com/BuaBook/kdb-common/pull/54) for more details) * The pattern-based logger is ~10% slower (when logging the equivalent patterns as the original logger) * Adding the call line tracing (`%T`) pattern causes logging to be an additional ~130% slower This is done by setting `.log.cfg.format` with any of the following supported patterns: | Pattern | Prints | Using | | ------- | ------------------ | ----------------------------- | | `%d` | Current date | `.time.today[]` | | `%t` | Current time | `.time.nowAsTime[]` | | `%P` | Current timestamp | `.time.now[]` | | `%n` | Current timespan | `.time.nowAsTimespan[]` | | `%l` | Log level | Call specific | | `%p` | Process identifier | `.log.process` | | `%u` | Current user | ``{ `system ^ .z.u }`` | | `%h` | Current IPC handle | `.z.w` | | `%H` | Hostname | `.z.h` | | `%m` | Log message | Call specific | | `%T` | Call line trace | `.log.patterns.callLineTrace` | For example, to use the pattern-based logger to log the same as the original logger: ```q .log.cfg.format:"%d %t %l %p %u %h %m"; .log.setLogger[]; ``` ### Log Levels By default when the log library is initialised, it defaults to `INFO`. If the process is started in _debug mode_, which is defined by using the `-e` command line argument, the level is set to `DEBUG`. The configured log level is printed when the library is initialised: ``` Logging enabled [ Level: INFO ] [ Current Logger: `.log.loggers.basic ] ``` You can use `.log.setLevel` to change it as necessary post initialisation. ### Logger Types The following loggers are supplied by default: * `.log.loggers.basic`: Simple space-separated logging * `.log.loggers.color`: Space-separated logging with color highlighting for WARN, ERROR and FATAL levels * `.log.loggers.syslog`: `syslog` compatible space-separated logging * `.log.loggers.json`: JSON formatted logging By default, the basic logger will be enabled but the other loggers can be selected by the following: * `.log.loggers.color`: If the environment variable `KDB_COLORS` or the command line argument `-logColors` is specified * `.log.loggers.syslog`: If the environment variable `KDB_LOG_SYSLOG` or the command line argument `-logSyslog` is specified * `.log.loggers.json`: If the environment variable `KDB_LOG_JSON` or the command line argument `-logJson` is specified For example, color output looks as follows: ![log.q Color Output](https://raw.githubusercontent.com/wiki/BuaBook/kdb-common/images/log-with-colors.png) ### Process Identifier By default, the process is identified by its PID, in the form `pid-*pid*`. However, you can change it any point to be more descriptive by setting `.log.process`: ``` q) .log.info "Hi" q).log.info "Hi" 2018.08.24 15:36:02.709 INFO pid-87646 jrajasansir 0 Hi q) .log.process:"myProcess" q) .log.info "Hi again" 2018.08.24 15:36:31.161 INFO myProcess jrajasansir 0 Hi again ``` ## Parameterised Logging The log library supports parameterised logging - whereby the objects to log are only stringified if the log line is actually going to emitted to standard out / standard error. Following the convention from slf4j, `{}` is used in the string message to signal where the stringified version of the objects should be inserted. You must ensure that the number of brace pairs matches the number of objects supplied after the string message. The log library does not validate this before attempting to log. The main advantage of switching to this mechanism is the performance improvement when the specified log level is disabled. For example - when logging a table to a disabled log level, the log line is executed ~99% faster than the previous version. More execution comparisons can be found in the original [pull request](https://github.com/BuaBook/kdb-common/pull/51). ## Call Line Tracing If the call line tracing pattern (`%T`) is added to a custom log format, each log line prints the location of where the log line was called (where possible). The call trace pattern logs as follows: ``` [*source-file*:*calling-function*(*function-definition-line-num*):*log-call-line-num*] ``` As an example, if this is enabled before loading the HTTP library: ```q / Enable call line tracing (%T) q) .log.cfg.format:"%P %l %T %m"; q) .log.setLogger[]; ... q) .require.lib`http; 2021.02.08D21:55:13.999369000 INFO [./kdb-common/src/require.q:.require.i.load(110):1] Loading library: http ... 2021.02.08D21:55:14.002061000 INFO [./kdb-common/src/require.q:.require.i.init(145):9] Library initialisation function detected [ Func: .http.init ] 2021.02.08D21:55:14.002107000 INFO [./kdb-common/src/http.q:.http.init(63):2] Querying environment variables for HTTP / HTTPS proxy settings 2021.02.08D21:55:14.002160000 INFO [./kdb-common/src/http.q:.http.init(63):11] Send user agent with HTTP requests enabled [ User Agent: kdbplus-4-2020.05.04-1772 ] 2021.02.08D21:55:14.002197000 INFO [./kdb-common/src/http.q:.http.init(63):15] HTTP compression with GZIP [ Available: yes ] 2021.02.08D21:55:14.002234000 INFO [./kdb-common/src/require.q:.require.i.init(145):24] Initialised library: http ``` ### Source File Truncation By default the `*source-file*` element of the call line tracing will be the full path of the file. Common prefixes can be added as strings to `.log.sourcePathExcludePrefixes`. If this is not set when the library is initialised, it will be set to `.require.location.root`. Example: ```q / No source prefix 2021.02.21 21:16:14.198 INFO pid-412 jas 0 [/home/jas/git/kdb-common/src/require.q:.require.i.load(110):1] Loading library: env 2021.02.21 21:16:14.198 INFO pid-412 jas 0 [/home/jas/git/kdb-common/src/require.q:.require.i.load@(120):1] Loading ./src/env.q / Default source prefix 2021.02.21 21:16:32.778 INFO pid-412 jas 0 [./src/require.q:.require.i.load(110):1] Loading library: slack 2021.02.21 21:16:32.778 INFO pid-412 jas 0 [./src/require.q:.require.i.load@(120):1] Loading ./src/slack.q ``` ## Adding Your Own Logger To add your own logger, you must modify the dictionary `.log.cfg.loggers`: 1. The key of the dictonary is a symbol reference to the logging function to use 2. The value of the dictionary is a function that determines when the function should be used NOTE: That the first function that returns true will be the logger selected. The logging function defined must accept the following 3 arguments: * `formatter`: Function that formats the log line and provides a list of string elements ready for printing * `fd`: The file descriptor to output the log line * `lvl`: The log level of the current message as a symbol (e.g. `` `INFO``) * `message`: The log message as a string Once the configuration dictionary has been modifed, call `.log.setLogger`. ### Example ``` / Ignore the formatter q) .jas.customLogger:{[formatter; fd; lvl; message] -1 " " sv ("Logging: ";string lvl;message) }; / Make .jas.customLogger the first entry in the config dictionary and always be used q) .log.cfg.loggers:(enlist[`.jas.customLogger]!enlist { 1b }),.log.cfg.loggers; q) .log.setLogger[]; Logging enabled [ Level: INFO ] [ Current Logger: `.jas.customLogger ] q) .log.info "A log message"; Logging: INFO A log message ``` ## Adding Your Own Formatter The formatter - which takes the log level and raw message and returns a list of strings - can be customised via `.log.cfg.formatters`. There are 2 formatter types: * `default`: Used in most cases * `pattern`: Used when a logging format pattern has been specified in `.log.cfg.format` Note that the parameterised logging format (`{}`) is implemented in the default formatters and should be copied in any custom formatters. ### Example ```q q) .require.libNoInit`log / Cheating for {} support q) .jas.customFormatter:{[lvl; message] (lvl; .Q.s1 message) }; q) .log.cfg.formatters[`default]:`.jas.customFormatter q) .require.lib`log