 |
libwebsockets
Lightweight C library for HTML5 websockets
|
|
libwebsockets
Lightweight C library for HTML5 websockets
|
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.
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.
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)
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
it indicates the object's tag, that it lived for 5.126s and after its destruction, there are 3 objects in its group left.
If the object has bindings, the tag can reflect that, eg
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.
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) |
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:
| 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.
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 |
The log context object is public, in libwebsockets/lws-logs.h, currently it is like this
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)
To bind the lws_context to this log context, set log_cx in the context creation info struct
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.
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.
The .opaque member is available for passing in configuration to the emit and refcount_cb members. Lws does not use this itself at all.
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.
If you have a log that may be generated at a high rate under some conditions, you can use the rate-limiting log macros. These allow you to specify a minimum interval between emissions in microseconds, and they will automatically append (dropped u logs) with the count of suppressed logs if any were dropped.
You need to provide a lws_log_ratelimit_t object to hold the state.
If the log context is local to a specific object (e.g., a wsi or vhost), you can compose the lws_log_ratelimit_t type into your object. It only needs to be zero-initialized:
If the log context is global or applies to a specific code block rather than a specific object, you can use the helper macro LWS_RATELIMIT_DEFINE_STATIC() to define a static state variable:
There are rate-limited counterparts for every log level and scoping context. For example:
| Scope | Api example |
|---|---|
| Processwide | lwsl_ratelimit_err(&rl, 1000000, ...) |
| lws_context | lwsl_ratelimit_cx_err(&rl, 1000000, context, ...) |
| lws_vhost | lwsl_ratelimit_vhost_err(&rl, 1000000, vh, ...) |
| lws_wsi | lwsl_ratelimit_wsi_err(&rl, 1000000, wsi, ...) |
| lws_ss | lwsl_ratelimit_ss_err(&rl, 1000000, handle, ...) |
Two things happen to every log line that passes the level filter, before it reaches the emit function.
A line identical to the previous one is not emitted again. The count of identical lines is accumulated, and at most once a second the line is emitted with (swallowed u dupes) appended.
A "spew" is a sustained rate of logging that nothing downstream can absorb: a tight loop logging every service call, a POLLOUT storm, a state machine ping-ponging. Left alone it fills the disk in seconds, and the lines are not even duplicates, so the check above does not help.
lws keeps a small ring of the timestamps of the last 64 lines it emitted. If those 64 lines span less than 20ms, ie, the sustained rate has exceeded about 3200 lines per second, lws enters spew mode:
Leaving spew mode is decided over a much shorter window than entering it, since a real spew never pauses: once the last 8 lines span more than the exit quiet, initially 5ms, lws emits a summary line saying how long the quiet was, then replays the retained tail of the spew in order, then frees the ringbuffer, and goes back to emitting directly. The timestamp ring is restarted at that point, so another full 64 lines at spew rate are needed to re-enter, which stops a bursty spew flapping in and out of the mode.
At the moment the next line arrives, a spew that has stopped and a process that was starved of cpu for a while, eg, on an overloaded CI builder, look the same. The difference shows afterwards: the spew comes back. If lws enters spew mode again within a second of calling it over, it says it resumed, and the exit quiet grows to twice the quiet that fooled it, up to a second, so the same size of stall does not end the spew again. Since the load on the box changes, each time a spew starts afresh rather than resuming, the exit quiet halves back towards 5ms. The lines saying spew mode was entered or resumed state the exit quiet in force.
The exit check can only run when a log arrives. If a spew stops dead and nothing logs afterwards, the retained tail is replayed by the next log whenever that comes, or by lws_context_destroy(). If the process dies during a spew, the retained tail dies with it.
A legitimate surge of logs, eg, context creation at debug level, may be fast enough to trip entry. Its first 63 lines were emitted before lws entered spew mode, and if it ends within the tail that is retained, that is replayed intact, so a surge of up to about 73 lines is waved through losslessly. A longer one loses its middle, as a spew does.
Logging is threadsafe wherever there are pthreads, except on the small embedded platforms, where lws runs no threads of its own unless it is built with SMP, the threadpool or the async queue.
The tunables are compile-time, and can be overridden on the compiler command line, eg, -DLWS_LOG_SPEW_TAIL_LINES=20:
| Define | Default | Meaning |
|---|---|---|
| LWS_LOG_SPEW_TS_RING | 64 | lines whose timestamps are tracked |
| LWS_LOG_SPEW_ENTER_US | 20000 | enter spew mode if they all fit in this |
| LWS_LOG_SPEW_EXIT_SAMPLES | 8 | lines considered for leaving spew mode |
| LWS_LOG_SPEW_EXIT_US | 5000 | leave spew mode if they span more than this |
| LWS_LOG_SPEW_EXIT_MAX_US | 1000000 | limit of how far that grows after resuming |
| LWS_LOG_SPEW_RESUME_US | 1000000 | re-entering this soon after leaving is a resume |
| LWS_LOG_SPEW_TAIL_LINES | 10 | lines of spew retained |
| LWS_LOG_SPEW_RING_SIZE | 2048 (1024 on FreeRTOS) | bytes of spew retained |
| LWS_LOG_SPEW_HEARTBEAT_US | 1000000 | interval of the still-going line |
How much of the tail is retained can also be set at runtime, for when the part of interest is further back than how the spew ended, eg, when debugging at a verbose log level where ordinary traffic is enough to trip spew mode. lws_log_spew_tail_lines(lines) sets it processwide, and any app that calls lws_cmdline_option_handle_builtin(), which includes lwsws and the examples, takes it on the commandline as --log-spew-tail <lines>. The ring is then sized for that many lines of typical length (256 bytes each), so long lines may mean somewhat fewer are kept; the count is capped at 65536. 0 restores the compile-time default. A spew already in progress keeps the tail it started with.
A log context with LLLF_LOG_SPEW_OFF in its lll_flags is exempt from spew handling; its lines are emitted directly regardless of rate.
1.19.0