Skip to content

log.q

Jump to bottom
Jas Rajasansir edited this page Apr 13, 2022 · 8 revisions

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
  • Customisable
    • Logging functions
    • Logging patterns

Using the Logger

The log message can be supplied in 2 formats:

  • String (10h)
  • Generic list (0h)

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:

/ 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 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:

.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

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.

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:

/ 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:

/ 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) .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

Copyright (C) Sport Trades Ltd 2017 - 2020, John Keys and Jaskirat Rajasansir 2020 - 2024

Clone this wiki locally