Minimalistic Logging Facade ​

cds.log (id?, options?) ​

Returns a logger identified by the given id.

const LOG = cds.log('sql')
LOG.info ('whatever', you, 'like...')

Arguments ​

• id? — the id for which a logger is requested — default: 'cds'
• options? — alternative to level pass an options object with:
  • level? — the log level specified as string or number — default: 'info'
  • label? — the log label to add to each log output — default: id
• level? — specify a string instead of options as a shorthand for {level}

// all following are equivalent...
const LOG = cds.log('foo', 'warn')  //> shorthand for:
const LOG = cds.log('foo', { level: 'warn' })
// including case-insensitivity...
const LOG = cds.log('foo', 'WARN')  //> shorthand for:
const LOG = cds.log('foo', { level: 'WARN' })

Logger id — cached & shared loggers ​

The loggers constructed by cds.log() are cached internally, and the same instances are returned on subsequent invocations of cds.log() with the same id. This allows to use and share the same logger in different modules.

const LOG1 = cds.log('foo')
const LOG2 = cds.log('foo')
console.log (LOG1 === LOG2) //> true

Logger label — used to prefix log output ​

By default, each log output is prefixed with [<id>] -, for example, as in [cds] - server listening . Sometimes you may want to use different ids and labels. Use option label to do so as in this examples:

const LOG = cds.log('foo',{label:'bar'})
LOG.info("it's a foo")
//> [bar] - it's a foo

Logger usage → much like console ​

Loggers returned by cds.log() look and behave very much like Javascript's standard console object a log method for each log level:

cds.log() → {
  trace(...), _trace,
  debug(...), _debug,
  info(...),  _info, log(...), // alias for info()
  warn(...),  _warn,
  error(...), _error,
}

In addition, there is a boolean indicator to check which levels are active through corresponding underscored property, for example, LOG._debug is true if debug is enabled.

Recommendations ​

1. Leave formatting to the log functions — for example don't expensively construct debug messages, which aren't logged at all if debug is not switched on. For example:

   js

   // DONT:
   const { format } = require('util')
   LOG.debug (`Expected ${arg} to be a string, but got: ${format(value)}`)
   // DO:
   LOG.debug ('Expected', arg, 'to be a string, but got', value)

2. Check levels explicitly — to further minimize overhead you can check whether a log level is switched on using the boolean Logger._<level> properties like so:

   js

   const LOG = cds.log('sql')
   LOG._info && LOG.info ('whatever', you, 'like...')

cds.log.format ​

Setting Formats for New Loggers ​

You can provide a custom log formatter function by setting cds.log.format programmatically as shown below, for example in your custom server.js.

// the current default:
cds.log.format = (id, level, ...args) => [ `[${id}]`, '-', ...args ]

// a verbose format:
const _levels = [ 'SILENT', 'ERROR', 'WARN', 'INFO', 'DEBUG', 'TRACE' ]
cds.log.format = (id, level, ...args) => [
  '[', (new Date).toISOString(),
  '|', _levels[level].padEnd(5),
  '|', cds.context?.tenant || '-',
  '|', cds.context?.id || '-',
  '|', id, '] -', ...args
]

Formatter functions are expected to return an array of arguments, which are passed to the logger functions — same as the arguments for console.log().

Setting Formats for Existing Loggers ​

You can also change the format used by newly or formerly constructed loggers using .setFormat() function:

const _levels = [ 'SILENT', 'ERROR', 'WARN', 'INFO', 'DEBUG', 'TRACE' ]
const LOG = cds.log('foo') .setFormat ((id, level, ...args) => [
  '[', (new Date).toISOString(),
  '|', _levels[level].padEnd(5),
  '|', cds.context?.tenant || '-',
  '|', cds.context?.id || '-',
  '|', id, '] -', ...args
])

cds.log.levels ​

Constants of supported log levels:

cds.log.levels = {
  SILENT: 0,    // all log output switched off
  ERROR: 1,     // logs errors only
  WARN: 2,      // logs errors and warnings only
  INFO: 3,      // logs errors, warnings and general infos
  DEBUG: 4,     // logs errors, warnings, info, and debug
                // (and trace when using default logger implementation)
  TRACE: 5,     // most detailed log level
  SILLY: 5,     // alias for TRACE
  VERBOSE: 5    // alias for TRACE
}

You can use these constants when constructing loggers, for example:

const LOG = cds.log('foo', cds.log.levels.WARN)

Configuring Log Levels ​

Configure initial log-levels per module through cds.env.log.levels, for example like that in your package.json:

{
  "cds": {
    "log": {
      "levels": {
        "sqlite": "debug",
        "cds": "info"
      }
    }
  }
}

Learn more about cds.env.

See pre-defined module names below.

Programmatically Set Log Levels ​

You can specify a default log level to use when constructing a logger as shown above. When called subsequently with a different log level, the cached and shared logger's log level will be changed dynamically. For example:

// some-module.js
const LOG = cds.log('foo') // using default log level 'info'

// some-other-module.js
const LOG = cds.log('foo') // shares the same logger as above

// some-controller-module.js
cds.log('foo','debug') // switches the 'foo' logger to 'debug' level

cds.log.Logger ​

Constructs a new logger with the method signature of { trace, debug, log, info, warn, error } (cf. console). The default implementation maps each method to the equivalent methods of console.

You can assign different implementations by exchanging the factory with your own, for example, in order to integrate advanced logging frameworks such as winston.

