diff --git a/READMEs/README.logging.md b/READMEs/README.logging.md index 83a9a678c..933a9208e 100644 --- a/READMEs/README.logging.md +++ b/READMEs/README.logging.md @@ -2,9 +2,10 @@ # `lwsl_` logging apis -LWS provides logging arrangements that are not indirected through the -lws context, because logging may be needed before and after the context -existence. For that reason it's processwide. +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()`) @@ -100,6 +101,188 @@ is a wsi bound to the SS object from the first log to do the outgoing client act 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 -`lws_wsi_tag(wsi)` -`lws_vh_tag(vh)` +|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 `:` 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. diff --git a/include/libwebsockets/lws-client.h b/include/libwebsockets/lws-client.h index fa01e2b45..cb307f8ff 100644 --- a/include/libwebsockets/lws-client.h +++ b/include/libwebsockets/lws-client.h @@ -219,12 +219,18 @@ struct lws_client_connect_info { * connection, allows targeting by "wsi=XXX/..." if you give XXX here. */ - uint16_t keep_warm_secs; + uint16_t keep_warm_secs; /**< 0 means 5s. If the client connection to the endpoint becomes idle, * defer closing it for this many seconds in case another outgoing * connection to the same endpoint turns up. */ + lws_log_cx_t *log_cx; + /**< NULL to use lws_context log context, else a pointer to a log + * context template to take a copy of for this wsi. Used to isolate + * wsi-specific logs into their own stream or file. + */ + /* Add new things just above here ---^ * This is part of the ABI, don't needlessly break compatibility * diff --git a/include/libwebsockets/lws-context-vhost.h b/include/libwebsockets/lws-context-vhost.h index 5e189a6f3..9fee5e2a1 100644 --- a/include/libwebsockets/lws-context-vhost.h +++ b/include/libwebsockets/lws-context-vhost.h @@ -632,7 +632,10 @@ struct lws_context_creation_info { const char *vhost_name; /**< VHOST: name of vhost, must match external DNS name used to * access the site, like "warmcat.com" as it's used to match - * Host: header and / or SNI name for SSL. */ + * Host: header and / or SNI name for SSL. + * CONTEXT: NULL, or the name to associate with the context for + * context-specific logging + */ #if defined(LWS_WITH_PLUGINS) const char * const *plugin_dirs; /**< CONTEXT: NULL, or NULL-terminated array of directories to @@ -889,6 +892,10 @@ struct lws_context_creation_info { * are allowed to live without active connections using them. */ #endif + lws_log_cx_t *log_cx; + /**< CONTEXT: NULL to use the default, process-scope logging context, + * else a specific logging context to associate with this context */ + /* Add new things just above here ---^ * This is part of the ABI, don't needlessly break compatibility * diff --git a/include/libwebsockets/lws-logs.h b/include/libwebsockets/lws-logs.h index 3a3c89241..3f21b8100 100644 --- a/include/libwebsockets/lws-logs.h +++ b/include/libwebsockets/lws-logs.h @@ -1,7 +1,7 @@ /* * libwebsockets - small server side websockets and web server implementation * - * Copyright (C) 2010 - 2019 Andy Green + * Copyright (C) 2010 - 2021 Andy Green * * Permission is hereby granted, free of charge, to any person obtaining a copy * of this software and associated documentation files (the "Software"), to @@ -31,23 +31,75 @@ * * Log categories may be individually filtered bitwise, and directed to built-in * sinks for syslog-compatible logging, or a user-defined function. + * + * Traditional logs use a single, processwide logging context. New style log + * apis (lws_xxx_cx()) can pass the logging context to use in. */ ///@{ -#define LLL_ERR (1 << 0) -#define LLL_WARN (1 << 1) -#define LLL_NOTICE (1 << 2) -#define LLL_INFO (1 << 3) -#define LLL_DEBUG (1 << 4) -#define LLL_PARSER (1 << 5) -#define LLL_HEADER (1 << 6) -#define LLL_EXT (1 << 7) -#define LLL_CLIENT (1 << 8) -#define LLL_LATENCY (1 << 9) -#define LLL_USER (1 << 10) -#define LLL_THREAD (1 << 11) +#define LLL_ERR (1 << 0) +#define LLL_WARN (1 << 1) +#define LLL_NOTICE (1 << 2) +#define LLL_INFO (1 << 3) +#define LLL_DEBUG (1 << 4) +#define LLL_PARSER (1 << 5) +#define LLL_HEADER (1 << 6) +#define LLL_EXT (1 << 7) +#define LLL_CLIENT (1 << 8) +#define LLL_LATENCY (1 << 9) +#define LLL_USER (1 << 10) +#define LLL_THREAD (1 << 11) -#define LLL_COUNT (12) /* set to count of valid flags */ +#define LLL_COUNT (12) /* set to count of valid flags */ + +#define LLLF_SECRECY_PII (1 << 16) + /**< contains Personally Identifiable Information */ +#define LLLF_SECRECY_BEARER (1 << 17) + /**< possession of this data allows impersonation */ + +#define LLLF_LOG_TIMESTAMP (1 << 18) + /**< set to prepend logs with timestamp */ + +#define LLLF_LOG_CONTEXT_AWARE (1 << 30) +/**< set if the context uses an emit function that takes the logctx, auto- + * applied when setting emit using lws_set_log_level_cx() api */ + +struct lws_log_cx; + +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); + +/* + * This is the logging context + */ + +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; /** * lwsl_timestamp: generate logging timestamp string @@ -64,10 +116,84 @@ lwsl_timestamp(int level, char *p, size_t len); #if defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NETWORK) #define _lws_log(aaa, ...) SMSG(__VA_ARGS__) #else -LWS_VISIBLE LWS_EXTERN void _lws_log(int filter, const char *format, ...) LWS_FORMAT(2); -LWS_VISIBLE LWS_EXTERN void _lws_logv(int filter, const char *format, va_list vl); +LWS_VISIBLE LWS_EXTERN void +_lws_log(int filter, const char *format, ...) LWS_FORMAT(2); +LWS_VISIBLE LWS_EXTERN void +_lws_logv(int filter, const char *format, va_list vl); #endif +struct lws_vhost; +struct lws; + +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_context_get_cx(struct lws_context *cx); +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_vhost_get_cx(struct lws_vhost *vh); +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_wsi_get_cx(struct lws *wsi); +#if defined(LWS_WITH_SECURE_STREAMS) +struct lws_ss_handle; +struct lws_sspc_handle; +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_ss_get_cx(struct lws_ss_handle *ss); +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_sspc_get_cx(struct lws_sspc_handle *ss); +#endif + +LWS_VISIBLE LWS_EXTERN void +lws_log_emit_cx_file(struct lws_log_cx *cx, int level, const char *line, + size_t len); + +LWS_VISIBLE LWS_EXTERN void +lws_log_use_cx_file(struct lws_log_cx *cx, int _new); + +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_context(struct lws_log_cx *cx, void *obj, char **p, char *e); +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_vhost(struct lws_log_cx *cx, void *obj, char **p, char *e); +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_wsi(struct lws_log_cx *cx, void *obj, char **p, char *e); +#if defined(LWS_WITH_SECURE_STREAMS) +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_ss(struct lws_log_cx *cx, void *obj, char **p, char *e); +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_sspc(struct lws_log_cx *cx, void *obj, char **p, char *e); +#endif + +LWS_VISIBLE LWS_EXTERN void +_lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj, + int filter, const char *_fun, const char *format, ...) LWS_FORMAT(6); + +#define lwsl_cx(_c, _fil, ...) \ + _lws_log_cx(lwsl_context_get_cx(_c), lws_log_prepend_context, \ + _c, _fil, __func__, __VA_ARGS__) +#define lwsl_vhost(_v, _fil, ...) \ + _lws_log_cx(lwsl_vhost_get_cx(_v), lws_log_prepend_vhost, _v, \ + _fil, __func__, __VA_ARGS__) +#define lwsl_wsi(_w, _fil, ...) \ + _lws_log_cx(lwsl_wsi_get_cx(_w), lws_log_prepend_wsi, _w, \ + _fil, __func__, __VA_ARGS__) +#define lwsl_ss(_h, _fil, ...) \ + _lws_log_cx(lwsl_ss_get_cx(_h), lws_log_prepend_ss, _h, \ + _fil, __func__, __VA_ARGS__) + +#define lwsl_hexdump_context(_c, _fil, _buf, _len) \ + lwsl_hexdump_level_cx(lwsl_context_get_cx(_c), \ + lws_log_prepend_context, \ + _c, _fil, _buf, _len) +#define lwsl_hexdump_vhost(_v, _fil, _buf, _len) \ + lwsl_hexdump_level_cx(lwsl_vhost_get_cx(_v), \ + lws_log_prepend_vhost, \ + _v, _fil, _buf, _len) +#define lwsl_hexdump_wsi(_w, _fil, _buf, _len) \ + lwsl_hexdump_level_cx(lwsl_wsi_get_cx(_w), \ + lws_log_prepend_wsi, \ + _w, _fil, _buf, _len) +#define lwsl_hexdump_ss(_h, _fil, _buf, _len) \ + lwsl_hexdump_level_cx(lwsl_ss_get_cx(_h), \ + lws_log_prepend_ss, \ + _h, _fil, _buf, _len) + /* * Figure out which logs to build in or not */ @@ -120,6 +246,10 @@ LWS_VISIBLE LWS_EXTERN void _lws_logv(int filter, const char *format, va_list vl * depending on what was computed */ +/* + * Process scope logs + */ + #if (_LWS_ENABLED_LOGS & LLL_ERR) #define lwsl_err(...) _lws_log(LLL_ERR, __VA_ARGS__) #else @@ -192,13 +322,344 @@ LWS_VISIBLE LWS_EXTERN void _lws_logv(int filter, const char *format, va_list vl #define lwsl_user(...) do {} while(0) #endif - #define lwsl_hexdump_err(...) lwsl_hexdump_level(LLL_ERR, __VA_ARGS__) #define lwsl_hexdump_warn(...) lwsl_hexdump_level(LLL_WARN, __VA_ARGS__) #define lwsl_hexdump_notice(...) lwsl_hexdump_level(LLL_NOTICE, __VA_ARGS__) #define lwsl_hexdump_info(...) lwsl_hexdump_level(LLL_INFO, __VA_ARGS__) #define lwsl_hexdump_debug(...) lwsl_hexdump_level(LLL_DEBUG, __VA_ARGS__) +/* + * lws_context scope logs + */ + +#if (_LWS_ENABLED_LOGS & LLL_ERR) +#define lwsl_cx_err(_c, ...) lwsl_cx(_c, LLL_ERR, __VA_ARGS__) +#else +#define lwsl_cx_err(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_WARN) +#define lwsl_cx_warn(_c, ...) lwsl_cx(_c, LLL_WARN, __VA_ARGS__) +#else +#define lwsl_cx_warn(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_NOTICE) +#define lwsl_cx_notice(_c, ...) lwsl_cx(_c, LLL_NOTICE, __VA_ARGS__) +#else +#define lwsl_cx_notice(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_INFO) +#define lwsl_cx_info(_c, ...) lwsl_cx(_c, LLL_INFO, __VA_ARGS__) +#else +#define lwsl_cx_info(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_DEBUG) +#define lwsl_cx_debug(_c, ...) lwsl_cx(_c, LLL_DEBUG, __VA_ARGS__) +#else +#define lwsl_cx_debug(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_PARSER) +#define lwsl_cx_parser(_c, ...) lwsl_cx(_c, LLL_PARSER, __VA_ARGS__) +#else +#define lwsl_cx_parser(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_HEADER) +#define lwsl_cx_header(_c, ...) lwsl_cx(_c, LLL_HEADER, __VA_ARGS__) +#else +#define lwsl_cx_header(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_EXT) +#define lwsl_cx_ext(_c, ...) lwsl_cx(_c, LLL_EXT, __VA_ARGS__) +#else +#define lwsl_cx_ext(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_CLIENT) +#define lwsl_cx_client(_c, ...) lwsl_cx(_c, LLL_CLIENT, __VA_ARGS__) +#else +#define lwsl_cx_client(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_LATENCY) +#define lwsl_cx_latency(_c, ...) lwsl_cx(_c, LLL_LATENCY, __VA_ARGS__) +#else +#define lwsl_cx_latency(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_THREAD) +#define lwsl_cx_thread(_c, ...) lwsl_cx(_c, LLL_THREAD, __VA_ARGS__) +#else +#define lwsl_cx_thread(_c, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_USER) +#define lwsl_cx_user(_c, ...) lwsl_cx(_c, LLL_USER, __VA_ARGS__) +#else +#define lwsl_cx_user(_c, ...) do {} while(0) +#endif + +#define lwsl_hexdump_cx_err(_c, ...) lwsl_hexdump_context(_c, LLL_ERR, __VA_ARGS__) +#define lwsl_hexdump_cx_warn(_c, ...) lwsl_hexdump_context(_c, LLL_WARN, __VA_ARGS__) +#define lwsl_hexdump_cx_notice(_c, ...) lwsl_hexdump_context(_c, LLL_NOTICE, __VA_ARGS__) +#define lwsl_hexdump_cx_info(_c, ...) lwsl_hexdump_context(_c, LLL_INFO, __VA_ARGS__) +#define lwsl_hexdump_cx_debug(_c, ...) lwsl_hexdump_context(_c, LLL_DEBUG, __VA_ARGS__) + +/* + * lws_vhost + */ + +#if (_LWS_ENABLED_LOGS & LLL_ERR) +#define lwsl_vhost_err(_v, ...) lwsl_vhost(_v, LLL_ERR, __VA_ARGS__) +#else +#define lwsl_vhost_err(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_WARN) +#define lwsl_vhost_warn(_v, ...) lwsl_vhost(_v, LLL_WARN, __VA_ARGS__) +#else +#define lwsl_vhost_warn(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_NOTICE) +#define lwsl_vhost_notice(_v, ...) lwsl_vhost(_v, LLL_NOTICE, __VA_ARGS__) +#else +#define lwsl_vhost_notice(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_INFO) +#define lwsl_vhost_info(_v, ...) lwsl_vhost(_v, LLL_INFO, __VA_ARGS__) +#else +#define lwsl_vhost_info(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_DEBUG) +#define lwsl_vhost_debug(_v, ...) lwsl_vhost(_v, LLL_DEBUG, __VA_ARGS__) +#else +#define lwsl_vhost_debug(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_PARSER) +#define lwsl_vhost_parser(_v, ...) lwsl_vhost(_v, LLL_PARSER, __VA_ARGS__) +#else +#define lwsl_vhost_parser(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_HEADER) +#define lwsl_vhost_header(_v, ...) lwsl_vhost(_v, LLL_HEADER, __VA_ARGS__) +#else +#define lwsl_vhost_header(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_EXT) +#define lwsl_vhost_ext(_v, ...) lwsl_vhost(_v, LLL_EXT, __VA_ARGS__) +#else +#define lwsl_vhost_ext(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_CLIENT) +#define lwsl_vhost_client(_v, ...) lwsl_vhost(_v, LLL_CLIENT, __VA_ARGS__) +#else +#define lwsl_vhost_client(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_LATENCY) +#define lwsl_vhost_latency(_v, ...) lwsl_vhost(_v, LLL_LATENCY, __VA_ARGS__) +#else +#define lwsl_vhost_latency(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_THREAD) +#define lwsl_vhost_thread(_v, ...) lwsl_vhost(_v, LLL_THREAD, __VA_ARGS__) +#else +#define lwsl_vhost_thread(_v, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_USER) +#define lwsl_vhost_user(_v, ...) lwsl_vhost(_v, LLL_USER, __VA_ARGS__) +#else +#define lwsl_vhost_user(_v, ...) do {} while(0) +#endif + +#define lwsl_hexdump_vhost_err(_v, ...) lwsl_hexdump_vhost(_v, LLL_ERR, __VA_ARGS__) +#define lwsl_hexdump_vhost_warn(_v, ...) lwsl_hexdump_vhost(_v, LLL_WARN, __VA_ARGS__) +#define lwsl_hexdump_vhost_notice(_v, ...) lwsl_hexdump_vhost(_v, LLL_NOTICE, __VA_ARGS__) +#define lwsl_hexdump_vhost_info(_v, ...) lwsl_hexdump_vhost(_v, LLL_INFO, __VA_ARGS__) +#define lwsl_hexdump_vhost_debug(_v, ...) lwsl_hexdump_vhost(_v, LLL_DEBUG, __VA_ARGS__) + + +/* + * lws_wsi + */ + +#if (_LWS_ENABLED_LOGS & LLL_ERR) +#define lwsl_wsi_err(_w, ...) lwsl_wsi(_w, LLL_ERR, __VA_ARGS__) +#else +#define lwsl_wsi_err(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_WARN) +#define lwsl_wsi_warn(_w, ...) lwsl_wsi(_w, LLL_WARN, __VA_ARGS__) +#else +#define lwsl_wsi_warn(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_NOTICE) +#define lwsl_wsi_notice(_w, ...) lwsl_wsi(_w, LLL_NOTICE, __VA_ARGS__) +#else +#define lwsl_wsi_notice(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_INFO) +#define lwsl_wsi_info(_w, ...) lwsl_wsi(_w, LLL_INFO, __VA_ARGS__) +#else +#define lwsl_wsi_info(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_DEBUG) +#define lwsl_wsi_debug(_w, ...) lwsl_wsi(_w, LLL_DEBUG, __VA_ARGS__) +#else +#define lwsl_wsi_debug(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_PARSER) +#define lwsl_wsi_parser(_w, ...) lwsl_wsi(_w, LLL_PARSER, __VA_ARGS__) +#else +#define lwsl_wsi_parser(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_HEADER) +#define lwsl_wsi_header(_w, ...) lwsl_wsi(_w, LLL_HEADER, __VA_ARGS__) +#else +#define lwsl_wsi_header(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_EXT) +#define lwsl_wsi_ext(_w, ...) lwsl_wsi(_w, LLL_EXT, __VA_ARGS__) +#else +#define lwsl_wsi_ext(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_CLIENT) +#define lwsl_wsi_client(_w, ...) lwsl_wsi(_w, LLL_CLIENT, __VA_ARGS__) +#else +#define lwsl_wsi_client(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_LATENCY) +#define lwsl_wsi_latency(_w, ...) lwsl_wsi(_w, LLL_LATENCY, __VA_ARGS__) +#else +#define lwsl_wsi_latency(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_THREAD) +#define lwsl_wsi_thread(_w, ...) lwsl_wsi(_w, LLL_THREAD, __VA_ARGS__) +#else +#define lwsl_wsi_thread(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_USER) +#define lwsl_wsi_user(_w, ...) lwsl_wsi(_w, LLL_USER, __VA_ARGS__) +#else +#define lwsl_wsi_user(_w, ...) do {} while(0) +#endif + +#define lwsl_hexdump_wsi_err(_v, ...) lwsl_hexdump_wsi(_v, LLL_ERR, __VA_ARGS__) +#define lwsl_hexdump_wsi_warn(_v, ...) lwsl_hexdump_wsi(_v, LLL_WARN, __VA_ARGS__) +#define lwsl_hexdump_wsi_notice(_v, ...) lwsl_hexdump_wsi(_v, LLL_NOTICE, __VA_ARGS__) +#define lwsl_hexdump_wsi_info(_v, ...) lwsl_hexdump_wsi(_v, LLL_INFO, __VA_ARGS__) +#define lwsl_hexdump_wsi_debug(_v, ...) lwsl_hexdump_wsi(_v, LLL_DEBUG, __VA_ARGS__) + + +/* + * lwsl_ss + */ + +#if (_LWS_ENABLED_LOGS & LLL_ERR) +#define lwsl_ss_err(_w, ...) lwsl_ss(_w, LLL_ERR, __VA_ARGS__) +#else +#define lwsl_ss_err(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_WARN) +#define lwsl_ss_warn(_w, ...) lwsl_ss(_w, LLL_WARN, __VA_ARGS__) +#else +#define lwsl_ss_warn(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_NOTICE) +#define lwsl_ss_notice(_w, ...) lwsl_ss(_w, LLL_NOTICE, __VA_ARGS__) +#else +#define lwsl_ss_notice(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_INFO) +#define lwsl_ss_info(_w, ...) lwsl_ss(_w, LLL_INFO, __VA_ARGS__) +#else +#define lwsl_ss_info(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_DEBUG) +#define lwsl_ss_debug(_w, ...) lwsl_ss(_w, LLL_DEBUG, __VA_ARGS__) +#else +#define lwsl_ss_debug(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_PARSER) +#define lwsl_ss_parser(_w, ...) lwsl_ss(_w, LLL_PARSER, __VA_ARGS__) +#else +#define lwsl_ss_parser(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_HEADER) +#define lwsl_ss_header(_w, ...) lwsl_ss(_w, LLL_HEADER, __VA_ARGS__) +#else +#define lwsl_ss_header(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_EXT) +#define lwsl_ss_ext(_w, ...) lwsl_ss(_w, LLL_EXT, __VA_ARGS__) +#else +#define lwsl_ss_ext(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_CLIENT) +#define lwsl_ss_client(_w, ...) lwsl_ss(_w, LLL_CLIENT, __VA_ARGS__) +#else +#define lwsl_ss_client(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_LATENCY) +#define lwsl_ss_latency(_w, ...) lwsl_ss(_w, LLL_LATENCY, __VA_ARGS__) +#else +#define lwsl_ss_latency(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_THREAD) +#define lwsl_ss_thread(_w, ...) lwsl_ss(_w, LLL_THREAD, __VA_ARGS__) +#else +#define lwsl_ss_thread(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_USER) +#define lwsl_ss_user(_w, ...) lwsl_ss(_w, LLL_USER, __VA_ARGS__) +#else +#define lwsl_ss_user(_w, ...) do {} while(0) +#endif + +#define lwsl_hexdump_ss_err(_v, ...) lwsl_hexdump_ss(_v, LLL_ERR, __VA_ARGS__) +#define lwsl_hexdump_ss_warn(_v, ...) lwsl_hexdump_ss(_v, LLL_WARN, __VA_ARGS__) +#define lwsl_hexdump_ss_notice(_v, ...) lwsl_hexdump_ss(_v, LLL_NOTICE, __VA_ARGS__) +#define lwsl_hexdump_ss_info(_v, ...) lwsl_hexdump_ss(_v, LLL_INFO, __VA_ARGS__) +#define lwsl_hexdump_ss_debug(_v, ...) lwsl_hexdump_ss(_v, LLL_DEBUG, __VA_ARGS__) + + + /** * lwsl_hexdump_level() - helper to hexdump a buffer at a selected debug level * @@ -212,6 +673,10 @@ LWS_VISIBLE LWS_EXTERN void _lws_logv(int filter, const char *format, va_list vl LWS_VISIBLE LWS_EXTERN void lwsl_hexdump_level(int level, const void *vbuf, size_t len); +LWS_VISIBLE LWS_EXTERN void +lwsl_hexdump_level_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj, + int hexdump_level, const void *vbuf, size_t len); + /** * lwsl_hexdump() - helper to hexdump a buffer (DEBUG builds only) * @@ -241,13 +706,20 @@ static LWS_INLINE int lws_is_be(void) { * function to perform log string emission instead of * the default stderr one. * - * log level defaults to "err", "warn" and "notice" contexts enabled and - * emission on stderr. If stderr is a tty (according to isatty()) then - * the output is coloured according to the log level using ANSI escapes. + * log level defaults to "err", "warn" and "notice" contexts enabled and + * emission on stderr. If stderr is a tty (according to isatty()) then + * the output is coloured according to the log level using ANSI escapes. + * + * You can set the default security level for logging using the + * secrecy_and_log_level() macro to set the \p level parameter, eg + * + * lws_set_log_level(secrecy_and_log_level(LWS_SECRECY_PII, LLL_ERR | LLL_WARN), + * my_emit_function); + * + * Normally you can just leave it at the default. */ LWS_VISIBLE LWS_EXTERN void -lws_set_log_level(int level, - void (*log_emit_function)(int level, const char *line)); +lws_set_log_level(int level, lws_log_emit_t log_emit_function); /** * lwsl_emit_syslog() - helper log emit function writes to system log @@ -308,4 +780,7 @@ struct lws; LWS_VISIBLE LWS_EXTERN const char * lws_wsi_tag(struct lws *wsi); +LWS_VISIBLE LWS_EXTERN void +lwsl_refcount_cx(lws_log_cx_t *cx, int _new); + ///@} diff --git a/include/libwebsockets/lws-secure-streams-client.h b/include/libwebsockets/lws-secure-streams-client.h index eac12e79a..adca1db16 100644 --- a/include/libwebsockets/lws-secure-streams-client.h +++ b/include/libwebsockets/lws-secure-streams-client.h @@ -40,6 +40,8 @@ * lws_sspc_ in one step by #define LWS_SS_USE_SSPC before including */ +struct lws_sspc_handle; + #if defined(LWS_SS_USE_SSPC) #define lws_ss_handle lws_sspc_handle #define lws_ss_create lws_sspc_create @@ -62,10 +64,112 @@ #define lws_smd_ss_rx_forward lws_smd_sspc_rx_forward #define lws_ss_tag lws_sspc_tag #define _lws_fi_user_ss_fi _lws_fi_user_sspc_fi +#define lwsl_ss_get_cx lwsl_sspc_get_cx + +LWS_VISIBLE LWS_EXTERN void +lws_log_prepend_sspc(struct lws_log_cx *cx, void *obj, char **p, char *e); + +LWS_VISIBLE LWS_EXTERN struct lws_log_cx * +lwsl_sspc_get_cx(struct lws_sspc_handle *ss); + +#undef lwsl_ss +#define lwsl_ss lwsl_sspc + +#undef lwsl_hexdump_ss +#define lwsl_hexdump_ss lwsl_hexdump_sspc #endif +#define lwsl_sspc(_h, _fil, ...) \ + _lws_log_cx(lwsl_sspc_get_cx(_h), lws_log_prepend_sspc, _h, \ + _fil, __func__, __VA_ARGS__) + +#define lwsl_hexdump_sspc(_h, _fil, _buf, _len) \ + lwsl_hexdump_level_cx(lwsl_sspc_get_cx(_h), \ + lws_log_prepend_sspc, \ + _h, _fil, _buf, _len) + +/* + * lwsl_sspc + */ + +#if (_LWS_ENABLED_LOGS & LLL_ERR) +#define lwsl_sspc_err(_w, ...) lwsl_sspc(_w, LLL_ERR, __VA_ARGS__) +#else +#define lwsl_sspc_err(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_WARN) +#define lwsl_sspc_warn(_w, ...) lwsl_sspc(_w, LLL_WARN, __VA_ARGS__) +#else +#define lwsl_sspc_warn(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_NOTICE) +#define lwsl_sspc_notice(_w, ...) lwsl_sspc(_w, LLL_NOTICE, __VA_ARGS__) +#else +#define lwsl_sspc_notice(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_INFO) +#define lwsl_sspc_info(_w, ...) lwsl_sspc(_w, LLL_INFO, __VA_ARGS__) +#else +#define lwsl_sspc_info(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_DEBUG) +#define lwsl_sspc_debug(_w, ...) lwsl_sspc(_w, LLL_DEBUG, __VA_ARGS__) +#else +#define lwsl_sspc_debug(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_PARSER) +#define lwsl_sspc_parser(_w, ...) lwsl_sspc(_w, LLL_PARSER, __VA_ARGS__) +#else +#define lwsl_sspc_parser(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_HEADER) +#define lwsl_sspc_header(_w, ...) lwsl_sspc(_w, LLL_HEADER, __VA_ARGS__) +#else +#define lwsl_sspc_header(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_EXT) +#define lwsl_sspc_ext(_w, ...) lwsl_sspc(_w, LLL_EXT, __VA_ARGS__) +#else +#define lwsl_sspc_ext(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_CLIENT) +#define lwsl_sspc_client(_w, ...) lwsl_sspc(_w, LLL_CLIENT, __VA_ARGS__) +#else +#define lwsl_sspc_client(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_LATENCY) +#define lwsl_sspc_latency(_w, ...) lwsl_sspc(_w, LLL_LATENCY, __VA_ARGS__) +#else +#define lwsl_sspc_latency(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_THREAD) +#define lwsl_sspc_thread(_w, ...) lwsl_sspc(_w, LLL_THREAD, __VA_ARGS__) +#else +#define lwsl_sspc_thread(_w, ...) do {} while(0) +#endif + +#if (_LWS_ENABLED_LOGS & LLL_USER) +#define lwsl_sspc_user(_w, ...) lwsl_sspc(_w, LLL_USER, __VA_ARGS__) +#else +#define lwsl_sspc_user(_w, ...) do {} while(0) +#endif + +#define lwsl_hexdump_sspc_err(_v, ...) lwsl_hexdump_sspc(_v, LLL_ERR, __VA_ARGS__) +#define lwsl_hexdump_sspc_warn(_v, ...) lwsl_hexdump_sspc(_v, LLL_WARN, __VA_ARGS__) +#define lwsl_hexdump_sspc_notice(_v, ...) lwsl_hexdump_sspc(_v, LLL_NOTICE, __VA_ARGS__) +#define lwsl_hexdump_sspc_info(_v, ...) lwsl_hexdump_sspc(_v, LLL_INFO, __VA_ARGS__) +#define lwsl_hexdump_sspc_debug(_v, ...) lwsl_hexdump_sspc(_v, LLL_DEBUG, __VA_ARGS__) -struct lws_sspc_handle; LWS_VISIBLE LWS_EXTERN int lws_sspc_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, diff --git a/lib/core-net/adopt.c b/lib/core-net/adopt.c index a5fb8b43e..0592bfc24 100644 --- a/lib/core-net/adopt.c +++ b/lib/core-net/adopt.c @@ -59,14 +59,15 @@ lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi, const char *de } lws_context_lock(vhost->context, __func__); - new_wsi = __lws_wsi_create_with_role(vhost->context, n, NULL); + new_wsi = __lws_wsi_create_with_role(vhost->context, n, NULL, + vhost->lc.log_cx); lws_context_unlock(vhost->context); if (new_wsi == NULL) { lwsl_err("Out of memory for new connection\n"); return NULL; } - __lws_lc_tag(&vhost->context->lcg[ + __lws_lc_tag(vhost->context, &vhost->context->lcg[ #if defined(LWS_ROLE_H2) || defined(LWS_ROLE_MQTT) strcmp(desc, "adopted") ? LWSLCG_WSI_MUX : #endif diff --git a/lib/core-net/client/connect.c b/lib/core-net/client/connect.c index f1028cffe..c26419a18 100644 --- a/lib/core-net/client/connect.c +++ b/lib/core-net/client/connect.c @@ -158,7 +158,7 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) /* PHASE 2: create a bare wsi */ - wsi = __lws_wsi_create_with_role(i->context, tsi, NULL); + wsi = __lws_wsi_create_with_role(i->context, tsi, NULL, i->log_cx); lws_context_unlock(i->context); if (wsi == NULL) return NULL; @@ -373,7 +373,7 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) * LCCSCF_SECSTREAM_PROXY_LINK : client SSPC link to proxy * LCCSCF_SECSTREAM_PROXY_ONWARD: proxy's onward connection */ - __lws_lc_tag(&i->context->lcg[ + __lws_lc_tag(i->context, &i->context->lcg[ #if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) i->ssl_connection & LCCSCF_SECSTREAM_PROXY_LINK ? LWSLCG_WSI_SSP_CLIENT : #if defined(LWS_WITH_SERVER) @@ -396,7 +396,7 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) lws_ss_tag(((lws_ss_handle_t *)i->opaque_user_data))); } else #endif - __lws_lc_tag(&i->context->lcg[LWSLCG_WSI_CLIENT], &wsi->lc, + __lws_lc_tag(i->context, &i->context->lcg[LWSLCG_WSI_CLIENT], &wsi->lc, "%s/%s/%s", i->method ? i->method : "WS", wsi->role_ops->name, i->address); diff --git a/lib/core-net/close.c b/lib/core-net/close.c index 9f9cdf828..31533977e 100644 --- a/lib/core-net/close.c +++ b/lib/core-net/close.c @@ -257,14 +257,13 @@ __lws_free_wsi(struct lws *wsi) if (wsi->a.context->event_loop_ops->destroy_wsi) wsi->a.context->event_loop_ops->destroy_wsi(wsi); - lwsl_debug("%s: %s, tsi fds count %d\n", __func__, - lws_wsi_tag(wsi), + lwsl_debug("%s: tsi fds count %d\n", __func__, wsi->a.context->pt[(int)wsi->tsi].fds_count); /* confirm no sul left scheduled in wsi itself */ lws_sul_debug_zombies(wsi->a.context, wsi, sizeof(*wsi), __func__); - __lws_lc_untag(&wsi->lc); + __lws_lc_untag(wsi->a.context, &wsi->lc); lws_free(wsi); } @@ -353,16 +352,15 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason, struct lws *wsi1, *wsi2; int n, ccb; - lwsl_info("%s: %s: caller: %s\n", __func__, lws_wsi_tag(wsi), caller); - if (!wsi) return; + lwsl_info("%s: %s: caller: %s\n", __func__, lws_wsi_tag(wsi), caller); + lws_access_log(wsi); - if (!lws_dll2_is_detached(&wsi->dll_buflist)) { - lwsl_info("%s: %s: going down with stuff in buflist\n", - __func__, lws_wsi_tag(wsi)); } + if (!lws_dll2_is_detached(&wsi->dll_buflist)) + lwsl_info("%s: going down with stuff in buflist\n", __func__); context = wsi->a.context; pt = &context->pt[(int)wsi->tsi]; @@ -899,12 +897,12 @@ __lws_close_free_wsi_final(struct lws *wsi) wsi->desc.sockfd = LWS_SOCK_INVALID; #if defined(LWS_WITH_CLIENT) + lws_free_set_NULL(wsi->cli_hostname_copy); if (wsi->close_is_redirect) { wsi->close_is_redirect = 0; - lwsl_info("%s: picking up redirection %s\n", __func__, - wsi->lc.gutag); + lwsl_info("%s: picking up redirection", __func__); lws_role_transition(wsi, LWSIFR_CLIENT, LRS_UNCONNECTED, &role_ops_h1); @@ -937,7 +935,7 @@ __lws_close_free_wsi_final(struct lws *wsi) #endif if (lws_header_table_attach(wsi, 0)) { - lwsl_err("%s: failed to get ah\n", __func__); + lwsl_err("failed to get ah\n"); return; } // } diff --git a/lib/core-net/lws-dsh.c b/lib/core-net/lws-dsh.c index 7a6c505ac..f49294e18 100644 --- a/lib/core-net/lws-dsh.c +++ b/lib/core-net/lws-dsh.c @@ -222,8 +222,6 @@ lws_dsh_destroy(lws_dsh_t **pdsh) if (!dsh) return; - lwsl_debug("%s: destroying dsh %p\n", __func__, dsh); - dsh->being_destroyed = 1; /* we need to explicitly free any of our allocations in foreign dsh */ diff --git a/lib/core-net/private-lib-core-net.h b/lib/core-net/private-lib-core-net.h index 33557c50f..882e6b2e9 100644 --- a/lib/core-net/private-lib-core-net.h +++ b/lib/core-net/private-lib-core-net.h @@ -718,6 +718,8 @@ struct lws { struct lws_sequencer *seq; /* associated sequencer if any */ const lws_retry_bo_t *retry_policy; + lws_log_cx_t *log_cx; + #if defined(LWS_WITH_THREADPOOL) lws_dll2_owner_t tp_task_owner; /* struct lws_threadpool_task */ #endif @@ -1240,7 +1242,8 @@ lws_http_client_connect_via_info2(struct lws *wsi); struct lws * __lws_wsi_create_with_role(struct lws_context *context, int tsi, - const struct lws_role_ops *ops); + const struct lws_role_ops *ops, + lws_log_cx_t *log_cx_template); int lws_wsi_inject_to_loop(struct lws_context_per_thread *pt, struct lws *wsi); @@ -1374,7 +1377,7 @@ int _lws_route_pt_close_unroutable(struct lws_context_per_thread *pt); void -_lws_routing_entry_dump(lws_route_t *rou); +_lws_routing_entry_dump(struct lws_context *cx, lws_route_t *rou); void _lws_routing_table_dump(struct lws_context *cx); diff --git a/lib/core-net/route.c b/lib/core-net/route.c index 6be93d62c..a7d9cc4c4 100644 --- a/lib/core-net/route.c +++ b/lib/core-net/route.c @@ -35,7 +35,7 @@ void -_lws_routing_entry_dump(lws_route_t *rou) +_lws_routing_entry_dump(struct lws_context *cx, lws_route_t *rou) { char sa[48], fin[192], *end = &fin[sizeof(fin)]; @@ -69,7 +69,7 @@ _lws_routing_table_dump(struct lws_context *cx) lws_dll2_get_head(&cx->routing_table)) { lws_route_t *rou = lws_container_of(d, lws_route_t, list); - _lws_routing_entry_dump(rou); + _lws_routing_entry_dump(cx, rou); } lws_end_foreach_dll(d); } #endif diff --git a/lib/core-net/vhost.c b/lib/core-net/vhost.c index 10919cb34..3f1dd32af 100644 --- a/lib/core-net/vhost.c +++ b/lib/core-net/vhost.c @@ -456,12 +456,16 @@ lws_protocol_init_vhost(struct lws_vhost *vh, int *any) #if !defined(LWS_WITH_PLUGINS) /* * with plugins, you have to explicitly - * instantiate them with pvos + * instantiate them per-vhost with pvos. + * + * Without plugins, not setting the vhost pvo + * list at creation enables all the protocols + * by default, for backwards compatibility */ || !vh->pvo #endif ) { - lwsl_info("%s: init %s.%s\n", __func__, vh->name, + lwsl_info("init %s.%s", vh->name, vh->protocols[n].name); if (vh->protocols[n].callback((struct lws *)lwsa, LWS_CALLBACK_PROTOCOL_INIT, NULL, @@ -602,6 +606,11 @@ lws_create_vhost(struct lws_context *context, if (!vh) goto early_bail; + if (info->log_cx) + vh->lc.log_cx = info->log_cx; + else + vh->lc.log_cx = &log_cx; + #if defined(LWS_WITH_EVENT_LIBS) vh->evlib_vh = (void *)&vh[1]; vh->name = (const char *)vh->evlib_vh + @@ -630,8 +639,8 @@ lws_create_vhost(struct lws_context *context, p += lws_snprintf(p, lws_ptr_diff_size_t(end, p), "|%u", info->port); } - __lws_lc_tag(&context->lcg[LWSLCG_VHOST], &vh->lc, "%s|%s|%d", buf, - info->iface ? info->iface : "", info->port); + __lws_lc_tag(context, &context->lcg[LWSLCG_VHOST], &vh->lc, "%s|%s|%d", + buf, info->iface ? info->iface : "", info->port); #if defined(LWS_WITH_SYS_FAULT_INJECTION) vh->fic.name = "vh"; @@ -1042,7 +1051,7 @@ bail1: return NULL; bail: - __lws_lc_untag(&vh->lc); + __lws_lc_untag(vh->context, &vh->lc); lws_fi_destroy(&vh->fic); lws_free(vh); @@ -1111,11 +1120,13 @@ __lws_create_event_pipes(struct lws_context *context) if (pt->pipe_wsi) return 0; - wsi = __lws_wsi_create_with_role(context, n, &role_ops_pipe); + wsi = __lws_wsi_create_with_role(context, n, &role_ops_pipe, + NULL); if (!wsi) return 1; - __lws_lc_tag(&context->lcg[LWSLCG_WSI], &wsi->lc, "pipe"); + __lws_lc_tag(context, &context->lcg[LWSLCG_WSI], &wsi->lc, + "pipe"); wsi->event_pipe = 1; pt->pipe_wsi = wsi; @@ -1131,7 +1142,7 @@ __lws_create_event_pipes(struct lws_context *context) */ wsi->desc.sockfd = context->pt[n].dummy_pipe_fds[0]; - lwsl_debug("event pipe fd %d\n", wsi->desc.sockfd); + // lwsl_debug("event pipe fd %d\n", wsi->desc.sockfd); if (lws_wsi_inject_to_loop(pt, wsi)) goto bail; @@ -1554,7 +1565,7 @@ __lws_vhost_destroy2(struct lws_vhost *vh) lws_sul_cancel(&vh->sul_unref); #endif - __lws_lc_untag(&vh->lc); + __lws_lc_untag(vh->context, &vh->lc); memset(vh, 0, sizeof(*vh)); lws_free(vh); @@ -1899,3 +1910,21 @@ lws_vh_tag(struct lws_vhost *vh) { return lws_lc_tag(&vh->lc); } + +struct lws_log_cx * +lwsl_vhost_get_cx(struct lws_vhost *vh) +{ + if (!vh) + return NULL; + + return vh->lc.log_cx; +} + +void +lws_log_prepend_vhost(struct lws_log_cx *cx, void *obj, char **p, char *e) +{ + struct lws_vhost *vh = (struct lws_vhost *)obj; + + *p += lws_snprintf(*p, lws_ptr_diff_size_t(e, (*p)), "%s: ", + lws_vh_tag(vh)); +} diff --git a/lib/core-net/wsi.c b/lib/core-net/wsi.c index 001ab794f..bb64a1fc3 100644 --- a/lib/core-net/wsi.c +++ b/lib/core-net/wsi.c @@ -47,12 +47,21 @@ void lwsi_set_state(struct lws *wsi, lws_wsi_state_t lrs) wsi->wsistate = (old & (unsigned int)(~LRS_MASK)) | lrs; - lwsl_debug("lwsi_set_state(%s): 0x%lx -> 0x%lx)\n", lws_wsi_tag(wsi), + lwsl_debug("lwsi_set_state 0x%lx -> 0x%lx)", (unsigned long)old, (unsigned long)wsi->wsistate); } #endif +void +lws_log_prepend_wsi(struct lws_log_cx *cx, void *obj, char **p, char *e) +{ + struct lws *wsi = (struct lws *)obj; + + *p += lws_snprintf(*p, lws_ptr_diff_size_t(e, (*p)), "%s: ", + lws_wsi_tag(wsi)); +} + void lws_vhost_bind_wsi(struct lws_vhost *vh, struct lws *wsi) { @@ -244,7 +253,8 @@ lws_callback_vhost_protocols(struct lws *wsi, int reason, void *in, size_t len) struct lws * __lws_wsi_create_with_role(struct lws_context *context, int tsi, - const struct lws_role_ops *ops) + const struct lws_role_ops *ops, + lws_log_cx_t *log_cx_template) { size_t s = sizeof(struct lws); struct lws *wsi; @@ -264,6 +274,11 @@ __lws_wsi_create_with_role(struct lws_context *context, int tsi, return NULL; } + if (log_cx_template) + wsi->lc.log_cx = log_cx_template; + else + wsi->lc.log_cx = context->log_cx; + #if defined(LWS_WITH_EVENT_LIBS) wsi->evlib_wsi = (uint8_t *)wsi + sizeof(*wsi); #endif @@ -953,6 +968,15 @@ lws_get_context(const struct lws *wsi) return wsi->a.context; } +struct lws_log_cx * +lwsl_wsi_get_cx(struct lws *wsi) +{ + if (!wsi) + return NULL; + + return wsi->lc.log_cx; +} + #if defined(LWS_WITH_CLIENT) int _lws_generic_transaction_completed_active_conn(struct lws **_wsi, char take_vh_lock) diff --git a/lib/core/context.c b/lib/core/context.c index 76d1139af..869c45af9 100644 --- a/lib/core/context.c +++ b/lib/core/context.c @@ -428,8 +428,6 @@ lws_create_context(const struct lws_context_creation_info *info) #endif } - lwsl_notice("LWS: %s, loglevel %d\n", library_version, log_level); - #if defined(LWS_WITH_IPV6) && !defined(LWS_WITH_NO_LOGS) if (!lws_check_opt(info->options, LWS_SERVER_OPTION_DISABLE_IPV6)) s = "IPV6-on"; @@ -437,8 +435,6 @@ lws_create_context(const struct lws_context_creation_info *info) s = "IPV6-off"; #endif - lwsl_notice("%s%s\n", opts_str, s); - if (lws_plat_context_early_init()) goto early_bail; @@ -597,8 +593,6 @@ lws_create_context(const struct lws_context_creation_info *info) #if defined(LWS_WITH_NETWORK) size += (size_t)plev->ops->evlib_size_ctx /* the ctx evlib priv */ + (count_threads * (size_t)plev->ops->evlib_size_pt) /* the pt evlib priv */; - - lwsl_info("Event loop: %s\n", plev->ops->name); #endif context = lws_zalloc(size, "context"); @@ -606,7 +600,7 @@ lws_create_context(const struct lws_context_creation_info *info) #if defined(LWS_WITH_SYS_FAULT_INJECTION) lws_free(context); #endif - lwsl_err("No memory for lws_context\n"); + lwsl_err("OOM"); goto early_bail; } @@ -641,6 +635,13 @@ lws_create_context(const struct lws_context_creation_info *info) context->username = info->username; context->groupname = info->groupname; #endif + context->name = info->vhost_name; + if (info->log_cx) + context->log_cx = info->log_cx; + else + context->log_cx = &log_cx; + lwsl_refcount_cx(context->log_cx, 1); + context->system_ops = info->system_ops; context->pt_serv_buf_size = (unsigned int)s1; context->protocols_copy = info->protocols; @@ -776,6 +777,11 @@ lws_create_context(const struct lws_context_creation_info *info) #endif /* network */ + lwsl_notice("LWS: %s, %s%s", library_version, opts_str, s); +#if defined(LWS_WITH_NETWORK) + lwsl_info("Event loop: %s", plev->ops->name); +#endif + /* * Proxy group */ @@ -1243,7 +1249,7 @@ lws_create_context(const struct lws_context_creation_info *info) } #endif - lws_context_init_ssl_library(info); + lws_context_init_ssl_library(context, info); context->user_space = info->user; @@ -1456,28 +1462,6 @@ early_bail: return NULL; -#if 0 -#if defined(LWS_WITH_NETWORK) -fail_clean_pipes: - -#if defined(LWS_WITH_LIBUV) - if (fatal_exit_defer) { - lws_context_destroy(context); - return context; - } -#endif - - for (n = 0; n < context->count_threads; n++) - lws_destroy_event_pipe(context->pt[n].pipe_wsi); - - lws_free_set_NULL(context->pt[0].fds); - lws_plat_context_late_destroy(context); - lws_free_set_NULL(context); - - return NULL; -#endif -#endif - #if defined(LWS_WITH_NETWORK) bail: lws_fi_destroy(&info->fic); @@ -1515,7 +1499,10 @@ free_context_fail2: lws_fi_destroy(&context->fic); } lws_fi_destroy(&info->fic); - lws_free(context); + if (context) { + lwsl_refcount_cx(context->log_cx, -1); + lws_free(context); + } return NULL; } @@ -1967,8 +1954,6 @@ next: while (context->vhost_pending_destruction_list) /* removes itself from list */ __lws_vhost_destroy2(context->vhost_pending_destruction_list); - - lwsl_debug("%p: post pdl\n", __func__); #endif #if defined(LWS_WITH_NETWORK) @@ -2169,8 +2154,9 @@ next: lws_fi_destroy(&context->fic); #endif + lwsl_refcount_cx(context->log_cx, -1); + lws_free(context); - lwsl_debug("%s: ctx %p freed\n", __func__, context); if (pcontext_finalize) *pcontext_finalize = NULL; @@ -2203,3 +2189,22 @@ lws_system_context_from_system_mgr(lws_state_manager_t *mgr) #endif } #endif + +void +lws_log_prepend_context(struct lws_log_cx *cx, void *obj, char **p, char *e) +{ + struct lws_context *lcx = (struct lws_context *)obj; + + if (lcx->name) + *p += lws_snprintf(*p, lws_ptr_diff_size_t(e, (*p)), "%s: ", + lcx->name); +} + +struct lws_log_cx * +lwsl_context_get_cx(struct lws_context *cx) +{ + if (!cx) + return NULL; + + return cx->log_cx; +} diff --git a/lib/core/logs.c b/lib/core/logs.c index 9d8a73387..3a7bb7ef0 100644 --- a/lib/core/logs.c +++ b/lib/core/logs.c @@ -1,7 +1,7 @@ /* * libwebsockets - small server side websockets and web server implementation * - * Copyright (C) 2010 - 2019 Andy Green + * Copyright (C) 2010 - 2021 Andy Green * * Permission is hereby granted, free of charge, to any person obtaining a copy * of this software and associated documentation files (the "Software"), to @@ -32,14 +32,15 @@ void lwsl_emit_optee(int level, const char *line); #endif -int log_level = LLL_ERR | LLL_WARN | LLL_NOTICE; -static void (*lwsl_emit)(int level, const char *line) -#ifndef LWS_PLAT_OPTEE - = lwsl_emit_stderr +lws_log_cx_t log_cx = { +#if !defined(LWS_PLAT_OPTEE) + .u.emit = lwsl_emit_stderr, #else - = lwsl_emit_optee; + .u.emit = lwsl_emit_optee, #endif - ; + .lll_flags = LLL_ERR | LLL_WARN | LLL_NOTICE, +}; + #if !defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NO_LOGS) static const char * log_level_names ="EWNIDPHXCLUT??"; #endif @@ -49,8 +50,8 @@ static const char * log_level_names ="EWNIDPHXCLUT??"; */ void -__lws_lc_tag(lws_lifecycle_group_t *grp, lws_lifecycle_t *lc, - const char *format, ...) +__lws_lc_tag(struct lws_context *context, lws_lifecycle_group_t *grp, + lws_lifecycle_t *lc, const char *format, ...) { va_list ap; int n = 1; @@ -96,11 +97,13 @@ __lws_lc_tag(lws_lifecycle_group_t *grp, lws_lifecycle_t *lc, lc->gutag[0] = '['; #if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) /* ie, will have getpid if set */ - n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - (unsigned int)n - 1u, - "%u|", getpid()); + n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - + (unsigned int)n - 1u, "%u|", getpid()); #endif - n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - (unsigned int)n - 1u, - "%s|%lx|", grp->tag_prefix, (unsigned long)grp->ordinal++); + n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - + (unsigned int)n - 1u, "%s|%lx|", + grp->tag_prefix, + (unsigned long)grp->ordinal++); va_start(ap, format); n += vsnprintf(&lc->gutag[n], sizeof(lc->gutag) - (unsigned int)n - @@ -118,6 +121,8 @@ __lws_lc_tag(lws_lifecycle_group_t *grp, lws_lifecycle_t *lc, lc->us_creation = (uint64_t)lws_now_usecs(); lws_dll2_add_tail(&lc->list, &grp->owner); + lwsl_refcount_cx(lc->log_cx, 1); + #if defined(LWS_LOG_TAG_LIFECYCLE) lwsl_notice(" ++ %s (%d)\n", lc->gutag, (int)grp->owner.count); #endif @@ -141,8 +146,8 @@ __lws_lc_tag_append(lws_lifecycle_t *lc, const char *app) if (n && lc->gutag[n - 1] == ']') n--; - n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - 2u - (unsigned int)n, - "|%s]", app); + n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - 2u - + (unsigned int)n, "|%s]", app); if ((unsigned int)n >= sizeof(lc->gutag) - 2u) { lc->gutag[sizeof(lc->gutag) - 2] = ']'; @@ -155,7 +160,7 @@ __lws_lc_tag_append(lws_lifecycle_t *lc, const char *app) */ void -__lws_lc_untag(lws_lifecycle_t *lc) +__lws_lc_untag(struct lws_context *context, lws_lifecycle_t *lc) { //lws_lifecycle_group_t *grp; char buf[24]; @@ -174,14 +179,18 @@ __lws_lc_untag(lws_lifecycle_t *lc) //grp = lws_container_of(lc->list.owner, lws_lifecycle_group_t, owner); - lws_humanize(buf, sizeof(buf), (uint64_t)lws_now_usecs() - lc->us_creation, - humanize_schema_us); + lws_humanize(buf, sizeof(buf), + (uint64_t)lws_now_usecs() - lc->us_creation, + humanize_schema_us); #if defined(LWS_LOG_TAG_LIFECYCLE) - lwsl_notice(" -- %s (%d) %s\n", lc->gutag, (int)lc->list.owner->count - 1, buf); + lwsl_notice(" -- %s (%d) %s", lc->gutag, + (int)lc->list.owner->count - 1, buf); #endif lws_dll2_remove(&lc->list); + + lwsl_refcount_cx(lc->log_cx, -1); } const char * @@ -207,7 +216,8 @@ lwsl_timestamp(int level, char *p, size_t len) gettimeofday(&tv, NULL); o_now = tv.tv_sec; - now = ((unsigned long long)tv.tv_sec * 10000) + (unsigned int)(tv.tv_usec / 100); + now = ((unsigned long long)tv.tv_sec * 10000) + + (unsigned int)(tv.tv_usec / 100); #if defined(LWS_HAVE_LOCALTIME_R) ptm = localtime_r(&o_now, &tm); @@ -262,20 +272,13 @@ static const char * const colours[] = { static char tty; static void -_lwsl_emit_stderr(int level, const char *line, int ts) +_lwsl_emit_stderr(int level, const char *line) { - char buf[50]; int n, m = LWS_ARRAY_SIZE(colours) - 1; if (!tty) tty = (char)(isatty(2) | 2); - buf[0] = '\0'; -#if defined(LWS_LOGS_TIMESTAMP) - if (ts) - lwsl_timestamp(level, buf, sizeof(buf)); -#endif - if (tty == 3) { n = 1 << (LWS_ARRAY_SIZE(colours) - 1); while (n) { @@ -284,27 +287,76 @@ _lwsl_emit_stderr(int level, const char *line, int ts) m--; n >>= 1; } - fprintf(stderr, "%c%s%s%s%c[0m", 27, colours[m], buf, line, 27); + fprintf(stderr, "%c%s%s%c[0m", 27, colours[m], line, 27); } else - fprintf(stderr, "%s%s", buf, line); + fprintf(stderr, "%s", line); } void lwsl_emit_stderr(int level, const char *line) { - _lwsl_emit_stderr(level, line, 1); + _lwsl_emit_stderr(level, line); } void lwsl_emit_stderr_notimestamp(int level, const char *line) { - _lwsl_emit_stderr(level, line, 0); + _lwsl_emit_stderr(level, line); +} + +#if !defined(LWS_PLAT_FREERTOS) && !defined(LWS_PLAT_OPTEE) + +/* + * Helper to emit to a file + */ + +void +lws_log_emit_cx_file(struct lws_log_cx *cx, int level, const char *line, + size_t len) +{ + int fd = (int)(intptr_t)cx->stg; + + if (fd >= 0) + if (write(fd, line, (unsigned int)len) != (ssize_t)len) + fprintf(stderr, "Unable to write log to file\n"); +} + +/* + * Helper to use a .refcount_cb to store logs in a file + */ + +void +lws_log_use_cx_file(struct lws_log_cx *cx, int _new) +{ + int fd; + + if (_new > 0 && cx->refcount == 1) { + fd = open((const char *)cx->opaque, + LWS_O_CREAT | LWS_O_TRUNC | LWS_O_WRONLY, 0600); + if (fd < 0) + fprintf(stderr, "Unable to open log %s: errno %d\n", + (const char *)cx->opaque, errno); + cx->stg = (void *)(intptr_t)fd; + + return; + } + + fd = (int)(intptr_t)cx->stg; + + if (_new <= 0 && cx->refcount == 0 && fd >= 0) { + close(fd); + cx->stg = (void *)(intptr_t)-1; + } } #endif +#endif + #if !(defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NETWORK)) -void _lws_logv(int filter, const char *format, va_list vl) +void +__lws_logv(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj, + int filter, const char *_fun, const char *format, va_list vl) { #if LWS_MAX_SMP == 1 && !defined(LWS_WITH_THREADPOOL) /* this is incompatible with multithreaded logging */ @@ -312,25 +364,103 @@ void _lws_logv(int filter, const char *format, va_list vl) #else char buf[1024]; #endif - int n; + char *p = buf, *end = p + sizeof(buf) - 1; + lws_log_cx_t *cxp; + int n, back = 0; - if (!(log_level & filter)) + /* + * We need to handle NULL wsi etc at the wrappers as gracefully as + * possible + */ + + if (!cx) { + lws_strncpy(p, "NULL log cx: ", sizeof(buf) - 1); + p += 13; + /* use the processwide one for lack of anything better */ + cx = &log_cx; + } + + cxp = cx; + + if (!(cx->lll_flags & (uint32_t)filter)) + /* + * logs may be produced and built in to the code but disabled + * at runtime + */ return; - n = vsnprintf(buf, sizeof(buf) - 1, format, vl); - (void)n; - /* vnsprintf returns what it would have written, even if truncated */ - if (n > (int)sizeof(buf) - 1) { - n = sizeof(buf) - 5; - buf[n++] = '.'; - buf[n++] = '.'; - buf[n++] = '.'; - buf[n++] = '\n'; - buf[n] = '\0'; +#if !defined(LWS_LOGS_TIMESTAMP) + if (cx->flags & LLLF_LOG_TIMESTAMP) +#endif + { + buf[0] = '\0'; + lwsl_timestamp(filter, buf, sizeof(buf)); + p += strlen(buf); } - if (n > 0) - buf[n] = '\0'; - lwsl_emit(filter, buf); + + /* + * prepend parent log ctx content first + * top level cx also gets an opportunity to prepend + */ + + while (cxp->parent) { + cxp = cxp->parent; + back++; + } + + do { + int b = back; + + cxp = cx; + while (b--) + cxp = cxp->parent; + if (cxp->prepend) + cxp->prepend(cxp, NULL, &p, end); + + back--; + } while (back > 0); + + if (prep) + prep(cxp, obj, &p, end); + + if (_fun) + p += lws_snprintf(p, lws_ptr_diff_size_t(end, p), "%s: ", _fun); + + /* + * The actual log content + */ + + n = vsnprintf(p, lws_ptr_diff_size_t(end, p), format, vl); + + /* vnsprintf returns what it would have written, even if truncated */ + if (p + n > end - 2) { + p = end - 5; + *p++ = '.'; + *p++ = '.'; + *p++ = '.'; + *p++ = '\n'; + *p++ = '\0'; + } else + if (n > 0) { + p += n; + if (p[-1] != '\n') + *p++ = '\n'; + *p = '\0'; + } + + /* + * The actual emit + */ + + if (cx->lll_flags & LLLF_LOG_CONTEXT_AWARE) + cx->u.emit_cx(cx, filter, buf, lws_ptr_diff_size_t(p, buf)); + else + cx->u.emit(filter, buf); +} + +void _lws_logv(int filter, const char *format, va_list vl) +{ + __lws_logv(&log_cx, NULL, NULL, filter, NULL, format, vl); } void _lws_log(int filter, const char *format, ...) @@ -338,42 +468,83 @@ void _lws_log(int filter, const char *format, ...) va_list ap; va_start(ap, format); - _lws_logv(filter, format, ap); + __lws_logv(&log_cx, NULL, NULL, filter, NULL, format, ap); + va_end(ap); +} + +void _lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj, + int filter, const char *_fun, const char *format, ...) +{ + va_list ap; + + if (!cx) + cx = &log_cx; + + va_start(ap, format); + __lws_logv(cx, prep, obj, filter, _fun, format, ap); va_end(ap); } #endif -void lws_set_log_level(int level, void (*func)(int level, const char *line)) + +void +lws_set_log_level(int flags, lws_log_emit_t func) { - log_level = level; + log_cx.lll_flags = (uint32_t)(flags & (~LLLF_LOG_CONTEXT_AWARE)); + if (func) - lwsl_emit = func; + log_cx.u.emit = func; } int lwsl_visible(int level) { - return log_level & level; + return !!(log_cx.lll_flags & (uint32_t)level); +} + +int lwsl_visible_cx(lws_log_cx_t *cx, int level) +{ + return !!(cx->lll_flags & (uint32_t)level); } void -lwsl_hexdump_level(int hexdump_level, const void *vbuf, size_t len) +lwsl_refcount_cx(lws_log_cx_t *cx, int _new) +{ + if (!cx) + return; + + if (_new > 0) + cx->refcount++; + else { + assert(cx->refcount); + cx->refcount--; + } + + if (cx->refcount_cb) + cx->refcount_cb(cx, _new); +} + +void +lwsl_hexdump_level_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj, + int hexdump_level, const void *vbuf, size_t len) { unsigned char *buf = (unsigned char *)vbuf; unsigned int n; - if (!lwsl_visible(hexdump_level)) + if (!lwsl_visible_cx(cx, hexdump_level)) return; if (!len) { - _lws_log(hexdump_level, "(hexdump: zero length)\n"); + _lws_log_cx(cx, prep, obj, hexdump_level, NULL, + "(hexdump: zero length)\n"); return; } if (!vbuf) { - _lws_log(hexdump_level, "(hexdump: NULL ptr)\n"); + _lws_log_cx(cx, prep, obj, hexdump_level, NULL, + "(hexdump: NULL ptr)\n"); return; } - _lws_log(hexdump_level, "\n"); + _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n"); for (n = 0; n < len;) { unsigned int start = n, m; @@ -399,11 +570,17 @@ lwsl_hexdump_level(int hexdump_level, const void *vbuf, size_t len) *p++ = '\n'; *p = '\0'; - _lws_log(hexdump_level, "%s", line); + _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "%s", line); (void)line; } - _lws_log(hexdump_level, "\n"); + _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n"); +} + +void +lwsl_hexdump_level(int hexdump_level, const void *vbuf, size_t len) +{ + lwsl_hexdump_level_cx(&log_cx, NULL, NULL, hexdump_level, vbuf, len); } void diff --git a/lib/core/private-lib-core.h b/lib/core/private-lib-core.h index d21238e06..d98d8386b 100644 --- a/lib/core/private-lib-core.h +++ b/lib/core/private-lib-core.h @@ -195,21 +195,24 @@ typedef struct lws_lifecycle { #endif lws_dll2_t list; /* group list membership */ uint64_t us_creation; /* creation timestamp */ + lws_log_cx_t *log_cx; } lws_lifecycle_t; void -__lws_lc_tag(lws_lifecycle_group_t *grp, lws_lifecycle_t *lc, - const char *format, ...); +__lws_lc_tag(struct lws_context *cx, lws_lifecycle_group_t *grp, + lws_lifecycle_t *lc, const char *format, ...); void __lws_lc_tag_append(lws_lifecycle_t *lc, const char *app); void -__lws_lc_untag(lws_lifecycle_t *lc); +__lws_lc_untag(struct lws_context *cx, lws_lifecycle_t *lc); const char * lws_lc_tag(lws_lifecycle_t *lc); +extern lws_log_cx_t log_cx; + /* * Generic bidi tx credit management */ @@ -597,6 +600,9 @@ struct lws_context { #endif /* NETWORK */ + lws_log_cx_t *log_cx; + const char *name; + #if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) const char *ss_proxy_bind; const char *ss_proxy_address; @@ -777,8 +783,6 @@ struct lws_buflist { char * lws_strdup(const char *s); -extern int log_level; - int lws_b64_selftest(void); @@ -805,7 +809,7 @@ void lwsl_emit_stderr(int level, const char *line); #define lws_ssl_SSL_CTX_destroy(_a) #define lws_ssl_remove_wsi_from_buffered_list(_a) #define __lws_ssl_remove_wsi_from_buffered_list(_a) - #define lws_context_init_ssl_library(_a) + #define lws_context_init_ssl_library(_a, _b) #define lws_context_deinit_ssl_library(_a) #define lws_tls_check_all_cert_lifetimes(_a) #define lws_tls_acme_sni_cert_destroy(_a) diff --git a/lib/misc/cache-ttl/heap.c b/lib/misc/cache-ttl/heap.c index b3a32394c..1ea7edfb1 100644 --- a/lib/misc/cache-ttl/heap.c +++ b/lib/misc/cache-ttl/heap.c @@ -511,7 +511,7 @@ lws_cache_heap_create(const struct lws_cache_creation_info *info) if (info->parent) info->parent->child = &cache->cache; - lwsl_cache("%s: create %s\n", __func__, info->name); + // lwsl_cache("%s: create %s\n", __func__, info->name); return (struct lws_cache_ttl_lru *)cache; } @@ -552,9 +552,6 @@ lws_cache_heap_destroy(struct lws_cache_ttl_lru **_cache) lws_dll2_foreach_safe(&cache->items_lru, cache, destroy_dll); - lwsl_cache("%s: destroy %s\n", __func__, c->info.name ? - c->info.name : "?"); - lws_free_set_NULL(*_cache); } diff --git a/lib/plat/unix/unix-fds.c b/lib/plat/unix/unix-fds.c index ec457664d..d6cd64d2e 100644 --- a/lib/plat/unix/unix-fds.c +++ b/lib/plat/unix/unix-fds.c @@ -192,9 +192,7 @@ delete_from_fd(const struct lws_context *context, int fd) while (p != done && (!*p || (*p)->desc.sockfd != fd)) p++; - if (p == done) - lwsl_debug("%s: fd %d not found\n", __func__, fd); - else + if (p != done) *p = NULL; #if defined(_DEBUG) diff --git a/lib/plat/unix/unix-spawn.c b/lib/plat/unix/unix-spawn.c index af8318090..1c68d45bf 100644 --- a/lib/plat/unix/unix-spawn.c +++ b/lib/plat/unix/unix-spawn.c @@ -83,7 +83,7 @@ lws_create_stdwsi(struct lws_context *context, int tsi, } lws_context_lock(context, __func__); - new_wsi = __lws_wsi_create_with_role(context, tsi, ops); + new_wsi = __lws_wsi_create_with_role(context, tsi, ops, NULL); lws_context_unlock(context); if (new_wsi == NULL) { lwsl_err("Out of memory for new connection\n"); @@ -382,8 +382,8 @@ lws_spawn_piped(const struct lws_spawn_piped_info *i) goto bail2; } - __lws_lc_tag(&i->vh->context->lcg[LWSLCG_WSI], &lsp->stdwsi[n]->lc, - "nspawn-stdwsi-%d", n); + __lws_lc_tag(i->vh->context, &i->vh->context->lcg[LWSLCG_WSI], + &lsp->stdwsi[n]->lc, "nspawn-stdwsi-%d", n); lsp->stdwsi[n]->lsp_channel = (uint8_t)n; lws_vhost_bind_wsi(i->vh, lsp->stdwsi[n]); diff --git a/lib/plat/windows/windows-spawn.c b/lib/plat/windows/windows-spawn.c index 10eb5d186..a7c0322e3 100644 --- a/lib/plat/windows/windows-spawn.c +++ b/lib/plat/windows/windows-spawn.c @@ -78,7 +78,7 @@ lws_create_basic_wsi(struct lws_context *context, int tsi, } lws_context_lock(context, __func__); - new_wsi = __lws_wsi_create_with_role(context, tsi, ops); + new_wsi = __lws_wsi_create_with_role(context, tsi, ops, NULL); lws_context_unlock(context); if (new_wsi == NULL) { lwsl_err("Out of memory for new connection\n"); @@ -415,8 +415,8 @@ lws_spawn_piped(const struct lws_spawn_piped_info *i) goto bail2; } - __lws_lc_tag(&i->vh->context->lcg[LWSLCG_WSI], &lsp->stdwsi[n]->lc, - "nspawn-stdwsi-%d", n); + __lws_lc_tag(i->vh->context, &i->vh->context->lcg[LWSLCG_WSI], + &lsp->stdwsi[n]->lc, "nspawn-stdwsi-%d", n); lsp->stdwsi[n]->lsp_channel = n; lws_vhost_bind_wsi(i->vh, lsp->stdwsi[n]); diff --git a/lib/roles/dbus/dbus.c b/lib/roles/dbus/dbus.c index e8e58078c..34457925f 100644 --- a/lib/roles/dbus/dbus.c +++ b/lib/roles/dbus/dbus.c @@ -72,7 +72,8 @@ __lws_shadow_wsi(struct lws_dbus_ctx *ctx, DBusWatch *w, int fd, int create_ok) lws_vhost_assert_lock_held(wsi->a.vhost); /* requires context lock */ - wsi = __lws_wsi_create_with_role(ctx->vh->context, ctx->tsi, NULL); + wsi = __lws_wsi_create_with_role(ctx->vh->context, ctx->tsi, NULL, + ctx->vh->lc.log_cx); if (wsi == NULL) { lwsl_err("Out of mem\n"); return NULL; @@ -87,7 +88,8 @@ __lws_shadow_wsi(struct lws_dbus_ctx *ctx, DBusWatch *w, int fd, int create_ok) wsi->opaque_parent_data = ctx; ctx->w[0] = w; - __lws_lc_tag(&ctx->vh->context->lcg[LWSLCG_WSI], &wsi->lc, "dbus|%s", ctx->vh->name); + __lws_lc_tag(ctx->vh->context, &ctx->vh->context->lcg[LWSLCG_WSI], + &wsi->lc, "dbus|%s", ctx->vh->name); lws_vhost_bind_wsi(ctx->vh, wsi); if (__insert_wsi_socket_into_fds(ctx->vh->context, wsi)) { diff --git a/lib/roles/http/server/server.c b/lib/roles/http/server/server.c index 8c1f74cae..4b61922b6 100644 --- a/lib/roles/http/server/server.c +++ b/lib/roles/http/server/server.c @@ -301,7 +301,7 @@ done_list: */ lws_context_lock(cx, __func__); - wsi = __lws_wsi_create_with_role(cx, m, &role_ops_listen); + wsi = __lws_wsi_create_with_role(cx, m, &role_ops_listen, NULL); lws_context_unlock(cx); if (wsi == NULL) { lwsl_err("Out of mem\n"); @@ -371,7 +371,8 @@ done_list: } if (wsi) - __lws_lc_tag(&a->vhost->context->lcg[LWSLCG_WSI], + __lws_lc_tag(a->vhost->context, + &a->vhost->context->lcg[LWSLCG_WSI], &wsi->lc, "listen|%s|%s|%d", a->vhost->name, a->vhost->iface ? a->vhost->iface : "", diff --git a/lib/roles/netlink/ops-netlink.c b/lib/roles/netlink/ops-netlink.c index f9ef3ebd9..8a9d0265d 100644 --- a/lib/roles/netlink/ops-netlink.c +++ b/lib/roles/netlink/ops-netlink.c @@ -338,7 +338,7 @@ second_half: case RTM_DELADDR: lwsl_notice("%s: DELADDR\n", __func__); #if defined(_DEBUG) - _lws_routing_entry_dump(&robj); + _lws_routing_entry_dump(cx, &robj); #endif lws_pt_lock(pt, __func__); _lws_route_remove(pt, &robj, LRR_MATCH_SRC | LRR_IGNORE_PRI); @@ -498,18 +498,19 @@ rops_pt_init_destroy_netlink(struct lws_context *context, lws_context_lock(context, __func__); wsi = __lws_wsi_create_with_role(context, (int)(pt - &context->pt[0]), - &role_ops_netlink); + &role_ops_netlink, NULL); lws_context_unlock(context); if (!wsi) goto bail; wsi->desc.sockfd = socket(AF_NETLINK, SOCK_RAW, NETLINK_ROUTE); if (wsi->desc.sockfd == LWS_SOCK_INVALID) { - lwsl_err("%s: unable to open netlink\n", __func__); + lwsl_err("unable to open netlink\n"); goto bail1; } - __lws_lc_tag(&context->lcg[LWSLCG_VHOST], &wsi->lc, "netlink"); + __lws_lc_tag(context, &context->lcg[LWSLCG_VHOST], &wsi->lc, + "netlink"); memset(&sanl, 0, sizeof(sanl)); sanl.nl_family = AF_NETLINK; @@ -585,7 +586,7 @@ rops_pt_init_destroy_netlink(struct lws_context *context, return 0; bail2: - __lws_lc_untag(&wsi->lc); + __lws_lc_untag(wsi->a.context, &wsi->lc); compatible_close(wsi->desc.sockfd); bail1: lws_free(wsi); diff --git a/lib/secure-streams/private-lib-secure-streams.h b/lib/secure-streams/private-lib-secure-streams.h index 12d5c6081..12b6f001f 100644 --- a/lib/secure-streams/private-lib-secure-streams.h +++ b/lib/secure-streams/private-lib-secure-streams.h @@ -426,9 +426,6 @@ int lws_ss_serialize_state(struct lws *wsi, struct lws_dsh *dsh, lws_ss_constate_t state, lws_ss_tx_ordinal_t ack); -void -lws_ss_serialize_state_transition(lws_ss_conn_states_t *state, int new_state); - const lws_ss_policy_t * lws_ss_policy_lookup(const struct lws_context *context, const char *streamtype); @@ -519,6 +516,14 @@ int lws_ss_check_next_state(lws_lifecycle_t *lc, uint8_t *prevstate, lws_ss_constate_t cs); +int +lws_ss_check_next_state_ss(lws_ss_handle_t *ss, uint8_t *prevstate, + lws_ss_constate_t cs); + +int +lws_ss_check_next_state_sspc(lws_sspc_handle_t *ss, uint8_t *prevstate, + lws_ss_constate_t cs); + void lws_proxy_clean_conn_ss(struct lws *wsi); diff --git a/lib/secure-streams/secure-streams-client.c b/lib/secure-streams/secure-streams-client.c index 3e5abaa70..b5f7e0825 100644 --- a/lib/secure-streams/secure-streams-client.c +++ b/lib/secure-streams/secure-streams-client.c @@ -19,6 +19,55 @@ */ #include +extern const uint32_t ss_state_txn_validity[17]; + +int +lws_ss_check_next_state_sspc(lws_sspc_handle_t *ss, uint8_t *prevstate, + lws_ss_constate_t cs) +{ + if (cs >= LWSSSCS_USER_BASE || cs == LWSSSCS_EVENT_WAIT_CANCELLED) + /* + * we can't judge user or transient states, leave the old state + * and just wave them through + */ + return 0; + + if (cs >= LWS_ARRAY_SIZE(ss_state_txn_validity)) { + /* we don't recognize this state as usable */ + lwsl_sspc_err(ss, "bad new state %u", cs); + assert(0); + return 1; + } + + if (*prevstate >= LWS_ARRAY_SIZE(ss_state_txn_validity)) { + /* existing state is broken */ + lwsl_sspc_err(ss, "bad existing state %u", + (unsigned int)*prevstate); + assert(0); + return 1; + } + + if (ss_state_txn_validity[*prevstate] & (1u << cs)) { + + lwsl_sspc_notice(ss, "%s -> %s", + lws_ss_state_name((int)*prevstate), + lws_ss_state_name((int)cs)); + + /* this is explicitly allowed, update old state to new */ + *prevstate = (uint8_t)cs; + + return 0; + } + + lwsl_sspc_err(ss, "transition from %s -> %s is illegal", + lws_ss_state_name((int)*prevstate), + lws_ss_state_name((int)cs)); + + assert(0); + + return 1; +} + lws_ss_state_return_t lws_sspc_event_helper(lws_sspc_handle_t *h, lws_ss_constate_t cs, lws_ss_tx_ordinal_t flags) @@ -28,7 +77,7 @@ lws_sspc_event_helper(lws_sspc_handle_t *h, lws_ss_constate_t cs, if (!h) return LWSSSSRET_OK; - if (lws_ss_check_next_state(&h->lc, &h->prev_ss_state, cs)) + if (lws_ss_check_next_state_sspc(h, &h->prev_ss_state, cs)) return LWSSSSRET_DESTROY_ME; if (!h->ssi.state) @@ -100,17 +149,18 @@ lws_sspc_sul_retry_cb(lws_sorted_usec_list_t *sul) return; } - lwsl_notice("%s: %s\n", __func__, h->cwsi->lc.gutag); + lwsl_notice("%s\n", h->cwsi->lc.gutag); } static int -lws_sspc_serialize_metadata(lws_sspc_metadata_t *md, uint8_t *p, uint8_t *end) +lws_sspc_serialize_metadata(lws_sspc_handle_t *h, lws_sspc_metadata_t *md, + uint8_t *p, uint8_t *end) { int n, txc; if (md->name[0] == '\0') { - lwsl_info("%s: sending tx credit update %d\n", __func__, + lwsl_info("sending tx credit update %d\n", md->tx_cr_adjust); p[0] = LWSSS_SER_TXPRE_TXCR_UPDATE; @@ -368,18 +418,18 @@ callback_sspc_client(struct lws *wsi, enum lws_callback_reasons reason, cp = p = pkt + LWS_PRE; end = p + pktsize; - n = lws_sspc_serialize_metadata(md, p, end); + n = lws_sspc_serialize_metadata(h, md, p, end); if (n < 0) goto metadata_hangup; - lwsl_debug("%s: (local_conn) metadata\n", __func__); + lwsl_debug("(local_conn) metadata\n"); goto req_write_and_issue; } if (h->pending_writeable_len) { - lwsl_debug("%s: (local_conn) PAYLOAD_LENGTH_HINT %u\n", - __func__, (unsigned int)h->writeable_len); + lwsl_debug("(local_conn) PAYLOAD_LENGTH_HINT %u", + (unsigned int)h->writeable_len); s[0] = LWSSS_SER_TXPRE_PAYLOAD_LENGTH_HINT; lws_ser_wu16be(&s[1], 4); lws_ser_wu32be(&s[3], (uint32_t)h->writeable_len); @@ -426,7 +476,7 @@ callback_sspc_client(struct lws *wsi, enum lws_callback_reasons reason, lws_dll2_get_tail(&h->metadata_owner), lws_sspc_metadata_t, list); - n = lws_sspc_serialize_metadata(md, p, end); + n = lws_sspc_serialize_metadata(h, md, p, end); if (n < 0) goto metadata_hangup; @@ -566,6 +616,8 @@ lws_sspc_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, return 1; memset(h, 0, sizeof(*h)); + h->lc.log_cx = context->log_cx; + #if defined(LWS_WITH_SYS_FAULT_INJECTION) h->fic.name = "sspc"; lws_xos_init(&h->fic.xos, lws_xos(&context->fic.xos)); @@ -585,7 +637,8 @@ lws_sspc_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, return 1; } - __lws_lc_tag(&context->lcg[LWSLCG_SSP_CLIENT], &h->lc, ssi->streamtype); + __lws_lc_tag(context, &context->lcg[LWSLCG_SSP_CLIENT], &h->lc, + ssi->streamtype); memcpy(&h->ssi, ssi, sizeof(*ssi)); ua = (uint8_t *)&h[1]; @@ -651,8 +704,6 @@ lws_sspc_destroy(lws_sspc_handle_t **ph) { lws_sspc_handle_t *h; - lwsl_debug("%s\n", __func__); - if (!*ph) return; @@ -716,12 +767,13 @@ lws_sspc_destroy(lws_sspc_handle_t **ph) lws_sul_cancel(&h->sul_retry); - __lws_lc_untag(&h->lc); /* confirm no sul left scheduled in handle or user allocation object */ lws_sul_debug_zombies(h->context, h, sizeof(*h) + h->ssi.user_alloc, __func__); + __lws_lc_untag(h->context, &h->lc); + free(h); } diff --git a/lib/secure-streams/secure-streams-serialize.c b/lib/secure-streams/secure-streams-serialize.c index 29e9d0801..967ff06e1 100644 --- a/lib/secure-streams/secure-streams-serialize.c +++ b/lib/secure-streams/secure-streams-serialize.c @@ -108,11 +108,31 @@ static const char *sn[] = { }; #endif +struct lws_log_cx * +lwsl_sspc_get_cx(struct lws_sspc_handle *sspc) +{ + if (!sspc) + return NULL; + + return sspc->lc.log_cx; +} + + void -lws_ss_serialize_state_transition(lws_ss_conn_states_t *state, int new_state) +lws_log_prepend_sspc(struct lws_log_cx *cx, void *obj, char **p, char *e) +{ + struct lws_sspc_handle *h = (struct lws_sspc_handle *)obj; + + *p += lws_snprintf(*p, lws_ptr_diff_size_t(e, (*p)), "%s: ", + lws_sspc_tag(h)); +} + +static void +lws_ss_serialize_state_transition(lws_sspc_handle_t *h, + lws_ss_conn_states_t *state, int new_state) { #if defined(_DEBUG) - lwsl_info("%s: %s -> %s\n", __func__, sn[*state], sn[new_state]); + lwsl_info("%s -> %s", sn[*state], sn[new_state]); #endif *state = (lws_ss_conn_states_t)new_state; } @@ -226,33 +246,6 @@ lws_ss_deserialize_tx_payload(struct lws_dsh *dsh, struct lws *wsi, *flags = (int)lws_ser_ru32be(&p[3]); -#if 0 - if (wsi && wsi->a.context->detailed_latency_cb) { - /* - * use the proxied latency information to compute the client - * and our delays, and apply to wsi. - * - * + 7 u32 us held at client before written - * +11 u32 us taken for transit to proxy - * +15 u64 ustime when proxy got packet from client - */ - lws_usec_t us = lws_now_usecs(); - - wsi->detlat.acc_size = wsi->detlat.req_size = si - 23; - wsi->detlat.latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE] = - lws_ser_ru32be(&p[7]); - wsi->detlat.latencies[LAT_DUR_PROXY_CLIENT_WRITE_TO_PROXY_RX] = - lws_ser_ru32be(&p[11]); - wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = - us - lws_ser_ru64be(&p[15]); - - wsi->detlat.latencies[LAT_DUR_USERCB] = 0; - } -#endif - - // lwsl_user("%s: len %d, flags: %d\n", __func__, (int)*len, *flags); - // lwsl_hexdump_info(buf, *len); - lws_dsh_free((void **)&p); return 0; @@ -378,6 +371,7 @@ lws_ss_deserialize_parse(struct lws_ss_serialization_parser *par, int n; while (len--) { + switch (par->ps) { case RPAR_TYPE: par->type = *cp++; @@ -714,6 +708,8 @@ payload_ff: us = lws_now_usecs(); if (!client) { + lws_ss_handle_t *hss; + /* * Proxy - we received some serialized tx from * the client. @@ -724,8 +720,9 @@ payload_ff: * additionally */ - lwsl_info("%s: C2P RX: len %d\n", __func__, - (int)n); + hss = proxy_pss_to_ss_h(pss); + if (hss) + lwsl_info("C2P RX: len %d", (int)n); p = pre; pre[0] = LWSSS_SER_TXPRE_TX_PAYLOAD; @@ -738,19 +735,17 @@ payload_ff: /* time used later to find proxy hold time */ lws_ser_wu64be(&p[15], (uint64_t)us); - if ((proxy_pss_to_ss_h(pss) && - lws_fi(&proxy_pss_to_ss_h(pss)->fic, "ssproxy_dsh_c2p_pay_oom")) || + if ((hss && + lws_fi(&hss->fic, "ssproxy_dsh_c2p_pay_oom")) || lws_dsh_alloc_tail(dsh, KIND_C_TO_P, pre, 23, cp, (unsigned int)n)) { - lwsl_err("%s: unable to alloc in dsh 3\n", - __func__); + lwsl_err("unable to alloc in dsh 3\n"); return LWSSSSRET_DISCONNECT_ME; } - if (proxy_pss_to_ss_h(pss)) - _lws_ss_request_tx( - proxy_pss_to_ss_h(pss)); + if (hss) + _lws_ss_request_tx(hss); } else { /* @@ -1284,9 +1279,11 @@ payload_ff: * Client (par->temp32 == dsh alloc) */ - lws_ss_serialize_state_transition(state, - LPCSCLI_LOCAL_CONNECTED); h = lws_container_of(par, lws_sspc_handle_t, parser); + + lws_ss_serialize_state_transition(h, state, + LPCSCLI_LOCAL_CONNECTED); + lws_set_timeout(h->cwsi, NO_PENDING_TIMEOUT, 0); if (h->dsh) @@ -1320,8 +1317,9 @@ payload_ff: #endif if (!h->creating_cb_done) { - if (lws_ss_check_next_state(&h->lc, &h->prev_ss_state, - LWSSSCS_CREATING)) + if (lws_ss_check_next_state_sspc(h, + &h->prev_ss_state, + LWSSSCS_CREATING)) return LWSSSSRET_DESTROY_ME; h->prev_ss_state = (uint8_t)LWSSSCS_CREATING; h->creating_cb_done = 1; @@ -1409,7 +1407,8 @@ payload_ff: * Client received a proxied state change */ - if (!client_pss_to_sspc_h(pss, ssi)) + h = client_pss_to_sspc_h(pss, ssi); + if (!h) /* * Since we're being informed we need to have * a stream to inform. Assume whatever set this @@ -1421,25 +1420,25 @@ payload_ff: case LWSSSCS_DISCONNECTED: case LWSSSCS_UNREACHABLE: case LWSSSCS_AUTH_FAILED: - lws_ss_serialize_state_transition(state, + lws_ss_serialize_state_transition(h, state, LPCSCLI_LOCAL_CONNECTED); - client_pss_to_sspc_h(pss, ssi)->conn_req_state = - LWSSSPC_ONW_NONE; + h->conn_req_state = LWSSSPC_ONW_NONE; break; + case LWSSSCS_CONNECTED: - lwsl_info("%s: CONNECTED %s\n", __func__, - ssi->streamtype); + lwsl_info("CONNECTED %s", + ssi->streamtype); if (*state == LPCSCLI_OPERATIONAL) /* * Don't allow to see connected more * than once for one connection */ goto swallow; - lws_ss_serialize_state_transition(state, - LPCSCLI_OPERATIONAL); - client_pss_to_sspc_h(pss, ssi)->conn_req_state = - LWSSSPC_ONW_CONN; + lws_ss_serialize_state_transition(h, state, + LPCSCLI_OPERATIONAL); + + h->conn_req_state = LWSSSPC_ONW_CONN; break; case LWSSSCS_TIMEOUT: break; @@ -1478,7 +1477,7 @@ payload_ff: if (cs == LWSSSCS_DISCONNECTED) h->ss_dangling_connected = 0; - if (lws_ss_check_next_state(&h->lc, + if (lws_ss_check_next_state_sspc(h, &h->prev_ss_state, cs)) return LWSSSSRET_DESTROY_ME; diff --git a/lib/secure-streams/secure-streams.c b/lib/secure-streams/secure-streams.c index e6bcae245..edd9fe258 100644 --- a/lib/secure-streams/secure-streams.c +++ b/lib/secure-streams/secure-streams.c @@ -79,7 +79,7 @@ static const char *state_names[] = { * (because we will assert if we have bugs that do it) */ -static const uint32_t ss_state_txn_validity[] = { +const uint32_t ss_state_txn_validity[] = { /* if we was last in this state... we can legally go to these states */ @@ -318,6 +318,53 @@ lws_ss_check_next_state(lws_lifecycle_t *lc, uint8_t *prevstate, return 1; } +int +lws_ss_check_next_state_ss(lws_ss_handle_t *ss, uint8_t *prevstate, + lws_ss_constate_t cs) +{ + if (cs >= LWSSSCS_USER_BASE || cs == LWSSSCS_EVENT_WAIT_CANCELLED) + /* + * we can't judge user or transient states, leave the old state + * and just wave them through + */ + return 0; + + if (cs >= LWS_ARRAY_SIZE(ss_state_txn_validity)) { + /* we don't recognize this state as usable */ + lwsl_err("bad new state %u", cs); + assert(0); + return 1; + } + + if (*prevstate >= LWS_ARRAY_SIZE(ss_state_txn_validity)) { + /* existing state is broken */ + lwsl_err("bad existing state %u", + (unsigned int)*prevstate); + assert(0); + return 1; + } + + if (ss_state_txn_validity[*prevstate] & (1u << cs)) { + + lwsl_notice("%s -> %s", + lws_ss_state_name((int)*prevstate), + lws_ss_state_name((int)cs)); + + /* this is explicitly allowed, update old state to new */ + *prevstate = (uint8_t)cs; + + return 0; + } + + lwsl_err("transition from %s -> %s is illegal", + lws_ss_state_name((int)*prevstate), + lws_ss_state_name((int)cs)); + + assert(0); + + return 1; +} + const char * lws_ss_state_name(int state) { @@ -338,7 +385,7 @@ lws_ss_event_helper(lws_ss_handle_t *h, lws_ss_constate_t cs) if (!h) return LWSSSSRET_OK; - if (lws_ss_check_next_state(&h->lc, &h->prev_ss_state, cs)) + if (lws_ss_check_next_state_ss(h, &h->prev_ss_state, cs)) return LWSSSSRET_DESTROY_ME; if (cs == LWSSSCS_CONNECTED) @@ -950,14 +997,18 @@ lws_ss_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, if (!h) return 2; + h->lc.log_cx = context->log_cx; + if (ssi->sss_protocol_version) - __lws_lc_tag(&context->lcg[LWSLCG_WSI_SS_CLIENT], &h->lc, "%s|v%u|%u", + __lws_lc_tag(context, &context->lcg[LWSLCG_WSI_SS_CLIENT], + &h->lc, "%s|v%u|%u", ssi->streamtype ? ssi->streamtype : "nostreamtype", (unsigned int)ssi->sss_protocol_version, (unsigned int)ssi->client_pid); else - __lws_lc_tag(&context->lcg[LWSLCG_WSI_SS_CLIENT], &h->lc, "%s", - ssi->streamtype ? ssi->streamtype : "nostreamtype"); + __lws_lc_tag(context, &context->lcg[LWSLCG_WSI_SS_CLIENT], + &h->lc, "%s", + ssi->streamtype ? ssi->streamtype : "nostreamtype"); #if defined(LWS_WITH_SYS_FAULT_INJECTION) h->fic.name = "ss"; @@ -1203,7 +1254,7 @@ late_bail: lws_pt_unlock(pt); lws_fi_destroy(&h->fic); - __lws_lc_untag(&h->lc); + __lws_lc_untag(context, &h->lc); lws_free(h); return 1; @@ -1410,7 +1461,7 @@ lws_ss_destroy(lws_ss_handle_t **ppss) lws_sul_debug_zombies(h->context, h, sizeof(*h) + h->info.user_alloc, __func__); - __lws_lc_untag(&h->lc); + __lws_lc_untag(h->context, &h->lc); lws_free_set_NULL(h); } @@ -1665,3 +1716,21 @@ lws_ss_tag(struct lws_ss_handle *h) return "[null ss]"; return lws_lc_tag(&h->lc); } + +struct lws_log_cx * +lwsl_ss_get_cx(struct lws_ss_handle *ss) +{ + if (!ss) + return NULL; + + return ss->lc.log_cx; +} + +void +lws_log_prepend_ss(struct lws_log_cx *cx, void *obj, char **p, char *e) +{ + struct lws_ss_handle *h = (struct lws_ss_handle *)obj; + + *p += lws_snprintf(*p, lws_ptr_diff_size_t(e, (*p)), "%s: ", + lws_ss_tag(h)); +} diff --git a/lib/system/async-dns/async-dns.c b/lib/system/async-dns/async-dns.c index c46c8f34c..f479480f3 100644 --- a/lib/system/async-dns/async-dns.c +++ b/lib/system/async-dns/async-dns.c @@ -554,7 +554,7 @@ lws_async_dns_deinit(lws_async_dns_t *dns) if (dns->wsi && !dns->dns_server_connected) { lwsl_notice("%s: late free of incomplete dns wsi\n", __func__); - __lws_lc_untag(&dns->wsi->lc); + __lws_lc_untag(dns->wsi->a.context, &dns->wsi->lc); #if defined(LWS_WITH_SYS_METRICS) lws_metrics_tags_destroy(&dns->wsi->cal_conn.mtags_owner); #endif diff --git a/lib/system/metrics/metrics.c b/lib/system/metrics/metrics.c index 8aa48c955..92d5e0d0f 100644 --- a/lib/system/metrics/metrics.c +++ b/lib/system/metrics/metrics.c @@ -68,7 +68,7 @@ lws_metrics_tag_add(lws_dll2_owner_t *owner, const char *name, const char *val) int lws_metrics_tag_wsi_add(struct lws *wsi, const char *name, const char *val) { - __lws_lc_tag(NULL, &wsi->lc, "|%s", val); + __lws_lc_tag(wsi->a.context, NULL, &wsi->lc, "|%s", val); return lws_metrics_tag_add(&wsi->cal_conn.mtags_owner, name, val); } @@ -77,15 +77,15 @@ lws_metrics_tag_wsi_add(struct lws *wsi, const char *name, const char *val) int lws_metrics_tag_ss_add(struct lws_ss_handle *ss, const char *name, const char *val) { - __lws_lc_tag(NULL, &ss->lc, "|%s", val); + __lws_lc_tag(ss->context, NULL, &ss->lc, "|%s", val); return lws_metrics_tag_add(&ss->cal_txn.mtags_owner, name, val); } -#if defined(LWS_WITH_SECURE_STREAMS) +#if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) int lws_metrics_tag_sspc_add(struct lws_sspc_handle *sspc, const char *name, const char *val) { - __lws_lc_tag(NULL, &sspc->lc, "|%s", val); + __lws_lc_tag(sspc->context, NULL, &sspc->lc, "|%s", val); return lws_metrics_tag_add(&sspc->cal_txn.mtags_owner, name, val); } #endif diff --git a/lib/system/smd/private-lib-system-smd.h b/lib/system/smd/private-lib-system-smd.h index e79165740..452ba15a3 100644 --- a/lib/system/smd/private-lib-system-smd.h +++ b/lib/system/smd/private-lib-system-smd.h @@ -53,6 +53,7 @@ typedef struct lws_smd_peer { #endif lws_smd_notification_cb_t cb; /* LSMDT_ */ + struct lws_context *ctx; void *opaque; /* NULL, or next message we will handle */ @@ -91,5 +92,3 @@ lws_smd_msg_distribute(struct lws_context *ctx); int _lws_smd_destroy(struct lws_context *ctx); -int -_lws_smd_msg_send(struct lws_context *ctx, void *pay, struct lws_smd_peer *exc); diff --git a/lib/system/smd/smd.c b/lib/system/smd/smd.c index 763070169..241d60828 100644 --- a/lib/system/smd/smd.c +++ b/lib/system/smd/smd.c @@ -159,7 +159,7 @@ _lws_smd_class_mask_union(lws_smd_t *smd) /* Call with message lock held */ static void -_lws_smd_msg_destroy(lws_smd_t *smd, lws_smd_msg_t *msg) +_lws_smd_msg_destroy(struct lws_context *cx, lws_smd_t *smd, lws_smd_msg_t *msg) { /* * We think we gave the message to everyone and can destroy it. @@ -472,7 +472,7 @@ _lws_smd_peer_destroy(lws_smd_peer_t *pr) if (_lws_smd_msg_peer_interested_in_msg(pr, pr->tail)) { if (!--pr->tail->refcount) - _lws_smd_msg_destroy(smd, pr->tail); + _lws_smd_msg_destroy(pr->ctx, smd, pr->tail); } pr->tail = m1; @@ -549,7 +549,7 @@ _lws_smd_msg_deliver_peer(struct lws_context *ctx, lws_smd_peer_t *pr) lws_mutex_lock(ctx->smd.lock_messages); /* +++++++++ messages */ if (!--msg->refcount) - _lws_smd_msg_destroy(&ctx->smd, msg); + _lws_smd_msg_destroy(ctx, &ctx->smd, msg); lws_mutex_unlock(ctx->smd.lock_messages); /* messages ------- */ return !!pr->tail; @@ -604,6 +604,7 @@ lws_smd_register(struct lws_context *ctx, void *opaque, int flags, pr->cb = cb; pr->opaque = opaque; pr->_class_filter = _class_filter; + pr->ctx = ctx; if (!ctx->smd.delivering) lws_mutex_lock(ctx->smd.lock_peers); /* +++++++++++++++ peers */ @@ -711,7 +712,7 @@ lws_smd_message_pending(struct lws_context *ctx) * when destroying the message now. */ - _lws_smd_msg_destroy(&ctx->smd, msg); + _lws_smd_msg_destroy(ctx, &ctx->smd, msg); } } lws_end_foreach_dll_safe(p, p1); diff --git a/lib/tls/mbedtls/mbedtls-tls.c b/lib/tls/mbedtls/mbedtls-tls.c index 6da053d0d..6ae4039a5 100644 --- a/lib/tls/mbedtls/mbedtls-tls.c +++ b/lib/tls/mbedtls/mbedtls-tls.c @@ -31,13 +31,14 @@ lws_tls_err_describe_clear(void) } int -lws_context_init_ssl_library(const struct lws_context_creation_info *info) +lws_context_init_ssl_library(struct lws_context *cx, + const struct lws_context_creation_info *info) { - lwsl_info(" Compiled with MbedTLS support\n"); + lwsl_info(" Compiled with MbedTLS support"); if (!lws_check_opt(info->options, LWS_SERVER_OPTION_DO_SSL_GLOBAL_INIT)) lwsl_info(" SSL disabled: no " - "LWS_SERVER_OPTION_DO_SSL_GLOBAL_INIT\n"); + "LWS_SERVER_OPTION_DO_SSL_GLOBAL_INIT"); return 0; } diff --git a/lib/tls/openssl/openssl-tls.c b/lib/tls/openssl/openssl-tls.c index 435903f11..a387e9d25 100644 --- a/lib/tls/openssl/openssl-tls.c +++ b/lib/tls/openssl/openssl-tls.c @@ -118,9 +118,9 @@ lws_openssl_thread_id(void) } #endif - int -lws_context_init_ssl_library(const struct lws_context_creation_info *info) +lws_context_init_ssl_library(struct lws_context *cx, + const struct lws_context_creation_info *info) { #ifdef USE_WOLFSSL #ifdef USE_OLD_CYASSL diff --git a/lib/tls/private-lib-tls.h b/lib/tls/private-lib-tls.h index 00135e168..23fc2a727 100644 --- a/lib/tls/private-lib-tls.h +++ b/lib/tls/private-lib-tls.h @@ -141,7 +141,8 @@ typedef X509 lws_tls_x509; #endif int -lws_context_init_ssl_library(const struct lws_context_creation_info *info); +lws_context_init_ssl_library(struct lws_context *cx, + const struct lws_context_creation_info *info); void lws_context_deinit_ssl_library(struct lws_context *context); #define LWS_SSL_ENABLED(vh) (vh && vh->tls.use_ssl) diff --git a/minimal-examples/http-client/minimal-http-client-multi/CMakeLists.txt b/minimal-examples/http-client/minimal-http-client-multi/CMakeLists.txt index c484e8186..a4da9b9ce 100644 --- a/minimal-examples/http-client/minimal-http-client-multi/CMakeLists.txt +++ b/minimal-examples/http-client/minimal-http-client-multi/CMakeLists.txt @@ -168,8 +168,13 @@ endif() --post --h1 -l --port 1${PORT_HCM_SRV} -d1151) add_test(NAME http-client-multi-post-pipe COMMAND lws-minimal-http-client-multi --post -p -l --port 1${PORT_HCM_SRV} -d1151) - add_test(NAME http-client-multi-post-h1-pipe COMMAND lws-minimal-http-client-multi + if (VALGRIND) + add_test(NAME http-client-multi-post-h1-pipe COMMAND ${VALGRIND} --tool=memcheck $ + --post --h1 -p -l --port 1${PORT_HCM_SRV} -d1151) + else() + add_test(NAME http-client-multi-post-h1-pipe COMMAND lws-minimal-http-client-multi --post --h1 -p -l --port 1${PORT_HCM_SRV} -d1151) + endif() add_test(NAME http-client-multi-post-stag COMMAND lws-minimal-http-client-multi --post -s -l -d1151 --port 1${PORT_HCM_SRV} -d1151) add_test(NAME http-client-multi-post-stag-h1 COMMAND lws-minimal-http-client-multi diff --git a/minimal-examples/secure-streams/minimal-secure-streams-post/CMakeLists.txt b/minimal-examples/secure-streams/minimal-secure-streams-post/CMakeLists.txt index 652209c0a..62404153f 100644 --- a/minimal-examples/secure-streams/minimal-secure-streams-post/CMakeLists.txt +++ b/minimal-examples/secure-streams/minimal-secure-streams-post/CMakeLists.txt @@ -16,9 +16,21 @@ require_lws_config(LWS_WITH_SYS_STATE 1 requirements) if (requirements) add_executable(${SAMP} minimal-secure-streams-post.c) + + find_program(VALGRIND "valgrind") if (LWS_CTEST_INTERNET_AVAILABLE) - add_test(NAME sspost-warmcat COMMAND lws-minimal-secure-streams-post) + if (VALGRIND) + add_test(NAME sspost-warmcat COMMAND + ${CMAKE_SOURCE_DIR}/scripts/ctest-background.sh + post_hcm_srv + ${VALGRIND} --tool=memcheck + $ + ) + else() + add_test(NAME sspost-warmcat + COMMAND lws-minimal-secure-streams-post) + endif() set_tests_properties(sspost-warmcat PROPERTIES WORKING_DIRECTORY ${CMAKE_SOURCE_DIR}/minimal-examples/secure-streams/minimal-secure-streams-post