xref: /third_party/libwebsockets/READMEs/README.logging.md

# lws logging

# `lwsl_` logging apis

LWS has traditionally provided logging arrangements that are not indirected
through the lws context, because logging may be needed before and after the
context existence.  For that reason the original logging arrangements are
processwide.

By default the logs are emitted on stdout, but this can be overridden
using `lws_set_log_level()` and either syslog (provided by `lwsl_emit_syslog()`)
or custom log emission is possible if you point it to your own.

Currently the following log levels are defined

|name|function|release|meaning|
|---|---|---|---|
|`LLL_ERR`|`lwsl_err()`|y|Serious operation errors anyone needs to know|
|`LLL_WARN`|`lwsl_warn()`|y|Operation errors you may need to know|
|`LLL_USER`|`lws_user()`|y|Information user code wants you to know|
|`LLL_NOTICE`|`lwsl_notice()`|y|Information about what lws is doing useful for logging|
|`LLL_INFO`|`lwsl_info()`|n|Detailed information about what lws is doing|
|`LLL_DEBUG`|`lwsl_debug()`|n|Very detailed information about what lws is doing|
|`LLL_PARSER`|`lwsl_parser()`|n|Very detailed information about parsing|
|`LLL_HEADER`|`lwsl_header()`|n|Very detailed information about header processing|
|`LLL_EXT`|`lwsl_ext()`|n|Very detailed information about ws extensions|
|`LLL_CLIENT`|`lwsl_client()`|n|Very detailed information about client connections|
|`LLL_LATENCY`|`lwsl_latency()`|n|detailed latency stats|
|`LLL_THREAD`|`lwsl_thread()`|n|detailed threadpool information|

The first four log levels are built into lws even on Release builds, the others
are only built in Debug builds.

You can select between Debug and Release builds using cmake `-DCMAKE_BUILD_TYPE=`
`DEBUG` or `Release`

`lws_set_log_level()` is used to OR together the logging bitfields you want to
see emitted, only log levels that were built in can be enabled since the code for them
is just not there otherwise.

## Finegrained control of log level build

You can deviate from the default log inclusion for release / debug by overriding it
at cmake, using `LWS_LOGGING_BITFIELD_SET` and `LWS_LOGGING_BITFIELD_CLEAR`.

For example you can set `-DLWS_LOGGING_BITFIELD_SET="LLL_INFO|LLL_DEBUG"`, which will
cause those log level traces to be built in even in Release mode.  Clear works
similarly to defeat build of specific log levels.

## Object tags in lws

Commonly logging wants to refer to an object in a repeatable way, the usual way to
do this is with `%p` to print the object pointer.  But this has a couple of drawbacks,
first the same memory may be freed and reallocated for a different instance of the same
or another object, causing confusion, and second when multiple processes are allocating
objects and logging, the same address may be allocated in different process also causing
confusion.

Lws has introduced unique tag strings to refer to object identity in logging instead, these
contain various information such as a 64-bit ordinal for the group the object belongs
to that won't repeat even if reallocated to the same address (until 2^64 allocations,
anyway).

Tags are fixed at object creation time for the whole object lifetime, although in some
cases the tag may be appended to... accepted server wsis for example don't have much
information available to form the tag until they start to indicate what they want to
do.

At their simplest the tags look like this (in a log indicating creation)

```
[2020/12/27 08:49:19:2956] N:  ++ (4) [wsi|5|h2]
```

It means a wsi has been created with the tag `[wsi|5|h2]`, and after that, there are 4
active objects in the wsi group.

The corresponding object destruction log with the tag is

```
[2020/12/27 08:49:24:4226] N:  -- (3)   5.126s [wsi|5|h2]
```

it indicates the object's tag, that it lived for 5.126s and after its destruction,
there are 3 objects in its group left.

### Compound tags

If the object has bindings, the tag can reflect that, eg

```
[2020/12/27 08:49:19:4787] N:  ++ (2) [wsiSScli|6|d_h1]
[2020/12/27 08:49:19:4793] N:  ++ (2) [wsicli|6|GET/h1/httpbin.org/([wsiSScli|6|d_h1])]
```