Arguments ​

• label— the log label to use with each log output, if applicable
• level— the log level to enable → 0=off, 1=error, 2=warn, 3=info, 4=debug, 5=trace

Using winston Loggers ​

Prerequisites: You need to add winston to your project:

npm add winston

Being designed as a simple log facade, cds.log can be easily integrated with advanced logging frameworks such as winston. For example, using the built-in convenience method cds.log.winstonLogger() in your project's server.js like that:

cds.log.Logger = cds.log.winstonLogger()

You can specify winston custom options to that method as documented for winston.createLogger(), for example like that:

cds.log.Logger = cds.log.winstonLogger({
  format: winston.format.simple()
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({
      filename: 'errors.log',
      level: 'error'
    })
  ],
})

Custom Loggers ​

Custom loggers basically have to return an object fulfilling the console-like cds.log loggers API as in this example:

const winston = require("winston")
const util = require('util')
const cds = require('@sap/cds')
cds.log.Logger = (label, level) => {
  // construct winston logger
  const logger = winston.createLogger({
    levels: cds.log.levels, // use cds.log's levels
    level: Object.keys(cds.log.levels)[level],
    transports: [new winston.transports.Console()],
  })
  // winston's log methods expect single message strings
  const _fmt = (args) => util.formatWithOptions(
    {colors:false}, `[${label}] -`, ...args
  )
  // map to cds.log's API
  return Object.assign (logger, {
    trace: (...args) => logger.TRACE (_fmt(args)),
    debug: (...args) => logger.DEBUG (_fmt(args)),
    log:   (...args) => logger.INFO  (_fmt(args)),
    info:  (...args) => logger.INFO  (_fmt(args)),
    warn:  (...args) => logger.WARN  (_fmt(args)),
    error: (...args) => logger.ERROR (_fmt(args)),
  })
}

Actually, the above is essentially the implementation of cds.log.winstonLogger().

DEBUG env variable ​

Use env variable DEBUG to quickly switch on debug output from command line like that:

DEBUG=app,sql cds watch
DEBUG=all cds watch

Values can be

• comma-separated list of logger ids, or
• the value all to switch on all debug output.

Matching multiple values of DEBUG ​

When obtaining loggers with cds.log() you can specify alternate ids that will all be matched against the entries of the DEBUG env variable; for example:

const LOG = cds.log('db|sql')

Will be debug-enabled by both, DEBUG=db, as well as DEBUG=sql ....

Note: The alternative ids specified after | have no impact on the unique logger ids. That is, the logger above will have the id 'db', while 'sql' will only be used for matching against DEBUG env variable.

Capture stack trace with SQLite ​

Set DEBUG=sqlite to activate capturing the stack trace on the way to executing a query.

Configuration ​

Configuration for cds.log() can be specified through cds.env.log, for example like that in your package.json:

{
  "cds": {
    "log": {
      "levels": {
        "sqlite": "debug",
        "cds": "info"
      }
    }
  }
}

Learn more about cds.env.

The following configuration options can be applied:

• levels — configures log levels for logged modules. The keys refer to the loggers' id, the values are lower-case names of log levels.

• user — Specify true to log the user's ID (req.user.id) as remote_user (Kibana formatter only). Consider the data privacy implications! Default: false.

• sanitize_values— Specify false to deactivate the default behavior of sanitizing payload data in debug logs in production. Default: true.

Common IDs ​

The runtime uses the same logger facade, that is cds.log(). For each component, it requires a separate logger. So projects can set different log levels for different components/layers. The following table lists the ids used to set the log levels:

Logging in Development ​

During development, we want concise, human-readable output in the console, with clickable stack traces in case of errors. You should not be overloaded with information that is additionally obfuscated by a bad rendering. Hence, console.log(), that makes use of util.format() out of the box, with raw arguments is a good choice.

The default log formatter does exactly that, prepending the list of arguments with [<module> -]. The following screenshot shows the log output for the previous warning and rejection with the default log formatter.

Logging in Production ​

In production, DevOps typically consume application logs via dashboards such as Kibana or Grafana. Hence, the log output needs to be formatted in a way that enables the respective dashboard technology to optimally support the user, for example, filtering for logs of specific levels, modules, status, etc.

The Kibana-friendly log formatter constructs a loggable object from the passed arguments as well as cds.context and the headers of the incoming request (if available).

Kibana-friendly log formatting can be added using cds add kibana-logging. Alternatively, it can be activated via cds.env.features.kibana_formatter = true. In the future, the Kibana-friendly formatter will become the default when running in SAP BTP and bound to an instance of the SAP Application Logging Service for the Cloud Foundry Environment.

The following screenshot shows the log output for the rejection in the previous example with the Kibana-friendly log formatter.

Request Correlation ​

Unfortunately, there is no standard correlation ID header. x-correlation-id and x-request-id are the most commonly used, but SAP products often use x-correlationid (that is, without the second hyphen) and SAP BTP uses x-vcap-request-id when logging incoming requests.

As CAP aims to be platform independent, we check an array of headers (or generate a new ID if none hits) and ensure the value available at cds.context.id as well as req.headers['x-correlation-id']:

const { headers: h } = req
const id = h['x-correlation-id'] || h['x-correlationid']
  || h['x-request-id'] || h['x-vcap-request-id']
  || uuid()
if (!cds.context) cds.context = { id }
req.headers['x-correlation-id'] = cds.context.id

The following screenshot shows an example for log correlation in Kibana .