the first log is describing a proxied SS client connection at the proxy, and the second
is a wsi bound to the SS object from the first log to do the outgoing client action.

## Tags in user code

When user code wants to refer to a tagged object like a wsi or vhost, there are helpers
that return a `const char *` containing the tag

|tag accessors|
|---|
|`lws_wsi_tag(wsi)`|
|`lws_vh_tag(vh)`|
|`lws_ss_tag(h)`|

# New logging context apis

From v4.3 on lws additionally provides wrappers that issue logs into a
"log context" object, one of these is embedded in the lws_context, lws_vhost,
wsi, ss and sspc handles.  These follow the same general approach as before, but
allow logs to be issued in "the context" of any of those objects, and to fall
back sanely if the object pointer is NULL.

The traditional process scope logs and emit management remain available as
before, and if you do not set custom log contexts, the new log apis use the
processwide log context emit and mask as before too.

Here's a summary of the differences:

|Traditional process scope logs|New log context apis|
|---|---|
|Single processwide log context|Defaults to processwide, but object can use custom log contexts|
|Single processwide emit function|Emit function per log context|
|Single processwide log mask|log mask is in log context, objects can be bound to custom log contexts at creation time|
|Require trailing `\n` in format|Trailing `\n` added if not present|
|Manual `__func__`|`__func__` added in wrapper macros automatically|
|Manual tag addition|Object tag prepended automatically|
|No hierarchy|Log contexts may refer to parent log contexts, which may prepend to child logs|
|Macros per level (eg, `lwsl_err(...)`)|Macros per object type / level (eg, `lwsl_wsi_err(wsi, ...)`)|

In addition to being able to control the emit function and log level for
individual log contexts, eg, for a particular wsi, the log functions understand
how to prepend object-specific information such as tags and `__func__`
automatically.  They also do not need a trailing `\n` in the format string.  So
the new context aware logs remove boilerplate from the logging calls while
making the log information more consistent.

So comparing this kind of logging the processwide and log context aware ways:

```
[2021/06/25 09:39:34:7050] N: [669282|wsicli|4|GET/h1/libwebsockets.org|default]: _lws_generic_transaction_completed_active_conn:  ...
```

|Type|Example code|
|---|---|
|Process scope apis|`lwsl_notice("%s: %s: mylog %d\n", __func__, lws_wsi_tag(wsi), n);`|
|New log context apis|`lwsl_wsi_notice(wsi, "mylog %d", n);`|

The log context / object-aware apis do not replace the processwide logging but
augment it, and the new apis default to use the original processwide emit
function and log mask, so the behaviours are the same.  The original processwide
log apis themselves are unchanged.

At lws_context creation time, you can set the context info `.log_cx` to a user
defined log context which is inherited by objects created in that lws_context by
default.  Vhost creation, wsi creation and ss / sspc creation all allow passing
a user log_cx to customize how logs for that object are handled.

## Using the new logging apis

This table describes the different ways to issue an ERROR verbosity log, it
works the same for info, notice, warn, etc.

|Scope|Api example|Functionality|
|---|---|---|
|Old, Processwide|lwsl_err(...)|Traditional processwide error log|
|lws_context|lwsl_cx_err(context, ...)|error log bound to lws_context|
|lws_vhost|lwsl_vhost_err(vh, ...)|error log bound to lws_vhost|
|lws_wsi|lwsl_wsi_err(wsi, ...)|error log bound to wsi|
|lws_ss|lwsl_ss_err(handle, ...)|error log bound to secure stream|

Similarly hexdumps can be bound to different log contexts

|Scope|Api example|Functionality|
|---|---|---|
|Old, Processwide|lwsl_hexdump_err(...)|Traditional processwide error hexdump|
|lws_context|lwsl_hexdump_cx_err(context, ...)|error hexdump bound to lws_context|
|lws_vhost|lwsl_hexdump_vhost_err(vh, ...)|error hexdump bound to lws_vhost|
|lws_wsi|lwsl_hexdump_wsi_err(wsi, ...)|error hexdump bound to wsi|
|lws_ss|lwsl_hexdump_ss_err(handle, ...)|error hexdump bound to secure stream|

## Creating and using custom log contexts

The log context object is public, in `libwebsockets/lws-logs.h`, currently it
is like this

```
typedef void (*lws_log_emit_t)(int level, const char *line);
typedef void (*lws_log_emit_cx_t)(struct lws_log_cx *cx, int level,
				  const char *line, size_t len);
typedef void (*lws_log_prepend_cx_t)(struct lws_log_cx *cx, void *obj,
				     char **p, char *e);
typedef void (*lws_log_use_cx_t)(struct lws_log_cx *cx, int _new);
typedef struct lws_log_cx {
	union {
		lws_log_emit_t		emit; /* legacy emit function */
		lws_log_emit_cx_t	emit_cx; /* LLLF_LOG_CONTEXT_AWARE */
	} u;
	lws_log_use_cx_t		refcount_cb;
	/**< NULL, or a function called after each change to .refcount below,
	 * this enables implementing side-effects like opening and closing
	 * log files when the first and last object binds / unbinds */
	lws_log_prepend_cx_t		prepend;
	/**< NULL, or a cb to optionally prepend a string to logs we are a
	 * parent of */
	struct lws_log_cx		*parent;
	/**< NULL, or points to log ctx we are a child of */
	void				*opaque;
	/**< ignored by lws, used to pass config to emit_cx, eg, filepath */
	void				*stg;
	/**< ignored by lws, may be used a storage by refcount_cb / emit_cx */
	uint32_t			lll_flags;
	/**< mask of log levels we want to emit in this context */
	int32_t				refcount;
	/**< refcount of objects bound to this log context */
} lws_log_cx_t;
```

The emit function is a union because the traditional logs and the old emit
functions are also implemented using the new log contexts internally.  For
new log context-aware code, you would use `.u.emit_cx` and set the flag
`LLLF_LOG_CONTEXT_AWARE` on `.lll_flags`.

Lws also exports some common emit and refcount functions so you don't have to
reinvent the wheel

|Dest|emit member|`.lll_flags`|emit|`.refcount_cb`|`.opaque`|
|---|---|---|---|---|---|
|stderr|`.u.emit`|-|`lwsl_emit_stderr`|NULL|NULL|
|file|`.u.emit_cx`|`LLLF_LOG_CONTEXT_AWARE`|`lws_log_emit_cx_file`|`lws_log_use_cx_file`|`(const char *)filepath`|

For example, a custom log context that emits to a configurable file can be
declared like this (lws exports the needed helpers already)

```
static lws_log_cx_t my_log_cx = {
        .lll_flags      = LLLF_LOG_CONTEXT_AWARE |
                          LLL_ERR | LLL_WARN | LLL_NOTICE | LLL_USER,
        .refcount_cb    = lws_log_use_cx_file,
        .u.emit_cx      = lws_log_emit_cx_file,
        .opaque	        = "/tmp/mylogpath.log" /* also settable at runtime */
};
```

To bind the lws_context to this log context, set `log_cx` in the context
creation info struct

```
	info.log_cx = &my_log_cx;
```

### Log context hierarchy

Log contexts may also point to a parent log context... the top level log context
defines the emit function to be used, but parent log contexts are consulted by
calling their prepend function if any, to annotate logs with information from
parent levels.

### Log context prepend function

Logs contexts may define a "prepend" function callback, that knows how to
represent the object in a brief string to be prepended to other logs.  For
example the wsi-aware log context layer knows how to provide the wsi tag
when called.

Prepend functions should add `:<space>` after their output, if any, since these
will appear before the start of other logs.

### Log context opaque member

The `.opaque` member is available for passing in configuration to the emit and
refcount_cb members.  Lws does not use this itself at all.

### Log context refcounting

An expected use for custom log contexts is emitting to a specific file, and
then binding one or more objects to that log context.  Since it's too expensive
to keep opening and closing the output file per log, it means we need to know
when we bind to the first object and unbind from the last, so we can keep the
file handle open.

For this reason the log contexts have a refcount, and an opaque `void *stg`
availble for the emit and refounct_cb to use how they see fit, eg, for storing
the output log file descriptor.