diff --git a/READMEs/README.coding.md b/READMEs/README.coding.md index a14d1fa8d..f0c7008e2 100644 --- a/READMEs/README.coding.md +++ b/READMEs/README.coding.md @@ -351,32 +351,7 @@ deal with fragmented messages. @section debuglog Debug Logging -Also using `lws_set_log_level` api you may provide a custom callback to actually -emit the log string. By default, this points to an internal emit function -that sends to stderr. Setting it to `NULL` leaves it as it is instead. - -A helper function `lwsl_emit_syslog()` is exported from the library to simplify -logging to syslog. You still need to use `setlogmask`, `openlog` and `closelog` -in your user code. - -The logging apis are made available for user code. - -- `lwsl_err(...)` -- `lwsl_warn(...)` -- `lwsl_notice(...)` -- `lwsl_info(...)` -- `lwsl_debug(...)` - -The difference between notice and info is that notice will be logged by default -whereas info is ignored by default. - -If you are not building with _DEBUG defined, ie, without this - -``` - $ cmake .. -DCMAKE_BUILD_TYPE=DEBUG -``` - -then log levels below notice do not actually get compiled in. +See ./READMEs/README.logging.md @section asan Building with ASAN diff --git a/READMEs/README.logging.md b/READMEs/README.logging.md new file mode 100644 index 000000000..83a9a678c --- /dev/null +++ b/READMEs/README.logging.md @@ -0,0 +1,105 @@ +# lws logging + +# `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. + +By default the logs are emitted on stdout, but this can be overridden +using `lws_set_log_level()` and either syslog (provided by `lwsl_emit_syslog()`) +or custom log emission is possible if you point it to your own. + +Currently the following log levels are defined + +|name|function|release|meaning| +|---|---|---|---| +|`LLL_ERR`|`lwsl_err()`|y|Serious operation errors anyone needs to know| +|`LLL_WARN`|`lwsl_warn()`|y|Operation errors you may need to know| +|`LLL_USER`|`lws_user()`|y|Information user code wants you to know| +|`LLL_NOTICE`|`lwsl_notice()`|y|Information about what lws is doing useful for logging| +|`LLL_INFO`|`lwsl_info()`|n|Detailed information about what lws is doing| +|`LLL_DEBUG`|`lwsl_debug()`|n|Very detailed information about what lws is doing| +|`LLL_PARSER`|`lwsl_parser()`|n|Very detailed information about parsing| +|`LLL_HEADER`|`lwsl_header()`|n|Very detailed information about header processing| +|`LLL_EXT`|`lwsl_ext()`|n|Very detailed information about ws extensions| +|`LLL_CLIENT`|`lwsl_client()`|n|Very detailed information about client connections| +|`LLL_LATENCY`|`lwsl_latency()`|n|detailed latency stats| +|`LLL_THREAD`|`lwsl_thread()`|n|detailed threadpool information| + +The first four log levels are built into lws even on Release builds, the others +are only built in Debug builds. + +You can select between Debug and Release builds using cmake `-DCMAKE_BUILD_TYPE=` +`DEBUG` or `Release` + +`lws_set_log_level()` is used to OR together the logging bitfields you want to +see emitted, only log levels that were built in can be enabled since the code for them +is just not there otherwise. + +## Finegrained control of log level build + +You can deviate from the default log inclusion for release / debug by overriding it +at cmake, using `LWS_LOGGING_BITFIELD_SET` and `LWS_LOGGING_BITFIELD_CLEAR`. + +For example you can set `-DLWS_LOGGING_BITFIELD_SET="LLL_INFO|LLL_DEBUG"`, which will +cause those log level traces to be built in even in Release mode. Clear works +similarly to defeat build of specific log levels. + +## Object tags in lws + +Commonly logging wants to refer to an object in a repeatable way, the usual way to +do this is with `%p` to print the object pointer. But this has a couple of drawbacks, +first the same memory may be freed and reallocated for a different instance of the same +or another object, causing confusion, and second when multiple processes are allocating +objects and logging, the same address may be allocated in different process also causing +confusion. + +Lws has introduced unique tag strings to refer to object identity in logging instead, these +contain various information such as a 64-bit ordinal for the group the object belongs +to that won't repeat even if reallocated to the same address (until 2^64 allocations, +anyway). + +Tags are fixed at object creation time for the whole object lifetime, although in some +cases the tag may be appended to... accepted server wsis for example don't have much +information available to form the tag until they start to indicate what they want to +do. + +At their simplest the tags look like this (in a log indicating creation) + +``` +[2020/12/27 08:49:19:2956] N: ++ (4) [wsi|5|h2] +``` + +It means a wsi has been created with the tag `[wsi|5|h2]`, and after that, there are 4 +active objects in the wsi group. + +The corresponding object destruction log with the tag is + +``` +[2020/12/27 08:49:24:4226] N: -- (3) 5.126s [wsi|5|h2] +``` + +it indicates the object's tag, that it lived for 5.126s and after its destruction, +there are 3 objects in its group left. + +### Compound tags + +If the object has bindings, the tag can reflect that, eg + +``` +[2020/12/27 08:49:19:4787] N: ++ (2) [wsiSScli|6|d_h1] +[2020/12/27 08:49:19:4793] N: ++ (2) [wsicli|6|GET/h1/httpbin.org/([wsiSScli|6|d_h1])] +``` + +the first log is describing a proxied SS client connection at the proxy, and the second +is a wsi bound to the SS object from the first log to do the outgoing client action. + +## Tags in user code + +When user code wants to refer to a tagged object like a wsi or vhost, there are helpers +that return a `const char *` containing the tag + +`lws_wsi_tag(wsi)` +`lws_vh_tag(vh)` + diff --git a/include/libwebsockets/lws-client.h b/include/libwebsockets/lws-client.h index 2249bd8c5..657108659 100644 --- a/include/libwebsockets/lws-client.h +++ b/include/libwebsockets/lws-client.h @@ -74,6 +74,10 @@ enum lws_client_connect_ssl_connection_flags { */ LCCSCF_SECSTREAM_CLIENT = (1 << 21), /**< used to mark client wsi as bound to secure stream */ + LCCSCF_SECSTREAM_PROXY_LINK = (1 << 22), + /**< client is a link between SS client and SS proxy */ + LCCSCF_SECSTREAM_PROXY_ONWARD = (1 << 23), + /**< client the SS proxy's onward connection */ }; /** struct lws_client_connect_info - parameters to connect with when using diff --git a/include/libwebsockets/lws-context-vhost.h b/include/libwebsockets/lws-context-vhost.h index 8e0812852..d23d49988 100644 --- a/include/libwebsockets/lws-context-vhost.h +++ b/include/libwebsockets/lws-context-vhost.h @@ -230,6 +230,9 @@ /**< (CTX) Disable lws_system state, eg, because we are a secure streams * proxy client that is not trying to track system state by itself. */ +#define LWS_SERVER_OPTION_SS_PROXY (1ll << 36) + /**< (VH) We are being a SS Proxy listen socket for the vhost */ + /****** add new things just above ---^ ******/ @@ -1113,6 +1116,9 @@ lws_vhost_user(struct lws_vhost *vhost); LWS_VISIBLE LWS_EXTERN void * lws_context_user(struct lws_context *context); +LWS_VISIBLE LWS_EXTERN const char * +lws_vh_tag(struct lws_vhost *vh); + /*! \defgroup vhost-mounts Vhost mounts and options * \ingroup context-and-vhost-creation * diff --git a/include/libwebsockets/lws-logs.h b/include/libwebsockets/lws-logs.h index c08384e62..f1c91b1c8 100644 --- a/include/libwebsockets/lws-logs.h +++ b/include/libwebsockets/lws-logs.h @@ -299,4 +299,9 @@ lwsl_emit_stderr_notimestamp(int level, const char *line); LWS_VISIBLE LWS_EXTERN int lwsl_visible(int level); +struct lws; + +LWS_VISIBLE LWS_EXTERN const char * +lws_wsi_tag(struct lws *wsi); + ///@} diff --git a/include/libwebsockets/lws-secure-streams-client.h b/include/libwebsockets/lws-secure-streams-client.h index 7070ec2d7..d0dd95929 100644 --- a/include/libwebsockets/lws-secure-streams-client.h +++ b/include/libwebsockets/lws-secure-streams-client.h @@ -59,6 +59,7 @@ #define lws_ss_cancel_timeout lws_sspc_cancel_timeout #define lws_ss_to_user_object lws_sspc_to_user_object #define lws_ss_change_handlers lws_sspc_change_handlers +#define lws_ss_tag lws_sspc_tag #endif @@ -221,3 +222,5 @@ lws_sspc_change_handlers(struct lws_sspc_handle *h, lws_ss_constate_t state, lws_ss_tx_ordinal_t ack)); +const char * +lws_sspc_tag(struct lws_sspc_handle *h); diff --git a/include/libwebsockets/lws-secure-streams.h b/include/libwebsockets/lws-secure-streams.h index 08bb68f50..26e861bbb 100644 --- a/include/libwebsockets/lws-secure-streams.h +++ b/include/libwebsockets/lws-secure-streams.h @@ -728,5 +728,8 @@ lws_ss_add_peer_tx_credit(struct lws_ss_handle *h, int32_t add); LWS_VISIBLE LWS_EXTERN int lws_ss_get_est_peer_tx_credit(struct lws_ss_handle *h); +LWS_VISIBLE LWS_EXTERN const char * +lws_ss_tag(struct lws_ss_handle *h); + ///@} diff --git a/lib/core-net/adopt.c b/lib/core-net/adopt.c index 2414f32bd..876548cdc 100644 --- a/lib/core-net/adopt.c +++ b/lib/core-net/adopt.c @@ -45,7 +45,7 @@ lws_get_idlest_tsi(struct lws_context *context) } struct lws * -lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi) +lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi, const char *desc) { struct lws *new_wsi; int n = fixed_tsi; @@ -59,16 +59,18 @@ lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi) } lws_context_lock(vhost->context, __func__); - new_wsi = __lws_wsi_create_with_role(vhost->context, fixed_tsi, NULL); + new_wsi = __lws_wsi_create_with_role(vhost->context, n, NULL); 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[LWSLCG_WSI], &new_wsi->lc, desc); + new_wsi->wsistate |= LWSIFR_SERVER; new_wsi->tsi = n; - lwsl_debug("new wsi %p joining vhost %s, tsi %d\n", new_wsi, + lwsl_debug("%s joining vhost %s, tsi %d\n", new_wsi->lc.gutag, vhost->name, new_wsi->tsi); lws_vhost_bind_wsi(vhost, new_wsi); @@ -132,7 +134,7 @@ lws_adopt_descriptor_vhost1(struct lws_vhost *vh, lws_adoption_type type, n = -1; if (parent) n = parent->tsi; - new_wsi = lws_create_new_server_wsi(vh, n); + new_wsi = lws_create_new_server_wsi(vh, n, "adopted"); if (!new_wsi) { lws_context_unlock(vh->context); return NULL; @@ -417,8 +419,8 @@ lws_adopt_descriptor_vhost2(struct lws *new_wsi, lws_adoption_type type, * (here) and h2 (at lws_wsi_server_new()) */ - lwsl_info("%s: wsi %p, vhost %s ss_handle %p\n", __func__, new_wsi, - new_wsi->a.vhost->name, new_wsi->a.vhost->ss_handle); + lwsl_info("%s: %s, vhost %s\n", __func__, new_wsi->lc.gutag, + new_wsi->a.vhost->lc.gutag); if (lws_adopt_ss_server_accept(new_wsi)) goto fail; diff --git a/lib/core-net/client/connect.c b/lib/core-net/client/connect.c index 05c901e98..377579eb1 100644 --- a/lib/core-net/client/connect.c +++ b/lib/core-net/client/connect.c @@ -42,7 +42,7 @@ lws_http_client_connect_via_info2(struct lws *wsi) struct client_info_stash *stash = wsi->stash; int n; - lwsl_debug("%s: %p (stash %p)\n", __func__, wsi, stash); + lwsl_debug("%s: %s (stash %p)\n", __func__, lws_lc_tag(&wsi->lc), stash); if (!stash) return wsi; @@ -252,8 +252,8 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) else lwsl_info("%s: unknown protocol %s\n", __func__, local); - lwsl_info("%s: wsi %p: %s %s entry\n", - __func__, wsi, wsi->role_ops->name, + lwsl_info("%s: %s: %s %s entry\n", + __func__, lws_wsi_tag(wsi), wsi->role_ops->name, wsi->a.protocol ? wsi->a.protocol->name : "none"); } @@ -320,7 +320,27 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) #if defined(LWS_WITH_SECURE_STREAMS) wsi->for_ss = !!(i->ssl_connection & LCCSCF_SECSTREAM_CLIENT); /* implies our opaque user ptr is the ss handle */ + if (wsi->for_ss) { + /* it's related to ss... the options are + * + * LCCSCF_SECSTREAM_PROXY_LINK : client SSPC link to proxy + * LCCSCF_SECSTREAM_PROXY_ONWARD: proxy's onward connection + */ + __lws_lc_tag(&i->context->lcg[ +#if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) + i->ssl_connection & LCCSCF_SECSTREAM_PROXY_LINK ? LWSLCG_WSI_SSP_CLIENT : + (i->ssl_connection & LCCSCF_SECSTREAM_PROXY_ONWARD ? LWSLCG_WSI_SSP_ONWARD : LWSLCG_WSI_CLIENT)], +#else + LWSLCG_WSI_CLIENT], #endif + &wsi->lc, "%s/%s/%s/(%s)", i->method ? i->method : "WS", + wsi->role_ops->name, i->address, + lws_ss_tag(((lws_ss_handle_t *)i->opaque_user_data))); + } else +#endif + __lws_lc_tag(&i->context->lcg[LWSLCG_WSI_CLIENT], &wsi->lc, + "%s/%s/%s", i->method ? i->method : "WS", + wsi->role_ops->name, i->address); pc = (char *)&wsi->stash[1]; @@ -384,8 +404,8 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) if (wsi->role_ops != &role_ops_raw_skt || (i->local_protocol_name && !strcmp(i->local_protocol_name, "raw-proxy"))) { - lwsl_debug("%s: wsi %p: adoption cb %d to %s %s\n", __func__, - wsi, wsi->role_ops->adoption_cb[0], + lwsl_debug("%s: %s: adoption cb %d to %s %s\n", __func__, + lws_wsi_tag(wsi), wsi->role_ops->adoption_cb[0], wsi->role_ops->name, wsi->a.protocol->name); wsi->a.protocol->callback(wsi, wsi->role_ops->adoption_cb[0], diff --git a/lib/core-net/client/connect2.c b/lib/core-net/client/connect2.c index cc8364016..f687ba1f3 100644 --- a/lib/core-net/client/connect2.c +++ b/lib/core-net/client/connect2.c @@ -206,7 +206,7 @@ solo: lws_dll2_is_detached(&wsi->dll2_cli_txn_queue) && lws_dll2_is_detached(&wsi->dll_cli_active_conns)) { lws_vhost_lock(wsi->a.vhost); - lwsl_info("%s: adding active conn %p\n", __func__, wsi); + lwsl_info("%s: adding active conn %s\n", __func__, lws_wsi_tag(wsi)); /* caution... we will have to unpick this on oom4 path */ lws_dll2_add_head(&wsi->dll_cli_active_conns, &wsi->a.vhost->dll_cli_active_conns_owner); @@ -304,7 +304,7 @@ solo: */ lwsi_set_state(wsi, LRS_WAITING_DNS); - lwsl_info("%s: %p: lookup %s:%u\n", __func__, wsi, ads, port); + lwsl_info("%s: %s: lookup %s:%u\n", __func__, wsi->lc.gutag, ads, port); (void)port; #if defined(LWS_WITH_DETAILED_LATENCY) diff --git a/lib/core-net/client/connect3.c b/lib/core-net/client/connect3.c index f872917e0..5de0419dd 100644 --- a/lib/core-net/client/connect3.c +++ b/lib/core-net/client/connect3.c @@ -309,7 +309,7 @@ ads_known: goto try_next_dns_result_closesock; } - lwsl_debug("%s: %p: WAITING_CONNECT\n", __func__, wsi); + lwsl_debug("%s: %s: WAITING_CONNECT\n", __func__, wsi->lc.gutag); lwsi_set_state(wsi, LRS_WAITING_CONNECT); if (wsi->a.context->event_loop_ops->sock_accept) diff --git a/lib/core-net/client/connect4.c b/lib/core-net/client/connect4.c index a47f28567..969599bd9 100644 --- a/lib/core-net/client/connect4.c +++ b/lib/core-net/client/connect4.c @@ -160,12 +160,12 @@ send_hs: wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); #endif - lwsl_info("%s: wsi %p: waiting to send hdrs (par state 0x%x)\n", - __func__, wsi, lwsi_state(wsi_piggyback)); + lwsl_info("%s: %s: waiting to send hdrs (par state 0x%x)\n", + __func__, wsi->lc.gutag, lwsi_state(wsi_piggyback)); } else { - lwsl_info("%s: wsi %p: %s %s client created own conn " + lwsl_info("%s: %s: %s %s client created own conn " "(raw %d) vh %sm st 0x%x\n", - __func__, wsi, wsi->role_ops->name, + __func__, wsi->lc.gutag, wsi->role_ops->name, wsi->a.protocol->name, rawish, wsi->a.vhost->name, lwsi_state(wsi)); @@ -210,9 +210,9 @@ send_hs: * LRS_H2_WAITING_TO_SEND_HEADERS already. */ - lwsl_notice("%s: wsi %p: " + lwsl_notice("%s: %s: " "tls established st 0x%x\n", - __func__, wsi, lwsi_state(wsi)); + __func__, wsi->lc.gutag, lwsi_state(wsi)); if (lwsi_state(wsi) != LRS_H2_WAITING_TO_SEND_HEADERS) diff --git a/lib/core-net/close.c b/lib/core-net/close.c index a4522f963..68520d16c 100644 --- a/lib/core-net/close.c +++ b/lib/core-net/close.c @@ -184,13 +184,15 @@ __lws_free_wsi(struct lws *wsi) lws_vhost_unbind_wsi(wsi); - lwsl_debug("%s: %p, remaining wsi %d, tsi fds count %d\n", __func__, wsi, + lwsl_debug("%s: %s, remaining wsi %d, tsi fds count %d\n", __func__, + lws_wsi_tag(wsi), wsi->a.context->pt[(int)wsi->tsi].count_wsi_allocated, 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_free(wsi); } @@ -208,8 +210,8 @@ lws_remove_child_from_any_parent(struct lws *wsi) pwsi = &wsi->parent->child_list; while (*pwsi) { if (*pwsi == wsi) { - lwsl_info("%s: detach %p from parent %p\n", __func__, - wsi, wsi->parent); + lwsl_info("%s: detach %s from parent %s\n", __func__, + lws_wsi_tag(wsi), lws_wsi_tag(wsi->parent)); if (wsi->parent->a.protocol) wsi->parent->a.protocol->callback(wsi, @@ -279,7 +281,7 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason, struct lws *wsi1, *wsi2; int n, ccb; - lwsl_info("%s: %p: caller: %s\n", __func__, wsi, caller); + lwsl_info("%s: %s: caller: %s\n", __func__, lws_wsi_tag(wsi), caller); if (!wsi) return; @@ -287,8 +289,8 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason, lws_access_log(wsi); if (!lws_dll2_is_detached(&wsi->dll_buflist)) { - lwsl_info("%s: wsi %p: going down with stuff in buflist\n", - __func__, wsi); } + lwsl_info("%s: %s: going down with stuff in buflist\n", + __func__, lws_wsi_tag(wsi)); } context = wsi->a.context; pt = &context->pt[(int)wsi->tsi]; @@ -414,7 +416,7 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason, lws_callback_on_writable(wsi); return; } - lwsl_info("%p: end LRS_FLUSHING_BEFORE_CLOSE\n", wsi); + lwsl_info("%s: %s: end LRS_FLUSHING_BEFORE_CLOSE\n", __func__, lws_wsi_tag(wsi)); goto just_kill_connection; default: if (lws_has_buffered_out(wsi) @@ -423,7 +425,7 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason, wsi->http.comp_ctx.may_have_more #endif ) { - lwsl_info("%p: LRS_FLUSHING_BEFORE_CLOSE\n", wsi); + lwsl_info("%s: %s: LRS_FLUSHING_BEFORE_CLOSE\n", __func__, lws_wsi_tag(wsi)); lwsi_set_state(wsi, LRS_FLUSHING_BEFORE_CLOSE); __lws_set_timeout(wsi, PENDING_FLUSH_STORED_SEND_BEFORE_CLOSE, 5); @@ -499,7 +501,7 @@ just_kill_connection: if (!wsi->told_user_closed && wsi->user_space && wsi->protocol_bind_balance && wsi->a.protocol) { - lwsl_debug("%s: %p: DROP_PROTOCOL %s\n", __func__, wsi, + lwsl_debug("%s: %s: DROP_PROTOCOL %s\n", __func__, lws_wsi_tag(wsi), wsi->a.protocol ? wsi->a.protocol->name: "NULL"); if (wsi->a.protocol) wsi->a.protocol->callback(wsi, @@ -578,8 +580,8 @@ just_kill_connection: } else #endif { - lwsl_info("%s: shutdown conn: %p (sk %d, state 0x%x)\n", - __func__, wsi, (int)(lws_intptr_t)wsi->desc.sockfd, + lwsl_info("%s: shutdown conn: %s (sk %d, state 0x%x)\n", + __func__, lws_wsi_tag(wsi), (int)(lws_intptr_t)wsi->desc.sockfd, lwsi_state(wsi)); if (!wsi->socket_is_permanently_unusable && lws_socket_is_valid(wsi->desc.sockfd)) { @@ -611,8 +613,8 @@ just_kill_connection: #endif } - lwsl_debug("%s: real just_kill_connection: %p (sockfd %d)\n", __func__, - wsi, wsi->desc.sockfd); + lwsl_debug("%s: real just_kill_connection: %s (sockfd %d)\n", __func__, + lws_wsi_tag(wsi), wsi->desc.sockfd); #ifdef LWS_WITH_HUBBUB if (wsi->http.rw) { @@ -634,8 +636,6 @@ just_kill_connection: //if (wsi->told_event_loop_closed) // cgi std close case (dummy-callback) // return; - // lwsl_notice("%s: wsi %p, fd %d\n", __func__, wsi, wsi->desc.sockfd); - /* checking return redundant since we anyway close */ __remove_wsi_socket_from_fds(wsi); @@ -723,7 +723,8 @@ __lws_close_free_wsi_final(struct lws *wsi) if (!wsi->shadow && lws_socket_is_valid(wsi->desc.sockfd) && !lws_ssl_close(wsi)) { - lwsl_debug("%s: wsi %p: fd %d\n", __func__, wsi, wsi->desc.sockfd); + lwsl_debug("%s: wsi %s: fd %d\n", __func__, lws_wsi_tag(wsi), + wsi->desc.sockfd); n = compatible_close(wsi->desc.sockfd); if (n) lwsl_debug("closing: close ret %d\n", LWS_ERRNO); diff --git a/lib/core-net/dummy-callback.c b/lib/core-net/dummy-callback.c index 1d21032db..e998aa9f2 100644 --- a/lib/core-net/dummy-callback.c +++ b/lib/core-net/dummy-callback.c @@ -136,7 +136,7 @@ lws_callback_ws_proxy(struct lws *wsi, enum lws_callback_reasons reason, case LWS_CALLBACK_CLIENT_CONNECTION_ERROR: case LWS_CALLBACK_CLIENT_CLOSED: - lwsl_info("%s: client closed: parent %p\n", __func__, wsi->parent); + lwsl_info("%s: client closed: parent %s\n", __func__, lws_wsi_tag(wsi->parent)); if (wsi->parent) lws_set_timeout(wsi->parent, 1, LWS_TO_KILL_ASYNC); break; @@ -377,8 +377,9 @@ lws_callback_http_dummy(struct lws *wsi, enum lws_callback_reasons reason, if (!wsi->http.prh_content_length) n |= LWS_WRITE_H2_STREAM_END; - lwsl_debug("%s: %p: issuing proxy headers: clen %d\n", - __func__, wsi, (int)wsi->http.prh_content_length); + lwsl_debug("%s: %s: issuing proxy headers: clen %d\n", + __func__, lws_wsi_tag(wsi), + (int)wsi->http.prh_content_length); n = lws_write(wsi, wsi->http.pending_return_headers + LWS_PRE, wsi->http.pending_return_headers_len, n); @@ -591,8 +592,9 @@ lws_callback_http_dummy(struct lws *wsi, enum lws_callback_reasons reason, break; } case LWS_CALLBACK_COMPLETED_CLIENT_HTTP: - lwsl_info("%s: COMPLETED_CLIENT_HTTP: %p (parent %p)\n", - __func__, wsi, lws_get_parent(wsi)); + lwsl_info("%s: COMPLETED_CLIENT_HTTP: %s (parent %s)\n", + __func__, lws_wsi_tag(wsi), + lws_wsi_tag(lws_get_parent(wsi))); if (!lws_get_parent(wsi)) break; lws_get_parent(wsi)->reason_bf |= @@ -812,8 +814,8 @@ lws_callback_http_dummy(struct lws *wsi, enum lws_callback_reasons reason, */ lwsl_info("%s: expected POST in end: " - "closing stdin wsi %p, fd %d\n", - __func__, siwsi, + "closing stdin wsi %s, fd %d\n", + __func__, lws_wsi_tag(siwsi), siwsi->desc.sockfd); /* diff --git a/lib/core-net/output.c b/lib/core-net/output.c index d0e0a3531..0f4c98f13 100644 --- a/lib/core-net/output.c +++ b/lib/core-net/output.c @@ -52,9 +52,9 @@ lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) */ if (0 && buf && wsi->could_have_pending) { lwsl_hexdump_level(LLL_INFO, buf, len); - lwsl_info("** %p: vh: %s, prot: %s, role %s: " + lwsl_info("** %s: vh: %s, prot: %s, role %s: " "Inefficient back-to-back write of %lu detected...\n", - wsi, wsi->a.vhost ? wsi->a.vhost->name : "no vhost", + lws_wsi_tag(wsi), lws_vh_tag(wsi->a.vhost), wsi->a.protocol->name, wsi->role_ops->name, (unsigned long)len); } @@ -71,8 +71,8 @@ lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) return (int)len; if (buf && lws_has_buffered_out(wsi)) { - lwsl_info("** %p: vh: %s, prot: %s, incr buflist_out by %lu\n", - wsi, wsi->a.vhost ? wsi->a.vhost->name : "no vhost", + lwsl_info("** %s: vh: %s, prot: %s, incr buflist_out by %lu\n", + lws_wsi_tag(wsi), lws_vh_tag(wsi->a.vhost), wsi->a.protocol->name, (unsigned long)len); /* @@ -101,7 +101,7 @@ lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) return 0; if (!wsi->mux_substream && !lws_socket_is_valid(wsi->desc.sockfd)) - lwsl_err("%s: invalid sock %p\n", __func__, wsi); + lwsl_err("%s: %s invalid sock\n", __func__, lws_wsi_tag(wsi)); /* limit sending */ if (wsi->a.protocol->tx_packet_size) @@ -148,18 +148,19 @@ lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) */ if (lws_has_buffered_out(wsi)) { if (m) { - lwsl_info("%p partial adv %d (vs %ld)\n", wsi, m, - (long)real_len); + lwsl_info("%s partial adv %d (vs %ld)\n", + lws_wsi_tag(wsi), m, (long)real_len); lws_buflist_use_segment(&wsi->buflist_out, m); } if (!lws_has_buffered_out(wsi)) { - lwsl_info("%s: wsi %p: buflist_out flushed\n", - __func__, wsi); + lwsl_info("%s: %s: buflist_out flushed\n", + __func__, lws_wsi_tag(wsi)); m = (int)real_len; if (lwsi_state(wsi) == LRS_FLUSHING_BEFORE_CLOSE) { - lwsl_info("*%p signalling to close now\n", wsi); + lwsl_info("*%s signalling to close now\n", + lws_wsi_tag(wsi)); return -1; /* retry closing now */ } @@ -207,8 +208,8 @@ lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) * buffering the unsent remainder on it. * (it will get first priority next time the socket is writable). */ - lwsl_debug("%p new partial sent %d from %lu total\n", wsi, m, - (unsigned long)real_len); + lwsl_debug("%s new partial sent %d from %lu total\n", lws_wsi_tag(wsi), + m, (unsigned long)real_len); if (lws_buflist_append_segment(&wsi->buflist_out, buf + m, real_len - m) < 0) diff --git a/lib/core-net/pollfd.c b/lib/core-net/pollfd.c index a0231cacd..af9fe4008 100644 --- a/lib/core-net/pollfd.c +++ b/lib/core-net/pollfd.c @@ -145,7 +145,7 @@ _lws_change_pollfd(struct lws *wsi, int _and, int _or, struct lws_pollargs *pa) pfd = &pt->fds[wsi->position_in_fds_table]; pa->fd = wsi->desc.sockfd; - lwsl_debug("%s: wsi %p: fd %d events %d -> %d\n", __func__, wsi, + lwsl_debug("%s: %s: fd %d events %d -> %d\n", __func__, lws_wsi_tag(wsi), pa->fd, pfd->events, (pfd->events & ~_and) | _or); pa->prev_events = pfd->events; pa->events = pfd->events = (pfd->events & ~_and) | _or; @@ -251,8 +251,8 @@ __dump_fds(struct lws_context_per_thread *pt, const char *s) for (n = 0; n < pt->fds_count; n++) { struct lws *wsi = wsi_from_fd(pt->context, pt->fds[n].fd); - lwsl_warn(" %d: fd %d, wsi %p, pos_in_fds: %d\n", - n + 1, pt->fds[n].fd, wsi, + lwsl_warn(" %d: fd %d, wsi %s, pos_in_fds: %d\n", + n + 1, pt->fds[n].fd, lws_wsi_tag(wsi), wsi ? wsi->position_in_fds_table : -1); } } @@ -273,8 +273,8 @@ __insert_wsi_socket_into_fds(struct lws_context *context, struct lws *wsi) lws_pt_assert_lock_held(pt); - lwsl_debug("%s: %p: tsi=%d, sock=%d, pos-in-fds=%d\n", - __func__, wsi, wsi->tsi, wsi->desc.sockfd, pt->fds_count); + lwsl_debug("%s: %s: tsi=%d, sock=%d, pos-in-fds=%d\n", + __func__, lws_wsi_tag(wsi), wsi->tsi, wsi->desc.sockfd, pt->fds_count); if ((unsigned int)pt->fds_count >= context->fd_limit_per_thread) { lwsl_err("Too many fds (%d vs %d)\n", context->max_fds, @@ -392,8 +392,8 @@ __remove_wsi_socket_from_fds(struct lws *wsi) LWS_EV_STOP | LWS_EV_READ | LWS_EV_WRITE | LWS_EV_PREPARE_DELETION); /* - lwsl_notice("%s: wsi=%p, skt=%d, fds pos=%d, end guy pos=%d, endfd=%d\n", - __func__, wsi, wsi->desc.sockfd, wsi->position_in_fds_table, + lwsl_notice("%s: wsi=%s, skt=%d, fds pos=%d, end guy pos=%d, endfd=%d\n", + __func__, lws_wsi_tag(wsi), wsi->desc.sockfd, wsi->position_in_fds_table, pt->fds_count, pt->fds[pt->fds_count - 1].fd); */ if (m != LWS_NO_FDS_POS) { @@ -552,7 +552,8 @@ lws_callback_on_writable(struct lws *wsi) return -1; } - //lwsl_notice("%s: marking for POLLOUT %p (wsi %p)\n", __func__, w, wsi); + // lwsl_notice("%s: marking for POLLOUT %s (%s)\n", __func__, + // lws_wsi_tag(w), lws_wsi_tag(wsi)); if (__lws_change_pollfd(w, 0, LWS_POLLOUT)) return -1; diff --git a/lib/core-net/private-lib-core-net.h b/lib/core-net/private-lib-core-net.h index df947ba95..4f7dedea3 100644 --- a/lib/core-net/private-lib-core-net.h +++ b/lib/core-net/private-lib-core-net.h @@ -506,6 +506,8 @@ struct lws_vhost { struct lws_vhost_role_ws ws; #endif + lws_lifecycle_t lc; + #if defined(LWS_WITH_SOCKS5) char socks_proxy_address[128]; char socks_user[96]; @@ -698,6 +700,8 @@ struct lws { struct lws_tx_credit txc; #endif + lws_lifecycle_t lc; + /* lifetime members */ #if defined(LWS_WITH_EVENT_LIBS) @@ -1237,7 +1241,7 @@ lws_client_reset(struct lws **wsi, int ssl, const char *address, int port, const char *path, const char *host, char weak); struct lws * LWS_WARN_UNUSED_RESULT -lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi); +lws_create_new_server_wsi(struct lws_vhost *vhost, int fixed_tsi, const char *desc); char * LWS_WARN_UNUSED_RESULT lws_generate_client_handshake(struct lws *wsi, char *pkt); diff --git a/lib/core-net/route.c b/lib/core-net/route.c index ce81dcf88..2fcb40193 100644 --- a/lib/core-net/route.c +++ b/lib/core-net/route.c @@ -259,7 +259,7 @@ _lws_route_pt_close_unroutable(struct lws_context_per_thread *pt) continue; if (_lws_route_check_wsi(wsi)) { - lwsl_info("%s: culling wsi %p\n", __func__, wsi); + lwsl_info("%s: culling wsi %s\n", __func__, lws_wsi_tag(wsi)); lws_wsi_close(wsi, LWS_TO_KILL_ASYNC); } } @@ -287,7 +287,7 @@ _lws_route_pt_close_route_users(struct lws_context_per_thread *pt, if (wsi->desc.sockfd != LWS_SOCK_INVALID && wsi->sa46_peer.sa4.sin_family && wsi->peer_route_uidx == uidx) { - lwsl_info("%s: culling wsi %p\n", __func__, wsi); + lwsl_info("%s: culling wsi %s\n", __func__, lws_wsi_tag(wsi)); lws_wsi_close(wsi, LWS_TO_KILL_ASYNC); } } diff --git a/lib/core-net/service.c b/lib/core-net/service.c index 3b37d58b8..1eda1619b 100644 --- a/lib/core-net/service.c +++ b/lib/core-net/service.c @@ -66,7 +66,7 @@ lws_handle_POLLOUT_event(struct lws *wsi, struct lws_pollfd *pollfd) volatile struct lws *vwsi = (volatile struct lws *)wsi; int n; - // lwsl_notice("%s: %p\n", __func__, wsi); + // lwsl_notice("%s: %s\n", __func__, lws_wsi_tag(wsi)); vwsi->leave_pollout_active = 0; vwsi->handling_pollout = 1; @@ -214,7 +214,8 @@ user_service_go_again: goto bail_ok; } - lwsl_debug("%s: %p: non mux: wsistate 0x%lx, ops %s\n", __func__, wsi, + lwsl_debug("%s: %s: non mux: wsistate 0x%lx, ops %s\n", __func__, + lws_wsi_tag(wsi), (unsigned long)wsi->wsistate, wsi->role_ops->name); vwsi = (volatile struct lws *)wsi; @@ -284,7 +285,7 @@ lws_rxflow_cache(struct lws *wsi, unsigned char *buf, int n, int len) if (m < 0) return LWSRXFC_ERROR; if (m) { - lwsl_debug("%s: added %p to rxflow list\n", __func__, wsi); + lwsl_debug("%s: added %s to rxflow list\n", __func__, lws_wsi_tag(wsi)); if (lws_dll2_is_detached(&wsi->dll_buflist)) lws_dll2_add_head(&wsi->dll_buflist, &pt->dll_buflist_owner); } @@ -382,7 +383,7 @@ lws_buflist_aware_read(struct lws_context_per_thread *pt, struct lws *wsi, int n, e, bns; uint8_t *ep, *b; - // lwsl_debug("%s: wsi %p: %s: prior %d\n", __func__, wsi, hint, prior); + // lwsl_debug("%s: %s: %s: prior %d\n", __func__, lws_wsi_tag(wsi), hint, prior); // lws_buflist_describe(&wsi->buflist, wsi, __func__); (void)hint; @@ -413,8 +414,8 @@ lws_buflist_aware_read(struct lws_context_per_thread *pt, struct lws *wsi, ebuf->token = ep; ebuf->len = n = lws_ssl_capable_read(wsi, ep, e); - lwsl_debug("%s: wsi %p: %s: ssl_capable_read %d\n", __func__, - wsi, hint, ebuf->len); + lwsl_debug("%s: %s: %s: ssl_capable_read %d\n", __func__, + lws_wsi_tag(wsi), hint, ebuf->len); if (!bns && /* only acknowledge error when we handled buflist content */ n == LWS_SSL_CAPABLE_ERROR) { @@ -506,8 +507,8 @@ lws_buflist_aware_finished_consuming(struct lws *wsi, struct lws_tokens *ebuf, if (m < 0) return 1; /* OOM */ if (m) { - lwsl_debug("%s: added %p to rxflow list\n", - __func__, wsi); + lwsl_debug("%s: added %s to rxflow list\n", + __func__, lws_wsi_tag(wsi)); if (lws_dll2_is_detached(&wsi->dll_buflist)) lws_dll2_add_head(&wsi->dll_buflist, &pt->dll_buflist_owner); @@ -541,8 +542,8 @@ lws_service_do_ripe_rxflow(struct lws_context_per_thread *pt) pfd.revents = LWS_POLLIN; pfd.fd = -1; - lwsl_debug("%s: rxflow processing: %p fc=%d, 0x%lx\n", __func__, - wsi, lws_is_flowcontrolled(wsi), + lwsl_debug("%s: rxflow processing: %s fc=%d, 0x%lx\n", __func__, + lws_wsi_tag(wsi), lws_is_flowcontrolled(wsi), (unsigned long)wsi->wsistate); if (!lws_is_flowcontrolled(wsi) && @@ -688,8 +689,8 @@ lws_service_fd_tsi(struct lws_context *context, struct lws_pollfd *pollfd, if ((!(pollfd->revents & pollfd->events & LWS_POLLIN)) && (pollfd->revents & LWS_POLLHUP)) { wsi->socket_is_permanently_unusable = 1; - lwsl_debug("Session Socket %p (fd=%d) dead\n", - (void *)wsi, pollfd->fd); + lwsl_debug("Session Socket %s (fd=%d) dead\n", + lws_wsi_tag(wsi), pollfd->fd); goto close_and_handled; } @@ -743,7 +744,7 @@ lws_service_fd_tsi(struct lws_context *context, struct lws_pollfd *pollfd, //lwsl_notice("%s: %s pollin says please close me\n", __func__, // wsi->role_ops->name); close_and_handled: - lwsl_debug("%p: Close and handled\n", wsi); + lwsl_debug("%s: %s: Close and handled\n", __func__, lws_wsi_tag(wsi)); lws_close_free_wsi(wsi, LWS_CLOSE_STATUS_NOSTATUS, "close_and_handled"); #if defined(_DEBUG) && defined(LWS_WITH_LIBUV) diff --git a/lib/core-net/socks5-client.c b/lib/core-net/socks5-client.c index 6042eb942..975f204c3 100644 --- a/lib/core-net/socks5-client.c +++ b/lib/core-net/socks5-client.c @@ -260,8 +260,8 @@ lws_socks5c_handle_state(struct lws *wsi, struct lws_pollfd *pollfd, /* handle proxy hung up on us */ if (pollfd->revents & LWS_POLLHUP) { - lwsl_warn("SOCKS connection %p (fd=%d) dead\n", - (void *)wsi, pollfd->fd); + lwsl_warn("SOCKS conn %s (fd=%d) dead\n", + lws_wsi_tag(wsi), pollfd->fd); *pcce = "socks conn dead"; return LW5CHS_RET_BAIL3; } diff --git a/lib/core-net/vhost.c b/lib/core-net/vhost.c index 62cf20c6f..c66596879 100644 --- a/lib/core-net/vhost.c +++ b/lib/core-net/vhost.c @@ -513,6 +513,9 @@ lws_create_vhost(struct lws_context *context, else vh->name = info->vhost_name; + __lws_lc_tag(&context->lcg[LWSLCG_VHOST], &vh->lc, "%s|%s|%d", vh->name, + info->iface ? info->iface : "", info->port); + #if defined(LWS_ROLE_H1) || defined(LWS_ROLE_H2) vh->http.error_document_404 = info->error_document_404; #endif @@ -946,6 +949,8 @@ __lws_create_event_pipes(struct lws_context *context) if (!wsi) return 1; + __lws_lc_tag(&context->lcg[LWSLCG_WSI], &wsi->lc, "pipe"); + wsi->event_pipe = 1; pt->pipe_wsi = wsi; @@ -1250,8 +1255,7 @@ __lws_vhost_destroy2(struct lws_vhost *vh) lws_dll2_foreach_safe(&vh->abstract_instances_owner, NULL, destroy_ais); #endif - lwsl_debug(" %s: Freeing vhost %p\n", __func__, vh); - + __lws_lc_untag(&vh->lc); memset(vh, 0, sizeof(*vh)); lws_free(vh); } @@ -1488,7 +1492,8 @@ lws_vhost_active_conns(struct lws *wsi, struct lws **nwsi, const char *adsin) struct lws *w = lws_container_of(d, struct lws, dll_cli_active_conns); - lwsl_debug("%s: check %p %p %s %s %d %d\n", __func__, wsi, w, + lwsl_debug("%s: check %s %s %s %s %d %d\n", __func__, + lws_wsi_tag(wsi), lws_wsi_tag(w), adsin, w->cli_hostname_copy, wsi->c_port, w->c_port); if (w != wsi && @@ -1581,8 +1586,9 @@ lws_vhost_active_conns(struct lws *wsi, struct lws **nwsi, const char *adsin) * to get there or fail. */ - lwsl_notice("%s: apply %p to txn queue on %p state 0x%lx\n", - __func__, wsi, w, (unsigned long)w->wsistate); + lwsl_notice("%s: apply %s to txn queue on %s state 0x%lx\n", + __func__, lws_wsi_tag(wsi), lws_wsi_tag(w), + (unsigned long)w->wsistate); /* * ...let's add ourselves to his transaction queue... * we are adding ourselves at the TAIL @@ -1618,3 +1624,9 @@ solo: } #endif #endif + +const char * +lws_vh_tag(struct lws_vhost *vh) +{ + return lws_lc_tag(&vh->lc); +} diff --git a/lib/core-net/wsi-timeout.c b/lib/core-net/wsi-timeout.c index e5dcf6494..bef81edb7 100644 --- a/lib/core-net/wsi-timeout.c +++ b/lib/core-net/wsi-timeout.c @@ -88,9 +88,9 @@ lws_sul_wsitimeout_cb(lws_sorted_usec_list_t *sul) // if (wsi->pending_timeout != PENDING_TIMEOUT_HTTP_KEEPALIVE_IDLE) #if defined(LWS_ROLE_H1) || defined(LWS_ROLE_H2) if (wsi->pending_timeout != PENDING_TIMEOUT_USER_OK) - lwsl_info("wsi %p: TIMEDOUT WAITING on %d " - "(did hdr %d, ah %p, wl %d)\n", - (void *)wsi, wsi->pending_timeout, + lwsl_info("%s: %s: TIMEDOUT WAITING on %d " + "(did hdr %d, ah %p, wl %d)\n", __func__, + lws_wsi_tag(wsi), wsi->pending_timeout, wsi->hdr_parsing_completed, wsi->http.ah, pt->http.ah_wait_list_length); #if defined(LWS_WITH_CGI) @@ -99,8 +99,8 @@ lws_sul_wsitimeout_cb(lws_sorted_usec_list_t *sul) #endif #else if (wsi->pending_timeout != PENDING_TIMEOUT_USER_OK) - lwsl_info("wsi %p: TIMEDOUT WAITING on %d ", (void *)wsi, - wsi->pending_timeout); + lwsl_info("%s: %s: TIMEDOUT WAITING on %d ", __func__, + lws_wsi_tag(wsi), wsi->pending_timeout); #endif /* cgi timeout */ if (wsi->pending_timeout != PENDING_TIMEOUT_HTTP_KEEPALIVE_IDLE) @@ -133,7 +133,8 @@ __lws_set_timeout(struct lws *wsi, enum pending_timeout reason, int secs) &wsi->sul_timeout, ((lws_usec_t)secs) * LWS_US_PER_SEC); - lwsl_debug("%s: %p: %d secs, reason %d\n", __func__, wsi, secs, reason); + lwsl_debug("%s: %s: %d secs, reason %d\n", __func__, lws_wsi_tag(wsi), + secs, reason); wsi->pending_timeout = reason; } @@ -152,7 +153,7 @@ lws_set_timeout(struct lws *wsi, enum pending_timeout reason, int secs) goto bail; if (secs == LWS_TO_KILL_SYNC) { - lwsl_debug("synchronously killing %p\n", wsi); + lwsl_debug("%s: TO_KILL_SYNC %s\n", __func__, lws_wsi_tag(wsi)); lws_context_unlock(pt->context); lws_close_free_wsi(wsi, LWS_CLOSE_STATUS_NOSTATUS, "to sync kill"); @@ -190,7 +191,7 @@ lws_set_timeout_us(struct lws *wsi, enum pending_timeout reason, lws_usec_t us) __lws_sul_insert_us(&pt->pt_sul_owner[LWSSULLI_MISS_IF_SUSPENDED], &wsi->sul_timeout, us); - lwsl_notice("%s: %p: %llu us, reason %d\n", __func__, wsi, + lwsl_notice("%s: %s: %llu us, reason %d\n", __func__, lws_wsi_tag(wsi), (unsigned long long)us, reason); wsi->pending_timeout = reason; @@ -229,8 +230,8 @@ lws_sul_timed_callback_vh_protocol_cb(lws_sorted_usec_list_t *sul) plwsa->vhost = tvp->vhost; /* not a real bound wsi */ plwsa->protocol = tvp->protocol; - lwsl_debug("%s: timed cb: vh %s, protocol %s, reason %d\n", __func__, - tvp->vhost->name, tvp->protocol->name, tvp->reason); + lwsl_debug("%s: timed cb: %s, protocol %s, reason %d\n", __func__, + lws_vh_tag(tvp->vhost), tvp->protocol->name, tvp->reason); tvp->protocol->callback((struct lws *)plwsa, tvp->reason, NULL, NULL, 0); @@ -298,7 +299,7 @@ lws_validity_cb(lws_sorted_usec_list_t *sul) /* one of either the ping or hangup validity threshold was crossed */ if (wsi->validity_hup) { - lwsl_info("%s: wsi %p: validity too old\n", __func__, wsi); + lwsl_info("%s: %s: validity too old\n", __func__, lws_wsi_tag(wsi)); __lws_close_free_wsi(wsi, LWS_CLOSE_STATUS_NOSTATUS, "validity timeout"); return; @@ -306,7 +307,7 @@ lws_validity_cb(lws_sorted_usec_list_t *sul) /* schedule a protocol-dependent ping */ - lwsl_info("%s: wsi %p: scheduling validity check\n", __func__, wsi); + lwsl_info("%s: %s: scheduling validity check\n", __func__, lws_wsi_tag(wsi)); if (lws_rops_fidx(wsi->role_ops, LWS_ROPS_issue_keepalive)) lws_rops_func_fidx(wsi->role_ops, LWS_ROPS_issue_keepalive). @@ -347,8 +348,8 @@ _lws_validity_confirmed_role(struct lws *wsi) wsi->validity_hup = rbo->secs_since_valid_ping >= rbo->secs_since_valid_hangup; - lwsl_info("%s: wsi %p: setting validity timer %ds (hup %d)\n", - __func__, wsi, + lwsl_info("%s: %s: setting validity timer %ds (hup %d)\n", + __func__, lws_wsi_tag(wsi), wsi->validity_hup ? rbo->secs_since_valid_hangup : rbo->secs_since_valid_ping, wsi->validity_hup); diff --git a/lib/core-net/wsi.c b/lib/core-net/wsi.c index 75a8f0643..23e024a5e 100644 --- a/lib/core-net/wsi.c +++ b/lib/core-net/wsi.c @@ -24,12 +24,18 @@ #include "private-lib-core.h" +const char * +lws_wsi_tag(struct lws *wsi) +{ + return lws_lc_tag(&wsi->lc); +} + #if defined (_DEBUG) void lwsi_set_role(struct lws *wsi, lws_wsi_state_t role) { wsi->wsistate = (wsi->wsistate & (~LWSI_ROLE_MASK)) | role; - lwsl_debug("lwsi_set_role(%p, 0x%lx)\n", wsi, + lwsl_debug("lwsi_set_role(%s, 0x%lx)\n", lws_wsi_tag(wsi), (unsigned long)wsi->wsistate); } @@ -37,7 +43,7 @@ void lwsi_set_state(struct lws *wsi, lws_wsi_state_t lrs) { wsi->wsistate = (wsi->wsistate & (~LRS_MASK)) | lrs; - lwsl_debug("lwsi_set_state(%p, 0x%lx)\n", wsi, + lwsl_debug("lwsi_set_state(%s, 0x%lx)\n", lws_wsi_tag(wsi), (unsigned long)wsi->wsistate); } #endif @@ -196,12 +202,14 @@ lws_callback_vhost_protocols(struct lws *wsi, int reason, void *in, int 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) { struct lws_context_per_thread *pt = &context->pt[tsi]; size_t s = sizeof(struct lws); struct lws *wsi; + assert(tsi >= 0 && tsi < LWS_MAX_SMP); + lws_context_assert_lock_held(context); #if defined(LWS_WITH_EVENT_LIBS) @@ -231,8 +239,8 @@ __lws_wsi_create_with_role(struct lws_context *context, int tsi, pt->count_wsi_allocated++; lws_pt_unlock(pt); - lwsl_notice("%s: tsi %d: role: %s\n", __func__, tsi, - ops ? ops->name : "none"); +// lwsl_debug("%s: tsi %d: role: %s\n", __func__, tsi, +// ops ? ops->name : "none"); return wsi; } @@ -326,7 +334,7 @@ lws_rx_flow_control(struct lws *wsi, int _enable) lwsi_role_h2_ENCAPSULATION(wsi)) return 0; // !!! - lwsl_info("%s: %p 0x%x\n", __func__, wsi, _enable); + lwsl_info("%s: %s 0x%x\n", __func__, lws_wsi_tag(wsi), _enable); if (!(_enable & LWS_RXFLOW_REASON_APPLIES)) { /* @@ -353,7 +361,8 @@ lws_rx_flow_control(struct lws *wsi, int _enable) wsi->rxflow_change_to = LWS_RXFLOW_PENDING_CHANGE | (!wsi->rxflow_bitmap); - lwsl_info("%s: %p: bitmap 0x%x: en 0x%x, ch 0x%x\n", __func__, wsi, + lwsl_info("%s: %s: bitmap 0x%x: en 0x%x, ch 0x%x\n", __func__, + lws_wsi_tag(wsi), wsi->rxflow_bitmap, en, wsi->rxflow_change_to); if (_enable & LWS_RXFLOW_REASON_FLAG_PROCESS_NOW || @@ -439,7 +448,7 @@ __lws_rx_flow_control(struct lws *wsi) wsi->rxflow_change_to &= ~LWS_RXFLOW_PENDING_CHANGE; - lwsl_info("rxflow: wsi %p change_to %d\n", wsi, + lwsl_info("rxflow: %s change_to %d\n", lws_wsi_tag(wsi), wsi->rxflow_change_to & LWS_RXFLOW_ALLOW); /* adjust the pollfd for this wsi */ @@ -482,8 +491,9 @@ lws_ensure_user_space(struct lws *wsi) return 1; } } else - lwsl_debug("%s: %p protocol pss %lu, user_space=%p\n", __func__, - wsi, (long)wsi->a.protocol->per_session_data_size, + lwsl_debug("%s: %s protocol pss %lu, user_space=%p\n", __func__, + lws_wsi_tag(wsi), + (long)wsi->a.protocol->per_session_data_size, wsi->user_space); return 0; } @@ -554,8 +564,8 @@ lws_role_transition(struct lws *wsi, enum lwsi_role role, enum lwsi_state state, #if (_LWS_ENABLED_LOGS & LLL_DEBUG) if (wsi->role_ops) name = wsi->role_ops->name; - lwsl_debug("%s: %p: wsistate 0x%lx, ops %s\n", __func__, wsi, - (unsigned long)wsi->wsistate, name); + lwsl_debug("%s: %s: wsistate 0x%lx, ops %s\n", __func__, + lws_wsi_tag(wsi), (unsigned long)wsi->wsistate, name); #endif } @@ -1025,8 +1035,8 @@ _lws_generic_transaction_completed_active_conn(struct lws **_wsi, char take_vh_l /* after the first one, they can only be coming from the queue */ wnew->transaction_from_pipeline_queue = 1; - lwsl_notice("%s: pipeline queue passed wsi %p on to queued wsi %p\n", - __func__, wsi, wnew); + lwsl_notice("%s: pipeline queue passed %s on to queued %s\n", + __func__, lws_wsi_tag(wsi), lws_wsi_tag(wnew)); *_wsi = wnew; /* inform caller we swapped */ @@ -1046,7 +1056,8 @@ lws_raw_transaction_completed(struct lws *wsi) * Defer the close until the last part of the partial is sent. * */ - lwsl_debug("%s: %p: deferring due to partial\n", __func__, wsi); + lwsl_debug("%s: %s: deferring due to partial\n", __func__, + lws_wsi_tag(wsi)); wsi->close_when_buffered_out_drained = 1; lws_callback_on_writable(wsi); @@ -1125,7 +1136,7 @@ lws_http_close_immortal(struct lws *wsi) wsi->mux_stream_immortal = 0; nwsi = lws_get_network_wsi(wsi); - lwsl_debug("%s: %p %p %d\n", __func__, wsi, nwsi, + lwsl_debug("%s: %s %s %d\n", __func__, lws_wsi_tag(wsi), lws_wsi_tag(nwsi), nwsi->immortal_substream_count); assert(nwsi->immortal_substream_count); nwsi->immortal_substream_count--; @@ -1159,7 +1170,7 @@ lws_mux_mark_immortal(struct lws *wsi) if (!nwsi) return; - lwsl_debug("%s: %p %p %d\n", __func__, wsi, nwsi, + lwsl_debug("%s: %s %s %d\n", __func__, lws_wsi_tag(wsi), lws_wsi_tag(nwsi), nwsi->immortal_substream_count); wsi->mux_stream_immortal = 1; @@ -1208,8 +1219,8 @@ lws_wsi_client_stash_item(struct lws *wsi, int stash_idx, int hdr_idx) void lws_wsi_mux_insert(struct lws *wsi, struct lws *parent_wsi, int sid) { - lwsl_info("%s: wsi %p, par %p: assign sid %d (curr %d)\n", __func__, - wsi, parent_wsi, sid, wsi->mux.my_sid); + lwsl_info("%s: %s, par %s: assign sid %d (curr %d)\n", __func__, + lws_wsi_tag(wsi), lws_wsi_tag(parent_wsi), sid, wsi->mux.my_sid); if (wsi->mux.my_sid && wsi->mux.my_sid != (unsigned int)sid) assert(0); @@ -1247,8 +1258,9 @@ lws_wsi_mux_dump_children(struct lws *wsi) lws_start_foreach_llp(struct lws **, w, wsi->mux.parent_wsi->mux.child_list) { - lwsl_info(" \\---- child %s %p\n", - (*w)->role_ops ? (*w)->role_ops->name : "?", *w); + lwsl_info(" \\---- child %s %s\n", + (*w)->role_ops ? (*w)->role_ops->name : "?", + lws_wsi_tag(*w)); assert(*w != (*w)->mux.sibling_list); } lws_end_foreach_llp(w, mux.sibling_list); #endif @@ -1265,7 +1277,7 @@ lws_wsi_mux_close_children(struct lws *wsi, int reason) w = &wsi->mux.child_list; while (*w) { - lwsl_info(" closing child %p\n", *w); + lwsl_info(" closing child %s\n", lws_wsi_tag(*w)); /* disconnect from siblings */ wsi2 = (*w)->mux.sibling_list; assert (wsi2 != *w); @@ -1290,8 +1302,8 @@ lws_wsi_mux_sibling_disconnect(struct lws *wsi) wsi2 = (*w)->mux.sibling_list; (*w)->mux.sibling_list = NULL; *w = wsi2; - lwsl_debug(" %p disentangled from sibling %p\n", - wsi, wsi2); + lwsl_debug(" %s disentangled from sibling %s\n", + lws_wsi_tag(wsi), lws_wsi_tag(wsi2)); break; } } lws_end_foreach_llp(w, mux.sibling_list); @@ -1304,14 +1316,14 @@ void lws_wsi_mux_dump_waiting_children(struct lws *wsi) { #if defined(_DEBUG) - lwsl_info("%s: %p: children waiting for POLLOUT service:\n", - __func__, wsi); + lwsl_info("%s: %s: children waiting for POLLOUT service:\n", + __func__, lws_wsi_tag(wsi)); wsi = wsi->mux.child_list; while (wsi) { - lwsl_info(" %c %p: sid %u: 0x%x %s %s\n", + lwsl_info(" %c %s: sid %u: 0x%x %s %s\n", wsi->mux.requested_POLLOUT ? '*' : ' ', - wsi, wsi->mux.my_sid, lwsi_state(wsi), + lws_wsi_tag(wsi), wsi->mux.my_sid, lwsi_state(wsi), wsi->role_ops->name, wsi->a.protocol ? wsi->a.protocol->name : "noprotocol"); @@ -1331,8 +1343,8 @@ lws_wsi_mux_mark_parents_needing_writeable(struct lws *wsi) wsi2 = wsi; while (wsi2) { wsi2->mux.requested_POLLOUT = 1; - lwsl_info("%s: mark wsi: %p, sid %u, pending writable\n", - __func__, wsi2, wsi2->mux.my_sid); + lwsl_info("%s: mark: %s, sid %u, pending writable\n", + __func__, lws_wsi_tag(wsi2), wsi2->mux.my_sid); wsi2 = wsi2->mux.parent_wsi; } @@ -1346,7 +1358,8 @@ lws_wsi_mux_move_child_to_tail(struct lws **wsi2) while (w) { if (!w->mux.sibling_list) { /* w is the current last */ - lwsl_debug("w=%p, *wsi2 = %p\n", w, *wsi2); + lwsl_debug("w=%s, *wsi2 = %s\n", lws_wsi_tag(w), + lws_wsi_tag(*wsi2)); if (w == *wsi2) /* we are already last */ break; @@ -1481,7 +1494,8 @@ lws_wsi_mux_apply_queue(struct lws *wsi) #if defined(LWS_ROLE_H2) if (lwsi_role_http(wsi) && lwsi_state(w) == LRS_H2_WAITING_TO_SEND_HEADERS) { - lwsl_info("%s: cli pipeq %p to be h2\n", __func__, w); + lwsl_info("%s: cli pipeq %s to be h2\n", __func__, + lws_wsi_tag(w)); lwsi_set_state(w, LRS_H1C_ISSUE_HANDSHAKE2); @@ -1496,7 +1510,8 @@ lws_wsi_mux_apply_queue(struct lws *wsi) #if defined(LWS_ROLE_MQTT) if (lwsi_role_mqtt(wsi) && lwsi_state(wsi) == LRS_ESTABLISHED) { - lwsl_info("%s: cli pipeq %p to be mqtt\n", __func__, w); + lwsl_info("%s: cli pipeq %s to be mqtt\n", __func__, + lws_wsi_tag(w)); /* remove ourselves from client queue */ lws_dll2_remove(&w->dll2_cli_txn_queue); diff --git a/lib/core/context.c b/lib/core/context.c index 3e74a5c89..b1ea22081 100644 --- a/lib/core/context.c +++ b/lib/core/context.c @@ -648,6 +648,53 @@ lws_create_context(const struct lws_context_creation_info *info) context->udp_loss_sim_rx_pc); #endif +#if defined(LWS_WITH_NETWORK) + context->lcg[LWSLCG_WSI].tag_prefix = "wsi"; + context->lcg[LWSLCG_VHOST].tag_prefix = "vh"; + +#if defined(LWS_WITH_SERVER) + context->lcg[LWSLCG_WSI_SERVER].tag_prefix = "wsisrv"; +#endif +#if defined(LWS_WITH_CLIENT) + context->lcg[LWSLCG_WSI_CLIENT].tag_prefix = "wsicli"; +#endif + +#if defined(LWS_WITH_SECURE_STREAMS) +#if defined(LWS_WITH_CLIENT) + context->lcg[LWSLCG_SS_CLIENT].tag_prefix = "SScli"; +#endif +#if defined(LWS_WITH_SERVER) + context->lcg[LWSLCG_SS_SERVER].tag_prefix = "SSsrv"; +#endif +#if defined(LWS_WITH_CLIENT) + context->lcg[LWSLCG_WSI_SS_CLIENT].tag_prefix = "wsiSScli"; +#endif +#if defined(LWS_WITH_SERVER) + context->lcg[LWSLCG_WSI_SS_SERVER].tag_prefix = "wsiSSsrv"; +#endif +#endif +#endif + + /* + * Proxy group + */ + +#if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) +#if defined(LWS_WITH_CLIENT) + context->lcg[LWSLCG_SSP_CLIENT].tag_prefix = "SSPcli"; +#endif +#if defined(LWS_WITH_SERVER) + context->lcg[LWSLCG_SSP_ONWARD].tag_prefix = "SSPonw"; +#endif +#if defined(LWS_WITH_CLIENT) + context->lcg[LWSLCG_WSI_SSP_CLIENT].tag_prefix = "wsiSSPcli"; +#endif +#if defined(LWS_WITH_SERVER) + context->lcg[LWSLCG_WSI_SSP_ONWARD].tag_prefix = "wsiSSPonw"; +#endif +#endif + + #if defined(LWS_WITH_SECURE_STREAMS_STATIC_POLICY_ONLY) /* directly use the user-provided policy object list */ context->pss_policies = info->pss_policies; @@ -1601,8 +1648,8 @@ lws_context_destroy(struct lws_context *context) if (wsi) { - lwsl_debug("%s: pt %d: closing wsi %p\n", - __func__, n, wsi); + lwsl_debug("%s: pt %d: closing wsi %p: role %s\n", + __func__, n, wsi, wsi->role_ops->name); lws_close_free_wsi(wsi, LWS_CLOSE_STATUS_NOSTATUS_CONTEXT_DESTROY, diff --git a/lib/core/logs.c b/lib/core/logs.c index 3fde1192a..c292fd71e 100644 --- a/lib/core/logs.c +++ b/lib/core/logs.c @@ -44,6 +44,107 @@ static void (*lwsl_emit)(int level, const char *line) static const char * log_level_names ="EWNIDPHXCLUT??"; #endif +/* + * Name an instance tag and attach to a group + */ + +void +__lws_lc_tag(lws_lifecycle_group_t *grp, lws_lifecycle_t *lc, + const char *format, ...) +{ + va_list ap; + int n; + + assert(grp->tag_prefix); /* lc group must have a tag prefix string */ + + n = lws_snprintf(lc->gutag, sizeof(lc->gutag) - 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 - + 1u, format, ap); + va_end(ap); + + if (n < (int)sizeof(lc->gutag) - 2) { + lc->gutag[n++] = ']'; + lc->gutag[n++] = '\0'; + } else { + lc->gutag[sizeof(lc->gutag) - 2] = ']'; + lc->gutag[sizeof(lc->gutag) - 1] = '\0'; + } + + lc->us_creation = (uint64_t)lws_now_usecs(); + lws_dll2_add_tail(&lc->list, &grp->owner); + + lwsl_notice(" ++ %s (%d)\n", lc->gutag, (int)grp->owner.count); +} + +/* + * Normally we want to set the tag one time at creation. But sometimes we + * don't have enough information at that point to give it a meaningful tag, eg, + * it's an accepted, served connection but we haven't read data from it yet + * to find out what it wants to be. + * + * This allows you to append some extra info to the tag in those cases, the + * initial tag remains the same on the lhs so it can be tracked correctly. + */ + +void +__lws_lc_tag_append(lws_lifecycle_t *lc, const char *app) +{ + int n = (int)strlen(lc->gutag); + + if (n && lc->gutag[n - 1] == ']') + n--; + + 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] = ']'; + lc->gutag[sizeof(lc->gutag) - 1] = '\0'; + } +} + +/* + * Remove instance from group + */ + +void +__lws_lc_untag(lws_lifecycle_t *lc) +{ + //lws_lifecycle_group_t *grp; + char buf[24]; + + if (!lc->gutag[0]) { /* we never tagged this object... */ + lwsl_err("%s: %s never tagged\n", __func__, lc->gutag); + assert(0); + return; + } + + if (!lc->list.owner) { /* we already untagged this object... */ + lwsl_err("%s: %s untagged twice\n", __func__, lc->gutag); + assert(0); + return; + } + + //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); + + lwsl_notice(" -- %s (%d) %s\n", lc->gutag, (int)lc->list.owner->count - 1, buf); + + lws_dll2_remove(&lc->list); +} + +const char * +lws_lc_tag(lws_lifecycle_t *lc) +{ + return lc->gutag; +} + + #if defined(LWS_LOGS_TIMESTAMP) int lwsl_timestamp(int level, char *p, int len) diff --git a/lib/core/private-lib-core.h b/lib/core/private-lib-core.h index 2c598b873..81ceb3aa6 100644 --- a/lib/core/private-lib-core.h +++ b/lib/core/private-lib-core.h @@ -111,7 +111,6 @@ #define strerror(x) "" #endif - /* * * ------ private platform defines ------ @@ -140,6 +139,41 @@ #include "libwebsockets.h" + /* + * + * ------ lifecycle defines ------ + * + */ + +typedef struct lws_lifecycle_group { + lws_dll2_owner_t owner; /* active count / list */ + uint64_t ordinal; /* monotonic uid count */ + const char *tag_prefix; /* eg, "wsi" */ +} lws_lifecycle_group_t; + +typedef struct lws_lifecycle { +#if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) + /* we append parent streams on the tag */ + char gutag[96]; /* object unique tag + relationship info */ +#else + char gutag[32]; +#endif + lws_dll2_t list; /* group list membership */ + uint64_t us_creation; /* creation timestamp */ +} lws_lifecycle_t; + +void +__lws_lc_tag(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); + +const char * +lws_lc_tag(lws_lifecycle_t *lc); /* * Generic bidi tx credit management @@ -285,6 +319,57 @@ typedef struct lws_attach_item { lws_system_states_t state; } lws_attach_item_t; +/* + * These are the context's lifecycle group indexes that exist in this build + * configuration. If you add some, make sure to also add the tag_prefix in + * context.c context creation with matching preprocessor conditionals. + */ + +enum { + LWSLCG_WSI, /* generic wsi, eg, pipe, listen */ + LWSLCG_VHOST, + +#if defined(LWS_WITH_SERVER) + LWSLCG_WSI_SERVER, /* server wsi */ +#endif +#if defined(LWS_WITH_CLIENT) + LWSLCG_WSI_CLIENT, /* client wsi */ +#endif + +#if defined(LWS_WITH_SECURE_STREAMS) +#if defined(LWS_WITH_CLIENT) + LWSLCG_SS_CLIENT, /* secstream client handle */ +#endif +#if defined(LWS_WITH_SERVER) + LWSLCG_SS_SERVER, /* secstream server handle */ +#endif +#if defined(LWS_WITH_CLIENT) + LWSLCG_WSI_SS_CLIENT, /* wsi bound to ss client handle */ +#endif +#if defined(LWS_WITH_SERVER) + LWSLCG_WSI_SS_SERVER, /* wsi bound to ss server handle */ +#endif +#endif + +#if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) +#if defined(LWS_WITH_CLIENT) + LWSLCG_SSP_CLIENT, /* SSPC handle client connection to proxy */ +#endif +#if defined(LWS_WITH_SERVER) + LWSLCG_SSP_ONWARD, /* SS handle at proxy for onward conn */ +#endif +#if defined(LWS_WITH_CLIENT) + LWSLCG_WSI_SSP_CLIENT, /* wsi bound to SSPC cli conn to proxy */ +#endif +#if defined(LWS_WITH_SERVER) + LWSLCG_WSI_SSP_ONWARD, /* wsi bound to Proxy onward connection */ +#endif +#endif + + /* always last */ + LWSLCG_COUNT +}; + /* * the rest is managed per-context, that includes * @@ -318,6 +403,9 @@ struct lws_context { struct lws_context_per_thread pt[LWS_MAX_SMP]; lws_retry_bo_t default_retry; lws_sorted_usec_list_t sul_system_state; + + lws_lifecycle_group_t lcg[LWSLCG_COUNT]; + #if defined(LWS_WITH_NETLINK) lws_sorted_usec_list_t sul_nl_coldplug; #endif diff --git a/lib/event-libs/glib/glib.c b/lib/event-libs/glib/glib.c index e5c01ec9c..5022a100c 100644 --- a/lib/event-libs/glib/glib.c +++ b/lib/event-libs/glib/glib.c @@ -132,7 +132,7 @@ lws_glib_dispatch(GSource *src, GSourceFunc x, gpointer userData) eventfd.events = eventfd.revents; eventfd.fd = sub->wsi->desc.sockfd; - lwsl_debug("%s: wsi %p: fd %d, events %d\n", __func__, sub->wsi, + lwsl_debug("%s: %s: fd %d, events %d\n", __func__, lws_wsi_tag(sub->wsi), eventfd.fd, eventfd.revents); pt = &sub->wsi->a.context->pt[(int)sub->wsi->tsi]; @@ -378,7 +378,7 @@ elops_io_glib(struct lws *wsi, int flags) wsipr->w_read.actual_events = cond; - lwsl_debug("%s: wsi %p, fd %d, 0x%x/0x%x\n", __func__, wsi, + lwsl_debug("%s: %s, fd %d, 0x%x/0x%x\n", __func__, lws_wsi_tag(wsi), wsi->desc.sockfd, flags, (int)cond); g_source_modify_unix_fd(wsi_to_gsource(wsi), wsi_to_subclass(wsi)->tag, diff --git a/lib/event-libs/libev/libev.c b/lib/event-libs/libev/libev.c index 4d9f36ac1..1f054c96c 100644 --- a/lib/event-libs/libev/libev.c +++ b/lib/event-libs/libev/libev.c @@ -302,8 +302,8 @@ elops_io_ev(struct lws *wsi, int flags) struct lws_pt_eventlibs_libev *ptpr = pt_to_priv_ev(pt); struct lws_wsi_eventlibs_libev *w = wsi_to_priv_ev(wsi); - lwsl_debug("%s: wsi %p %s flags 0x%x %p %d\n", __func__, - wsi, wsi->role_ops->name, flags, + lwsl_debug("%s: %s %s flags 0x%x %p %d\n", __func__, + lws_wsi_tag(wsi), wsi->role_ops->name, flags, ptpr->io_loop, pt->is_destroyed); if (!ptpr->io_loop || pt->is_destroyed) diff --git a/lib/event-libs/libuv/libuv.c b/lib/event-libs/libuv/libuv.c index 68a4029ec..2d668da64 100644 --- a/lib/event-libs/libuv/libuv.c +++ b/lib/event-libs/libuv/libuv.c @@ -465,12 +465,12 @@ elops_wsi_logical_close_uv(struct lws *wsi) return 0; if (wsi->listener || wsi->event_pipe) { - lwsl_debug("%s: %p: %d %d stop listener / pipe poll\n", - __func__, wsi, wsi->listener, wsi->event_pipe); + lwsl_debug("%s: %s: %d %d stop listener / pipe poll\n", + __func__, lws_wsi_tag(wsi), wsi->listener, wsi->event_pipe); if (wsi_to_priv_uv(wsi)->w_read.pwatcher) uv_poll_stop(wsi_to_priv_uv(wsi)->w_read.pwatcher); } - lwsl_debug("%s: lws_libuv_closehandle: wsi %p\n", __func__, wsi); + lwsl_debug("%s: lws_libuv_closehandle: %s\n", __func__, lws_wsi_tag(wsi)); /* * libuv has to do his own close handle processing asynchronously */ @@ -504,7 +504,7 @@ elops_close_handle_manually_uv(struct lws *wsi) { uv_handle_t *h = (uv_handle_t *)wsi_to_priv_uv(wsi)->w_read.pwatcher; - lwsl_debug("%s: lws_libuv_closehandle: wsi %p\n", __func__, wsi); + lwsl_debug("%s: lws_libuv_closehandle: %s\n", __func__, lws_wsi_tag(wsi)); /* * the "manual" variant only closes the handle itself and the @@ -555,7 +555,7 @@ elops_io_uv(struct lws *wsi, int flags) struct lws_io_watcher_libuv *w = &(wsi_to_priv_uv(wsi)->w_read); int current_events = w->actual_events & (UV_READABLE | UV_WRITABLE); - lwsl_debug("%s: %p: %d\n", __func__, wsi, flags); + lwsl_debug("%s: %s: %d\n", __func__, lws_wsi_tag(wsi), flags); /* w->context is set after the loop is initialized */ @@ -783,7 +783,7 @@ lws_libuv_closewsi(uv_handle_t* handle) int lspd = 0; #endif - lwsl_info("%s: %p\n", __func__, wsi); + lwsl_info("%s: %s\n", __func__, lws_wsi_tag(wsi)); lws_context_lock(context, __func__); @@ -856,7 +856,7 @@ lws_libuv_closehandle(struct lws *wsi) return; } - lwsl_debug("%s: %p\n", __func__, wsi); + lwsl_debug("%s: %s\n", __func__, lws_wsi_tag(wsi)); wsi->told_event_loop_closed = 1; diff --git a/lib/misc/peer-limits.c b/lib/misc/peer-limits.c index d2e38176b..32ea50dc4 100644 --- a/lib/misc/peer-limits.c +++ b/lib/misc/peer-limits.c @@ -219,14 +219,15 @@ lws_peer_dump_from_wsi(struct lws *wsi) peer = wsi->peer; #if defined(LWS_ROLE_H1) || defined(LWS_ROLE_H2) - lwsl_notice("%s: wsi %p: created %llu: wsi: %d/%d, ah %d/%d\n", - __func__, - wsi, (unsigned long long)peer->time_created, + lwsl_notice("%s: %s: created %llu: wsi: %d/%d, ah %d/%d\n", + __func__, lws_wsi_tag(wsi), + (unsigned long long)peer->time_created, peer->count_wsi, peer->total_wsi, peer->http.count_ah, peer->http.total_ah); #else - lwsl_notice("%s: wsi %p: created %llu: wsi: %d/%d\n", __func__, - wsi, (unsigned long long)peer->time_created, + lwsl_notice("%s: %s: created %llu: wsi: %d/%d\n", __func__, + lws_wsi_tag(wsi), + (unsigned long long)peer->time_created, peer->count_wsi, peer->total_wsi); #endif } diff --git a/lib/misc/threadpool/threadpool.c b/lib/misc/threadpool/threadpool.c index 1f43c0c1c..1109373f7 100644 --- a/lib/misc/threadpool/threadpool.c +++ b/lib/misc/threadpool/threadpool.c @@ -259,8 +259,8 @@ lws_threadpool_task_cleanup_destroy(struct lws_threadpool_task *task) lws_dll2_remove(&task->list); - lwsl_thread("%s: tp %p: cleaned finished task for wsi %p\n", - __func__, task->tp, task_to_wsi(task)); + lwsl_thread("%s: tp %p: cleaned finished task for %s\n", + __func__, task->tp, lws_wsi_tag(task_to_wsi(task))); lws_free(task); } @@ -283,8 +283,8 @@ __lws_threadpool_reap(struct lws_threadpool_task *task) t->task_queue_next = NULL; tp->done_queue_depth--; - lwsl_thread("%s: tp %s: reaped task wsi %p\n", __func__, - tp->name, task_to_wsi(task)); + lwsl_thread("%s: tp %s: reaped task %s\n", __func__, + tp->name, lws_wsi_tag(task_to_wsi(task))); break; } @@ -401,8 +401,8 @@ lws_threadpool_worker_sync(struct lws_pool *pool, lwsl_debug("%s: %p: LWS_TP_RETURN_SYNC in\n", __func__, task); pthread_mutex_lock(&pool->lock); /* ======================= pool lock */ - lwsl_info("%s: %s: task %p (%s): syncing with wsi %p\n", __func__, - pool->tp->name, task, task->name, task_to_wsi(task)); + lwsl_info("%s: %s: task %p (%s): syncing with %s\n", __func__, + pool->tp->name, task, task->name, lws_wsi_tag(task_to_wsi(task))); temp = task->status; state_transition(task, LWS_TP_STATUS_SYNCING); @@ -458,9 +458,9 @@ lws_threadpool_worker_sync(struct lws_pool *pool, task->late_sync_retries++; if (!tries) { lwsl_err("%s: %s: task %p (%s): SYNC timed out " - "(associated wsi %p)\n", + "(associated %s)\n", __func__, pool->tp->name, task, - task->name, task_to_wsi(task)); + task->name, lws_wsi_tag(task_to_wsi(task))); state_transition(task, LWS_TP_STATUS_STOPPING); goto done; @@ -872,8 +872,8 @@ lws_threadpool_dequeue_task(struct lws_threadpool_task *task) tp->done_queue_depth++; task->done = lws_now_usecs(); - lwsl_debug("%s: tp %p: removed queued task wsi %p\n", - __func__, tp, task_to_wsi(task)); + lwsl_debug("%s: tp %p: removed queued task %s\n", + __func__, tp, lws_wsi_tag(task_to_wsi(task))); break; } @@ -924,15 +924,16 @@ lws_threadpool_dequeue_task(struct lws_threadpool_task *task) pthread_mutex_unlock(&tp->pool_list[n].lock); lwsl_debug("%s: tp %p: request stop running task " - "for wsi %p\n", __func__, tp, task_to_wsi(task)); + "for %s\n", __func__, tp, + lws_wsi_tag(task_to_wsi(task))); break; } if (n == tp->threads_in_pool) { /* can't find it */ - lwsl_notice("%s: tp %p: no task for wsi %p, decoupling\n", - __func__, tp, task_to_wsi(task)); + lwsl_notice("%s: tp %p: no task for %s, decoupling\n", + __func__, tp, lws_wsi_tag(task_to_wsi(task))); lws_dll2_remove(&task->list); task->args.wsi = NULL; #if defined(LWS_WITH_SECURE_STREAMS) @@ -1029,9 +1030,9 @@ lws_threadpool_enqueue(struct lws_threadpool *tp, #endif lws_dll2_add_tail(&task->list, &args->wsi->tp_task_owner); - lwsl_thread("%s: tp %s: enqueued task %p (%s) for wsi %p, depth %d\n", - __func__, tp->name, task, task->name, task_to_wsi(task), - tp->queue_depth); + lwsl_thread("%s: tp %s: enqueued task %p (%s) for %s, depth %d\n", + __func__, tp->name, task, task->name, + lws_wsi_tag(task_to_wsi(task)), tp->queue_depth); /* alert any idle thread there's something new on the task list */ diff --git a/lib/plat/unix/unix-spawn.c b/lib/plat/unix/unix-spawn.c index 28c304e02..cf4d2009d 100644 --- a/lib/plat/unix/unix-spawn.c +++ b/lib/plat/unix/unix-spawn.c @@ -355,7 +355,11 @@ lws_spawn_piped(const struct lws_spawn_piped_info *i) lwsl_err("%s: unable to create lsp stdwsi\n", __func__); goto bail2; } - lsp->stdwsi[n]->lsp_channel = n; + + __lws_lc_tag(&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]); lsp->stdwsi[n]->a.protocol = pcol; lsp->stdwsi[n]->a.opaque_user_data = i->opaque; diff --git a/lib/plat/windows/windows-service.c b/lib/plat/windows/windows-service.c index 69c664c86..daeaf3cdb 100644 --- a/lib/plat/windows/windows-service.c +++ b/lib/plat/windows/windows-service.c @@ -269,8 +269,8 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi) if ((networkevents.lNetworkEvents & FD_CONNECT) && wsi_from_fd(context, pfd->fd) && !wsi_from_fd(context, pfd->fd)->udp) { - lwsl_debug("%s: FD_CONNECT: %p\n", __func__, - wsi_from_fd(context, pfd->fd)); + lwsl_debug("%s: FD_CONNECT: %s\n", __func__, + lws_wsi_tag(wsi_from_fd(context, pfd->fd))); pfd->revents &= ~LWS_POLLOUT; if (err && err != LWS_EALREADY && err != LWS_EINPROGRESS && diff --git a/lib/plat/windows/windows-spawn.c b/lib/plat/windows/windows-spawn.c index 427fa5d9c..b4dc68285 100644 --- a/lib/plat/windows/windows-spawn.c +++ b/lib/plat/windows/windows-spawn.c @@ -417,6 +417,10 @@ lws_spawn_piped(const struct lws_spawn_piped_info *i) lwsl_err("%s: unable to create lsp stdwsi\n", __func__); goto bail2; } + + __lws_lc_tag(&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]); lsp->stdwsi[n]->a.protocol = pcol; diff --git a/lib/roles/cgi/cgi-server.c b/lib/roles/cgi/cgi-server.c index 2e88f3298..5d2271463 100644 --- a/lib/roles/cgi/cgi-server.c +++ b/lib/roles/cgi/cgi-server.c @@ -75,7 +75,7 @@ lws_cgi_grace(lws_sorted_usec_list_t *sul) /* act on the reap cb from earlier */ - lwsl_info("%s: wsi %p\n", __func__, cgi->wsi); + lwsl_info("%s: %s\n", __func__, lws_wsi_tag(cgi->wsi)); if (!cgi->wsi->http.cgi->post_in_expected) cgi->wsi->http.cgi->cgi_transaction_over = 1; @@ -94,7 +94,7 @@ lws_cgi_reap_cb(void *opaque, lws_usec_t *accounting, siginfo_t *si, * The cgi has come to an end, by itself or with a signal... */ - lwsl_info("%s: wsi %p post_in_expected %d\n", __func__, wsi, + lwsl_info("%s: %s post_in_expected %d\n", __func__, lws_wsi_tag(wsi), (int)wsi->http.cgi->post_in_expected); /* @@ -903,7 +903,7 @@ lws_cgi_kill(struct lws *wsi) pid_t pid; int n, m; - lwsl_debug("%s: %p\n", __func__, wsi); + lwsl_debug("%s: %s\n", __func__, lws_wsi_tag(wsi)); if (!wsi->http.cgi || !wsi->http.cgi->lsp) return 0; @@ -960,9 +960,9 @@ lws_cgi_kill_terminated(struct lws_context_per_thread *pt) continue; if (cgi->content_length) { - lwsl_debug("%s: wsi %p: expected content " + lwsl_debug("%s: %s: expected content " "length seen: %lld\n", __func__, - cgi->wsi, + lws_wsi_tag(cgi->wsi), (unsigned long long)cgi->content_length_seen); } @@ -1031,10 +1031,10 @@ lws_cgi_kill_terminated(struct lws_context_per_thread *pt) continue; if (cgi->content_length) - lwsl_debug("%s: wsi %p: expected " + lwsl_debug("%s: %s: expected " "content len seen: %lld\n", __func__, - cgi->wsi, - (unsigned long long)cgi->content_length_seen); + lws_wsi_tag(cgi->wsi), + (unsigned long long)cgi->content_length_seen); /* reap it */ if (waitpid(cgi->lsp->child_pid, &status, WNOHANG) > 0) { diff --git a/lib/roles/dbus/dbus.c b/lib/roles/dbus/dbus.c index 456b869a8..d43fc216e 100644 --- a/lib/roles/dbus/dbus.c +++ b/lib/roles/dbus/dbus.c @@ -178,7 +178,7 @@ lws_dbus_add_watch(DBusWatch *w, void *data) if (flags & DBUS_WATCH_WRITABLE) lws_flags |= LWS_POLLOUT; - lwsl_info("%s: w %p, fd %d, data %p, flags %d\n", __func__, w, + lwsl_info("%s: %p, fd %d, data %p, fl %d\n", __func__, w, dbus_watch_get_unix_fd(w), data, lws_flags); __lws_change_pollfd(wsi, 0, lws_flags); @@ -247,8 +247,9 @@ lws_dbus_remove_watch(DBusWatch *w, void *data) if ((~flags) & DBUS_WATCH_WRITABLE) lws_flags |= LWS_POLLOUT; - lwsl_info("%s: w %p, fd %d, data %p, clearing lws flags %d\n", - __func__, w, dbus_watch_get_unix_fd(w), data, lws_flags); + lwsl_info("%s: %p, fd %d, data %p, clearing lws flags %d\n", + __func__, w, dbus_watch_get_unix_fd(w), + data, lws_flags); __lws_change_pollfd(wsi, lws_flags, 0); diff --git a/lib/roles/h1/ops-h1.c b/lib/roles/h1/ops-h1.c index 1674585ab..01437c42c 100644 --- a/lib/roles/h1/ops-h1.c +++ b/lib/roles/h1/ops-h1.c @@ -232,8 +232,8 @@ postbody_completion: break; } #endif - lwsl_info("HTTP_BODY_COMPLETION: %p (%s)\n", - wsi, wsi->a.protocol->name); + lwsl_info("HTTP_BODY_COMPLETION: %s (%s)\n", + lws_wsi_tag(wsi), wsi->a.protocol->name); n = wsi->a.protocol->callback(wsi, LWS_CALLBACK_HTTP_BODY_COMPLETION, @@ -371,8 +371,8 @@ lws_h1_server_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) lwsi_state(wsi) == LRS_BODY)) { if (!wsi->http.ah && lws_header_table_attach(wsi, 0)) { - lwsl_info("%s: wsi %p: ah not available\n", __func__, - wsi); + lwsl_info("%s: %s: ah not available\n", __func__, + lws_wsi_tag(wsi)); goto try_pollout; } @@ -665,8 +665,8 @@ rops_handle_POLLIN_h1(struct lws_context_per_thread *pt, struct lws *wsi, if (!lwsi_role_client(wsi)) { int n; - lwsl_debug("%s: %p: wsistate 0x%x\n", __func__, wsi, - (int)wsi->wsistate); + lwsl_debug("%s: %s: wsistate 0x%x\n", __func__, lws_wsi_tag(wsi), + (unsigned int)wsi->wsistate); n = lws_h1_server_socket_service(wsi, pollfd); if (n != LWS_HPI_RET_HANDLED) return n; @@ -751,8 +751,8 @@ rops_handle_POLLOUT_h1(struct lws *wsi) memcpy(prebuf + LWS_PRE, buf, len); - lwsl_debug("%s: %p: proxying body %d %d %d %d %d\n", - __func__, wsi, (int)len, + lwsl_debug("%s: %s: proxying body %d %d %d %d %d\n", + __func__, lws_wsi_tag(wsi), (int)len, (int)wsi->http.tx_content_length, (int)wsi->http.tx_content_remain, (int)wsi->http.rx_content_length, @@ -818,8 +818,9 @@ rops_write_role_protocol_h1(struct lws *wsi, unsigned char *buf, size_t len, if (n) return n; - lwsl_info("%s: %p: transformed %d bytes to %d " - "(wp 0x%x, more %d)\n", __func__, wsi, (int)len, + lwsl_info("%s: %s: transformed %d bytes to %d " + "(wp 0x%x, more %d)\n", __func__, + lws_wsi_tag(wsi), (int)len, (int)o, (int)*wp, wsi->http.comp_ctx.may_have_more); if (!o) @@ -897,7 +898,8 @@ rops_destroy_role_h1(struct lws *wsi) while (ah) { if (ah->in_use && ah->wsi == wsi) { - lwsl_err("%s: ah leak: wsi %p\n", __func__, wsi); + lwsl_err("%s: ah leak: wsi %s\n", __func__, + lws_wsi_tag(wsi)); ah->in_use = 0; ah->wsi = NULL; pt->http.ah_count_in_use--; diff --git a/lib/roles/h2/hpack.c b/lib/roles/h2/hpack.c index d147595da..eff8a2745 100644 --- a/lib/roles/h2/hpack.c +++ b/lib/roles/h2/hpack.c @@ -436,8 +436,8 @@ lws_h2_dynamic_table_dump(struct lws *wsi) return 1; dyn = &nwsi->h2.h2n->hpack_dyn_table; - lwsl_header("Dump dyn table for nwsi %p (%d / %d members, pos = %d, " - "start index %d, virt used %d / %d)\n", nwsi, + lwsl_header("Dump dyn table for nwsi %s (%d / %d members, pos = %d, " + "start index %d, virt used %d / %d)\n", lws_wsi_tag(nwsi), dyn->used_entries, dyn->num_entries, dyn->pos, (uint32_t)LWS_ARRAY_SIZE(static_token), dyn->virtual_payload_usage, dyn->virtual_payload_max); diff --git a/lib/roles/h2/http2.c b/lib/roles/h2/http2.c index c244239a8..0364d8494 100644 --- a/lib/roles/h2/http2.c +++ b/lib/roles/h2/http2.c @@ -142,7 +142,7 @@ lws_h2_state(struct lws *wsi, enum lws_h2_states s) { if (!wsi) return; - lwsl_info("%s: wsi %p: state %s -> %s\n", __func__, wsi, + lwsl_info("%s: %s: state %s -> %s\n", __func__, lws_wsi_tag(wsi), h2_state_names[wsi->h2.h2_state], h2_state_names[s]); @@ -241,9 +241,9 @@ lws_wsi_server_new(struct lws_vhost *vh, struct lws *parent_wsi, lwsl_notice("reached concurrent stream limit\n"); return NULL; } - wsi = lws_create_new_server_wsi(vh, parent_wsi->tsi); + wsi = lws_create_new_server_wsi(vh, parent_wsi->tsi, "h2"); if (!wsi) { - lwsl_notice("new server wsi failed (vh %p)\n", vh); + lwsl_notice("new server wsi failed (%s)\n", lws_vh_tag(vh)); return NULL; } @@ -279,8 +279,8 @@ lws_wsi_server_new(struct lws_vhost *vh, struct lws *parent_wsi, /* get the ball rolling */ lws_validity_confirmed(wsi); - lwsl_info("%s: %p new ch %p, sid %d, usersp=%p\n", __func__, - parent_wsi, wsi, sid, wsi->user_space); + lwsl_info("%s: %s new ch %s, sid %d, usersp=%p\n", __func__, + lws_wsi_tag(parent_wsi), lws_wsi_tag(wsi), sid, wsi->user_space); lws_wsi_txc_describe(&wsi->txc, __func__, wsi->mux.my_sid); lws_wsi_txc_describe(&nwsi->txc, __func__, 0); @@ -331,8 +331,8 @@ lws_wsi_h2_adopt(struct lws *parent_wsi, struct lws *wsi) } #endif - lwsl_info("%s: binding wsi %p to sid %d (next %d)\n", __func__, - wsi, (int)wsi->mux.my_sid, (int)nwsi->h2.h2n->highest_sid); + lwsl_info("%s: binding wsi %s to sid %d (next %d)\n", __func__, + lws_wsi_tag(wsi), (int)wsi->mux.my_sid, (int)nwsi->h2.h2n->highest_sid); lws_wsi_mux_insert(wsi, parent_wsi, wsi->mux.my_sid); @@ -376,7 +376,7 @@ lws_h2_issue_preface(struct lws *wsi) struct lws_h2_netconn *h2n = wsi->h2.h2n; struct lws_h2_protocol_send *pps; - lwsl_notice("%s: wsi %p: fd %d\n", __func__, wsi, (int)wsi->desc.sockfd); + lwsl_notice("%s: %s: fd %d\n", __func__, lws_wsi_tag(wsi), (int)wsi->desc.sockfd); if (lws_issue_raw(wsi, (uint8_t *)preface, strlen(preface)) != (int)strlen(preface)) @@ -426,7 +426,7 @@ lws_h2_goaway(struct lws *wsi, uint32_t err, const char *reason) if (!pps) return 1; - lwsl_info("%s: %p: ERR 0x%x, '%s'\n", __func__, wsi, (int)err, reason); + lwsl_info("%s: %s: ERR 0x%x, '%s'\n", __func__, lws_wsi_tag(wsi), (int)err, reason); pps->u.ga.err = err; pps->u.ga.highest_sid = h2n->highest_sid; @@ -606,8 +606,8 @@ lws_h2_tx_cr_get(struct lws *wsi) if (!wsi->mux_substream && !nwsi->upgraded_to_http2) return ~0x80000000; - lwsl_info ("%s: %p: own tx credit %d: nwsi credit %d\n", - __func__, wsi, c, (int)nwsi->txc.tx_cr); + lwsl_info ("%s: %s: own tx credit %d: nwsi credit %d\n", + __func__, lws_wsi_tag(wsi), c, (int)nwsi->txc.tx_cr); if (nwsi->txc.tx_cr < c) c = nwsi->txc.tx_cr; @@ -649,15 +649,16 @@ int lws_h2_frame_write(struct lws *wsi, int type, int flags, *p++ = sid >> 8; *p++ = sid; - lwsl_debug("%s: %p (eff %p). typ %d, fl 0x%x, sid=%d, len=%d, " - "txcr=%d, nwsi->txcr=%d\n", __func__, wsi, nwsi, type, flags, + lwsl_debug("%s: %s (eff %s). typ %d, fl 0x%x, sid=%d, len=%d, " + "txcr=%d, nwsi->txcr=%d\n", __func__, lws_wsi_tag(wsi), + lws_wsi_tag(nwsi), type, flags, sid, len, (int)wsi->txc.tx_cr, (int)nwsi->txc.tx_cr); if (type == LWS_H2_FRAME_TYPE_DATA) { if (wsi->txc.tx_cr < (int)len) - lwsl_info("%s: %p: sending payload len %d" - " but tx_cr only %d!\n", __func__, wsi, - len, (int)wsi->txc.tx_cr); + lwsl_info("%s: %s: sending payload len %d" + " but tx_cr only %d!\n", __func__, + lws_wsi_tag(wsi), len, (int)wsi->txc.tx_cr); lws_h2_tx_cr_consume(wsi, len); } @@ -708,7 +709,7 @@ int lws_h2_do_pps_send(struct lws *wsi) if (!pps) return 1; - lwsl_info("%s: %p: %d\n", __func__, wsi, pps->type); + lwsl_info("%s: %s: %d\n", __func__, lws_wsi_tag(wsi), pps->type); switch (pps->type) { @@ -796,8 +797,9 @@ int lws_h2_do_pps_send(struct lws *wsi) h2n->swsi->http.ah); h2n->swsi->txc.tx_cr = h2n->our_set.s[H2SET_INITIAL_WINDOW_SIZE]; - lwsl_info("initial tx credit on conn %p: %d\n", - h2n->swsi, (int)h2n->swsi->txc.tx_cr); + lwsl_info("initial tx credit on %s: %d\n", + lws_wsi_tag(h2n->swsi), + (int)h2n->swsi->txc.tx_cr); h2n->swsi->h2.initialized = 1; /* demanded by HTTP2 */ h2n->swsi->h2.END_STREAM = 1; @@ -875,9 +877,10 @@ int lws_h2_do_pps_send(struct lws *wsi) } cwsi = lws_wsi_mux_from_id(wsi, pps->u.rs.sid); if (cwsi) { - lwsl_debug("%s: closing cwsi %p %s %s (wsi %p)\n", - __func__, cwsi, cwsi->role_ops->name, - cwsi->a.protocol->name, wsi); + lwsl_debug("%s: closing cwsi %s %s %s (wsi %s)\n", + __func__, lws_wsi_tag(cwsi), + cwsi->role_ops->name, + cwsi->a.protocol->name, lws_wsi_tag(wsi)); lws_close_free_wsi(cwsi, 0, "reset stream"); } break; @@ -953,9 +956,9 @@ lws_h2_parse_frame_header(struct lws *wsi) if (h2n->sid) h2n->swsi = lws_wsi_mux_from_id(wsi, h2n->sid); - lwsl_debug("%p (%p): fr hdr: typ 0x%x, fla 0x%x, sid 0x%x, len 0x%x\n", - wsi, h2n->swsi, h2n->type, h2n->flags, (unsigned int)h2n->sid, - (unsigned int)h2n->length); + lwsl_debug("%s (%s): fr hdr: typ 0x%x, fla 0x%x, sid 0x%x, len 0x%x\n", + lws_wsi_tag(wsi), lws_wsi_tag(h2n->swsi), h2n->type, + h2n->flags, (unsigned int)h2n->sid, (unsigned int)h2n->length); if (h2n->we_told_goaway && h2n->sid > h2n->highest_sid) h2n->type = LWS_H2_FRAME_TYPE_COUNT; /* ie, IGNORE */ @@ -984,8 +987,8 @@ lws_h2_parse_frame_header(struct lws *wsi) } if (h2n->swsi) - lwsl_info("%s: wsi %p, State: %s, received cmd %d\n", - __func__, h2n->swsi, + lwsl_info("%s: %s, State: %s, received cmd %d\n", + __func__, lws_wsi_tag(h2n->swsi), h2_state_names[h2n->swsi->h2.h2_state], h2n->type); else { /* if it's data, either way no swsi means CLOSED state */ @@ -1015,8 +1018,8 @@ lws_h2_parse_frame_header(struct lws *wsi) h2n->type != LWS_H2_FRAME_TYPE_HEADERS && h2n->type != LWS_H2_FRAME_TYPE_PRIORITY) { /* if not credible, reject it */ - lwsl_info("%s: wsi %p, No child for sid %d, rxcmd %d\n", - __func__, h2n->swsi, (unsigned int)h2n->sid, h2n->type); + lwsl_info("%s: %s, No child for sid %d, rxcmd %d\n", + __func__, lws_wsi_tag(h2n->swsi), (unsigned int)h2n->sid, h2n->type); lws_h2_goaway(wsi, H2_ERR_STREAM_CLOSED, "Data for nonexistent sid"); return 0; @@ -1025,8 +1028,8 @@ lws_h2_parse_frame_header(struct lws *wsi) if (h2n->swsi && h2n->sid && h2n->type != LWS_H2_FRAME_TYPE_COUNT && !(http2_rx_validity[h2n->swsi->h2.h2_state] & (1 << h2n->type))) { - lwsl_info("%s: wsi %p, State: %s, ILLEGAL cmdrx %d (OK 0x%x)\n", - __func__, h2n->swsi, + lwsl_info("%s: %s, State: %s, ILLEGAL cmdrx %d (OK 0x%x)\n", + __func__, lws_wsi_tag(h2n->swsi), h2_state_names[h2n->swsi->h2.h2_state], h2n->type, http2_rx_validity[h2n->swsi->h2.h2_state]); @@ -1224,9 +1227,10 @@ lws_h2_parse_frame_header(struct lws *wsi) if (wsi->client_h2_alpn) { if (h2n->sid) { h2n->swsi = lws_wsi_mux_from_id(wsi, h2n->sid); - lwsl_info("HEADERS: nwsi %p: sid %u mapped " - "to wsi %p\n", wsi, - (unsigned int)h2n->sid, h2n->swsi); + lwsl_info("HEADERS: nwsi %s: sid %u mapped " + "to wsi %s\n", lws_wsi_tag(wsi), + (unsigned int)h2n->sid, + lws_wsi_tag(h2n->swsi)); if (!h2n->swsi) break; } @@ -1304,8 +1308,8 @@ lws_h2_parse_frame_header(struct lws *wsi) * poll */ lws_mux_mark_immortal(h2n->swsi); - lwsl_info("%s: %p: h2 stream entering long poll\n", - __func__, h2n->swsi); + lwsl_info("%s: %s: h2 stream entering long poll\n", + __func__, lws_wsi_tag(h2n->swsi)); } else { h2n->swsi->h2.END_STREAM = @@ -1323,7 +1327,7 @@ update_end_headers: /* no END_HEADERS means CONTINUATION must come */ h2n->swsi->h2.END_HEADERS = !!(h2n->flags & LWS_H2_FLAG_END_HEADERS); - lwsl_info("%p: END_HEADERS %d\n", h2n->swsi, + lwsl_info("%s: %s: END_HEADERS %d\n", __func__, lws_wsi_tag(h2n->swsi), h2n->swsi->h2.END_HEADERS); if (h2n->swsi->h2.END_HEADERS) h2n->cont_exp = 0; @@ -1472,12 +1476,13 @@ lws_h2_parse_end_of_frame(struct lws *wsi) h2n->swsi->http.ah->wsi = h2n->swsi; wsi->http.ah = NULL; - lwsl_info("%s: MIGRATING nwsi %p: swsi %p\n", __func__, - wsi, h2n->swsi); + lwsl_info("%s: MIGRATING nwsi %s -> swsi %s\n", __func__, + lws_wsi_tag(wsi), lws_wsi_tag(h2n->swsi)); h2n->swsi->txc.tx_cr = h2n->peer_set.s[H2SET_INITIAL_WINDOW_SIZE]; - lwsl_info("%s: initial tx credit on conn %p: %d\n", - __func__, h2n->swsi, (int)h2n->swsi->txc.tx_cr); + lwsl_info("%s: initial tx credit on %s: %d\n", + __func__, lws_wsi_tag(h2n->swsi), + (int)h2n->swsi->txc.tx_cr); h2n->swsi->h2.initialized = 1; /* set our initial window size */ @@ -1486,8 +1491,8 @@ lws_h2_parse_end_of_frame(struct lws *wsi) h2n->peer_set.s[H2SET_INITIAL_WINDOW_SIZE]; lwsl_info("%s: initial tx credit for us to " - "write on nwsi %p: %d\n", __func__, - wsi, (int)wsi->txc.tx_cr); + "write on nwsi %s: %d\n", __func__, + lws_wsi_tag(wsi), (int)wsi->txc.tx_cr); wsi->h2.initialized = 1; } @@ -1555,7 +1560,8 @@ lws_h2_parse_end_of_frame(struct lws *wsi) break; } - lwsl_info("http req, wsi=%p, h2n->swsi=%p\n", wsi, h2n->swsi); + lwsl_info("http req, %s, h2n->swsi=%s\n", lws_wsi_tag(wsi), + lws_wsi_tag(h2n->swsi)); h2n->swsi->hdr_parsing_completed = 1; #if defined(LWS_WITH_CLIENT) @@ -1635,8 +1641,9 @@ lws_h2_parse_end_of_frame(struct lws *wsi) #if defined(LWS_WITH_CLIENT) if (h2n->swsi->client_mux_substream) { - lwsl_info("%s: wsi %p: headers: client path (h2 state %s)\n", - __func__, wsi, h2_state_names[h2n->swsi->h2.h2_state]); + lwsl_info("%s: %s: headers: client path (h2 state %s)\n", + __func__, lws_wsi_tag(wsi), + h2_state_names[h2n->swsi->h2.h2_state]); break; } #endif @@ -1722,8 +1729,8 @@ lws_h2_parse_end_of_frame(struct lws *wsi) if (h2n->swsi->client_mux_substream && (h2n->flags & LWS_H2_FLAG_END_STREAM)) { - lwsl_info("%s: %p: DATA: end stream\n", - __func__, h2n->swsi); + lwsl_info("%s: %s: DATA: end stream\n", + __func__, lws_wsi_tag(h2n->swsi)); if (h2n->swsi->h2.h2_state == LWS_H2_STATE_OPEN) { lws_h2_state(h2n->swsi, @@ -1903,7 +1910,7 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t _inlen, if (preface[h2n->count]) break; - lwsl_info("http2: %p: established\n", wsi); + lwsl_info("http2: %s: established\n", lws_wsi_tag(wsi)); lwsi_set_state(wsi, LRS_H2_AWAIT_SETTINGS); lws_validity_confirmed(wsi); h2n->count = 0; @@ -2064,8 +2071,8 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t _inlen, if (lwsi_role_http(h2n->swsi) && lwsi_state(h2n->swsi) == LRS_ESTABLISHED) { lwsi_set_state(h2n->swsi, LRS_BODY); - lwsl_info("%s: swsi %p to LRS_BODY\n", - __func__, h2n->swsi); + lwsl_info("%s: %s to LRS_BODY\n", + __func__, lws_wsi_tag(h2n->swsi)); } if (lws_hdr_total_length(h2n->swsi, @@ -2096,8 +2103,8 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t _inlen, #if defined(LWS_WITH_CLIENT) if (h2n->swsi->client_mux_substream) { if (!h2n->swsi->a.protocol) { - lwsl_err("%s: swsi %p doesn't have protocol\n", - __func__, h2n->swsi); + lwsl_err("%s: %p doesn't have protocol\n", + __func__, lws_wsi_tag(h2n->swsi)); m = 1; } else { h2n->swsi->txc.peer_tx_cr_est -= n; @@ -2136,8 +2143,8 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t _inlen, struct lws_context_per_thread *pt; pt = &wsi->a.context->pt[(int)wsi->tsi]; - lwsl_debug("%s: added %p to rxflow list\n", - __func__, wsi); + lwsl_debug("%s: added %s to rxflow list\n", + __func__, lws_wsi_tag(wsi)); lws_dll2_add_head( &h2n->swsi->dll_buflist, &pt->dll_buflist_owner); @@ -2396,7 +2403,8 @@ lws_h2_client_handshake(struct lws *wsi) */ wsi->mux.my_sid = nwsi->h2.h2n->highest_sid_opened = sid; - lwsl_info("%s: wsi %p: assigning SID %d at header send\n", __func__, wsi, sid); + lwsl_info("%s: %s: assigning SID %d at header send\n", __func__, + lws_wsi_tag(wsi), sid); lwsl_info("%s: CLIENT_WAITING_TO_SEND_HEADERS: pollout (sid %d)\n", @@ -2574,8 +2582,8 @@ lws_h2_ws_handshake(struct lws *wsi) lws_ss_handle_t *h = (lws_ss_handle_t *)wsi->a.opaque_user_data; - lwsl_notice("%s: Server SS %p .wsi %p switching to ws protocol\n", - __func__, h, h->wsi); + lwsl_notice("%s: Server SS %s .wsi %s switching to ws protocol\n", + __func__, lws_ss_tag(h), lws_wsi_tag(h->wsi)); wsi->a.protocol = &protocol_secstream_ws; diff --git a/lib/roles/h2/ops-h2.c b/lib/roles/h2/ops-h2.c index 264ec4b65..42ed9f5cd 100644 --- a/lib/roles/h2/ops-h2.c +++ b/lib/roles/h2/ops-h2.c @@ -280,8 +280,8 @@ drain: lwsl_info("%s: draining rxflow: used %d, next %d\n", __func__, n, m); if (!m) { - lwsl_notice("%s: removed %p from dll_buflist\n", - __func__, wsi); + lwsl_notice("%s: removed %s from dll_buflist\n", + __func__, lws_wsi_tag(wsi)); lws_dll2_remove(&wsi->dll_buflist); } } else @@ -293,8 +293,8 @@ drain: if (m < 0) return LWS_HPI_RET_PLEASE_CLOSE_ME; if (m) { - lwsl_debug("%s: added %p to rxflow list\n", - __func__, wsi); + lwsl_debug("%s: added %s to rxflow list\n", + __func__, lws_wsi_tag(wsi)); if (lws_dll2_is_detached(&wsi->dll_buflist)) lws_dll2_add_head(&wsi->dll_buflist, &pt->dll_buflist_owner); @@ -420,9 +420,9 @@ rops_write_role_protocol_h2(struct lws *wsi, unsigned char *buf, size_t len, if (n) return n; - lwsl_info("%s: %p: transformed %d bytes to %d " + lwsl_info("%s: %s: transformed %d bytes to %d " "(wp 0x%x, more %d)\n", __func__, - wsi, (int)len, (int)o, (int)*wp, + lws_wsi_tag(wsi), (int)len, (int)o, (int)*wp, wsi->http.comp_ctx.may_have_more); buf = out; @@ -465,7 +465,8 @@ rops_write_role_protocol_h2(struct lws *wsi, unsigned char *buf, size_t len, base == LWS_WRITE_HTTP_FINAL) && wsi->http.tx_content_length) { wsi->http.tx_content_remain -= len; - lwsl_info("%s: wsi %p: tx_content_rem = %llu\n", __func__, wsi, + lwsl_info("%s: %s: tx_content_rem = %llu\n", __func__, + lws_wsi_tag(wsi), (unsigned long long)wsi->http.tx_content_remain); if (!wsi->http.tx_content_remain) { lwsl_info("%s: selecting final write mode\n", __func__); @@ -474,7 +475,8 @@ rops_write_role_protocol_h2(struct lws *wsi, unsigned char *buf, size_t len, } if (base == LWS_WRITE_HTTP_FINAL || ((*wp) & LWS_WRITE_H2_STREAM_END)) { - lwsl_info("%s: %p: setting END_STREAM\n", __func__, wsi); + lwsl_info("%s: %s: setting END_STREAM\n", __func__, + lws_wsi_tag(wsi)); flags |= LWS_H2_FLAG_END_STREAM; wsi->h2.send_END_STREAM = 1; } @@ -613,14 +615,14 @@ rops_destroy_role_h2(struct lws *wsi) struct allocated_headers *ah; /* we may not have an ah, but may be on the waiting list... */ - lwsl_info("%s: wsi %p: ah det due to close\n", __func__, wsi); + lwsl_info("%s: %s: ah det due to close\n", __func__, lws_wsi_tag(wsi)); __lws_header_table_detach(wsi, 0); ah = pt->http.ah_list; while (ah) { if (ah->in_use && ah->wsi == wsi) { - lwsl_err("%s: ah leak: wsi %p\n", __func__, wsi); + lwsl_err("%s: ah leak: %s\n", __func__, lws_wsi_tag(wsi)); ah->in_use = 0; ah->wsi = NULL; pt->http.ah_count_in_use--; @@ -667,7 +669,7 @@ rops_close_kill_connection_h2(struct lws *wsi, enum lws_close_status reason) lws_h2_rst_stream(wsi, H2_ERR_STREAM_CLOSED, "swsi got closed"); */ - lwsl_info(" wsi: %p, his parent %p: siblings:\n", wsi, wsi->mux.parent_wsi); + lwsl_info(" %s, his parent %s: siblings:\n", lws_wsi_tag(wsi), lws_wsi_tag(wsi->mux.parent_wsi)); lws_wsi_mux_dump_children(wsi); if (wsi->upgraded_to_http2 || wsi->mux_substream @@ -675,10 +677,11 @@ rops_close_kill_connection_h2(struct lws *wsi, enum lws_close_status reason) || wsi->client_mux_substream #endif ) { - lwsl_info("closing %p: parent %p\n", wsi, wsi->mux.parent_wsi); + lwsl_info("closing %s: parent %s\n", lws_wsi_tag(wsi), + lws_wsi_tag(wsi->mux.parent_wsi)); if (wsi->mux.child_list && lwsl_visible(LLL_INFO)) { - lwsl_info(" parent %p: closing children: list:\n", wsi); + lwsl_info(" parent %s: closing children: list:\n", lws_wsi_tag(wsi)); lws_wsi_mux_dump_children(wsi); } lws_wsi_mux_close_children(wsi, reason); @@ -862,7 +865,7 @@ rops_perform_user_POLLOUT_h2(struct lws *wsi) * move him to be the last child */ - lwsl_debug("servicing child %p\n", *wsi2); + lwsl_debug("servicing child %s\n", lws_wsi_tag(*wsi2)); w = lws_wsi_mux_move_child_to_tail(wsi2); @@ -871,8 +874,9 @@ rops_perform_user_POLLOUT_h2(struct lws *wsi) goto next_child; } - lwsl_info("%s: child wsi %p, sid %d, (wsistate 0x%x)\n", - __func__, w, w->mux.my_sid, (unsigned int)w->wsistate); + lwsl_info("%s: child %s, sid %d, (wsistate 0x%x)\n", + __func__, lws_wsi_tag(w), w->mux.my_sid, + (unsigned int)w->wsistate); /* priority 1: post compression-transform buffered output */ @@ -1030,7 +1034,8 @@ rops_perform_user_POLLOUT_h2(struct lws *wsi) * DATA here... if so close the actual wsi */ if (n < 0 || w->h2.send_END_STREAM) { - lwsl_debug("Closing POLLOUT child %p\n", w); + lwsl_debug("Closing POLLOUT child %s\n", + lws_wsi_tag(w)); lws_close_free_wsi(w, LWS_CLOSE_STATUS_NOSTATUS, "h2 end stream file"); wa = &wsi->mux.child_list; @@ -1122,12 +1127,12 @@ rops_perform_user_POLLOUT_h2(struct lws *wsi) if (!rops_write_role_protocol_h2(w, buf + LWS_PRE, 0, &wp)) { - lwsl_info("%s: wsi %p: entering ro long poll\n", - __func__, w); + lwsl_info("%s: %s: entering ro long poll\n", + __func__, lws_wsi_tag(w)); lws_mux_mark_immortal(w); } else - lwsl_err("%s: wsi %p: failed to set long poll\n", - __func__, w); + lwsl_err("%s: %s: failed to set long poll\n", + __func__, lws_wsi_tag(w)); goto next_child; } @@ -1203,7 +1208,7 @@ rops_alpn_negotiated_h2(struct lws *wsi, const char *alpn) wsi->h2.h2n->our_set.s[H2SET_HEADER_TABLE_SIZE]); wsi->txc.tx_cr = 65535; - lwsl_info("%s: wsi %p: configured for h2\n", __func__, wsi); + lwsl_info("%s: %s: configured for h2\n", __func__, lws_wsi_tag(wsi)); return 0; } diff --git a/lib/roles/http/client/client-http.c b/lib/roles/http/client/client-http.c index 50a3ad212..b315de7d6 100644 --- a/lib/roles/http/client/client-http.c +++ b/lib/roles/http/client/client-http.c @@ -50,7 +50,7 @@ lws_http_client_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) * we are under PENDING_TIMEOUT_SENT_CLIENT_HANDSHAKE * timeout protection set in client-handshake.c */ - lwsl_err("%s: wsi %p: WAITING_DNS\n", __func__, wsi); + lwsl_err("%s: %s: WAITING_DNS\n", __func__, lws_wsi_tag(wsi)); if (!lws_client_connect_2_dnsreq(wsi)) { /* closed */ lwsl_client("closed\n"); @@ -97,8 +97,8 @@ lws_http_client_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) if (pollfd->revents & LWS_POLLHUP) { - lwsl_warn("Proxy connection %p (fd=%d) dead\n", - (void *)wsi, pollfd->fd); + lwsl_warn("Proxy conn %s (fd=%d) dead\n", + lws_wsi_tag(wsi), pollfd->fd); cce = "proxy conn dead"; goto bail3; @@ -137,7 +137,7 @@ lws_http_client_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) case LRS_H1C_ISSUE_HANDSHAKE: - lwsl_notice("%s: LRS_H1C_ISSUE_HANDSHAKE\n", __func__); + lwsl_debug("%s: LRS_H1C_ISSUE_HANDSHAKE\n", __func__); /* * we are under PENDING_TIMEOUT_SENT_CLIENT_HANDSHAKE @@ -267,10 +267,10 @@ hs2: /* send our request to the server */ - lwsl_info("%s: HANDSHAKE2: %p: sending headers " + lwsl_info("%s: HANDSHAKE2: %s: sending headers " "(wsistate 0x%lx), w sock %d\n", - __func__, wsi, (unsigned long)wsi->wsistate, - wsi->desc.sockfd); + __func__, lws_wsi_tag(wsi), + (unsigned long)wsi->wsistate, wsi->desc.sockfd); #if defined(LWS_WITH_DETAILED_LATENCY) wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); #endif @@ -359,8 +359,8 @@ client_http_body_sent: if ((pollfd->revents & (LWS_POLLIN | LWS_POLLHUP)) == LWS_POLLHUP) { - lwsl_debug("Server connection %p (fd=%d) dead\n", - (void *)wsi, pollfd->fd); + lwsl_debug("Server conn %s (fd=%d) dead\n", + lws_wsi_tag(wsi), pollfd->fd); cce = "Peer hung up"; goto bail3; } @@ -452,8 +452,8 @@ client_http_body_sent: return lws_client_interpret_server_handshake(wsi); bail3: - lwsl_info("%s: closing conn at LWS_CONNMODE...SERVER_REPLY, wsi %p, state 0x%x\n", - __func__, wsi, lwsi_state(wsi)); + lwsl_info("%s: closing conn at LWS_CONNMODE...SERVER_REPLY, %s, state 0x%x\n", + __func__, lws_wsi_tag(wsi), lwsi_state(wsi)); if (cce) lwsl_info("reason: %s\n", cce); else @@ -478,7 +478,8 @@ lws_http_transaction_completed_client(struct lws *wsi) struct lws_context_per_thread *pt = &wsi->a.context->pt[(int)wsi->tsi]; int n; - lwsl_info("%s: wsi: %p (%s)\n", __func__, wsi, wsi->a.protocol->name); + lwsl_info("%s: %s (%s)\n", __func__, lws_wsi_tag(wsi), + wsi->a.protocol->name); if (user_callback_handle_rxflow(wsi->a.protocol->callback, wsi, LWS_CALLBACK_COMPLETED_CLIENT_HTTP, @@ -533,7 +534,7 @@ lws_http_transaction_completed_client(struct lws *wsi) wsi->http.ah->ues = URIES_IDLE; lwsi_set_state(wsi, LRS_H1C_ISSUE_HANDSHAKE2); - lwsl_info("%s: %p: new queued transaction\n", __func__, wsi); + lwsl_info("%s: %s: new queued transaction\n", __func__, lws_wsi_tag(wsi)); lws_callback_on_writable(wsi); return 0; @@ -576,8 +577,8 @@ lws_client_interpret_server_handshake(struct lws *wsi) */ #if defined(LWS_ROLE_H2) if (wsi->client_h2_alpn || wsi->client_mux_substream) { - lwsl_debug("%s: %p: transitioning to h2 client\n", - __func__, wsi); + lwsl_debug("%s: %s: transitioning to h2 client\n", + __func__, lws_wsi_tag(wsi)); lws_role_transition(wsi, LWSIFR_CLIENT, LRS_ESTABLISHED, &role_ops_h2); } else @@ -585,8 +586,8 @@ lws_client_interpret_server_handshake(struct lws *wsi) { #if defined(LWS_ROLE_H1) { - lwsl_debug("%s: %p: transitioning to h1 client\n", - __func__, wsi); + lwsl_debug("%s: %s: transitioning to h1 client\n", + __func__, lws_wsi_tag(wsi)); lws_role_transition(wsi, LWSIFR_CLIENT, LRS_ESTABLISHED, &role_ops_h1); } @@ -924,7 +925,7 @@ lws_client_interpret_server_handshake(struct lws *wsi) wsi->http.ah = ah1; - lwsl_info("%s: wsi %p: client connection up\n", __func__, wsi); + lwsl_info("%s: %s: client conn up\n", __func__, lws_wsi_tag(wsi)); /* * Did we get a response from the server with an explicit @@ -1509,8 +1510,8 @@ lws_client_reset(struct lws **pwsi, int ssl, const char *address, int port, wsi = *pwsi; - lwsl_debug("%s: wsi %p: redir %d: %s\n", __func__, wsi, wsi->redirects, - address); + lwsl_debug("%s: %s: redir %d: %s\n", __func__, lws_wsi_tag(wsi), + wsi->redirects, address); if (wsi->redirects == 3) { lwsl_err("%s: Too many redirects\n", __func__); diff --git a/lib/roles/http/compression/stream.c b/lib/roles/http/compression/stream.c index d6dc20d20..824bca712 100644 --- a/lib/roles/http/compression/stream.c +++ b/lib/roles/http/compression/stream.c @@ -98,8 +98,8 @@ lws_http_compression_apply(struct lws *wsi, const char *name, strlen(lcs_available[n]->encoding_name), p, end)) return -1; - lwsl_info("%s: wsi %p: applied %s content-encoding\n", __func__, - wsi, lcs_available[n]->encoding_name); + lwsl_info("%s: %s: applied %s content-encoding\n", __func__, + lws_wsi_tag(wsi), lcs_available[n]->encoding_name); return 0; } @@ -164,22 +164,22 @@ lws_http_compression_transform(struct lws *wsi, unsigned char *buf, if (lws_buflist_append_segment( &ctx->buflist_comp, buf, len) < 0) return -1; - lwsl_debug("%s: %p: adding %d to comp buflist\n", - __func__,wsi, (int)len); + lwsl_debug("%s: %s: adding %d to comp buflist\n", + __func__, lws_wsi_tag(wsi), (int)len); } len = lws_buflist_next_segment_len(&ctx->buflist_comp, &buf); ilen_iused = len; use = 1; - lwsl_debug("%s: %p: trying comp buflist %d\n", __func__, wsi, - (int)len); + lwsl_debug("%s: %s: trying comp buflist %d\n", __func__, + lws_wsi_tag(wsi), (int)len); } if (!buf && ilen_iused) return 0; - lwsl_debug("%s: %p: pre-process: ilen_iused %d, olen_oused %d\n", - __func__, wsi, (int)ilen_iused, (int)*olen_oused); + lwsl_debug("%s: %s: pre-process: ilen_iused %d, olen_oused %d\n", + __func__, lws_wsi_tag(wsi), (int)ilen_iused, (int)*olen_oused); n = wsi->http.lcs->process(ctx, buf, &ilen_iused, *outbuf, olen_oused); @@ -192,7 +192,7 @@ lws_http_compression_transform(struct lws *wsi, unsigned char *buf, if (!ctx->may_have_more && ctx->final_on_input_side) *wp = LWS_WRITE_HTTP_FINAL | ((*wp) & ~0x1f); - lwsl_debug("%s: %p: more %d, ilen_iused %d\n", __func__, wsi, + lwsl_debug("%s: %s: more %d, ilen_iused %d\n", __func__, lws_wsi_tag(wsi), ctx->may_have_more, (int)ilen_iused); if (use && ilen_iused) { @@ -202,9 +202,9 @@ lws_http_compression_transform(struct lws *wsi, unsigned char *buf, * transform */ lws_buflist_use_segment(&ctx->buflist_comp, ilen_iused); - lwsl_debug("%s: %p: marking %d of comp buflist as used " - "(ctx->buflist_comp %p)\n", __func__, wsi, - (int)len, ctx->buflist_comp); + lwsl_debug("%s: %s: marking %d of comp buflist as used " + "(ctx->buflist_comp %p)\n", __func__, + lws_wsi_tag(wsi), (int)len, ctx->buflist_comp); } if (!use && ilen_iused != len) { diff --git a/lib/roles/http/header.c b/lib/roles/http/header.c index 2eed54ff7..1d55abcc3 100644 --- a/lib/roles/http/header.c +++ b/lib/roles/http/header.c @@ -153,8 +153,8 @@ lws_add_http_header_content_length(struct lws *wsi, wsi->http.tx_content_length = content_length; wsi->http.tx_content_remain = content_length; - lwsl_info("%s: wsi %p: tx_content_length/remain %llu\n", __func__, - wsi, (unsigned long long)content_length); + lwsl_info("%s: %s: tx_content_length/remain %llu\n", __func__, + lws_wsi_tag(wsi), (unsigned long long)content_length); return 0; } @@ -607,10 +607,10 @@ lws_sul_http_ah_lifecheck(lws_sorted_usec_list_t *sul) #else buf[0] = '\0'; #endif - lwsl_notice("ah excessive hold: wsi %p\n" + lwsl_notice("%s: ah excessive hold: wsi %p\n" " peer address: %s\n" - " ah pos %lu\n", - wsi, buf, (unsigned long)ah->pos); + " ah pos %lu\n", __func__, lws_wsi_tag(wsi), + buf, (unsigned long)ah->pos); buf[0] = '\0'; m = 0; do { diff --git a/lib/roles/http/parsers.c b/lib/roles/http/parsers.c index 3282ea5ff..ecf2f373a 100644 --- a/lib/roles/http/parsers.c +++ b/lib/roles/http/parsers.c @@ -170,7 +170,7 @@ _lws_header_ensure_we_are_on_waiting_list(struct lws *wsi) pwsi = &(*pwsi)->http.ah_wait_list; } - lwsl_info("%s: wsi: %p\n", __func__, wsi); + lwsl_info("%s: wsi: %s\n", __func__, lws_wsi_tag(wsi)); wsi->http.ah_wait_list = pt->http.ah_wait_list; pt->http.ah_wait_list = wsi; pt->http.ah_wait_list_length++; @@ -188,7 +188,7 @@ __lws_remove_from_ah_waiting_list(struct lws *wsi) while (*pwsi) { if (*pwsi == wsi) { - lwsl_info("%s: wsi %p\n", __func__, wsi); + lwsl_info("%s: wsi %s\n", __func__, lws_wsi_tag(wsi)); /* point prev guy to our next */ *pwsi = wsi->http.ah_wait_list; /* we shouldn't point anywhere now */ @@ -216,8 +216,8 @@ lws_header_table_attach(struct lws *wsi, int autoservice) goto connect_via_info2; #endif - lwsl_info("%s: wsi %p: ah %p (tsi %d, count = %d) in\n", __func__, - (void *)wsi, (void *)wsi->http.ah, wsi->tsi, + lwsl_info("%s: %s: ah %p (tsi %d, count = %d) in\n", __func__, + lws_wsi_tag(wsi), (void *)wsi->http.ah, wsi->tsi, pt->http.ah_count_in_use); if (!lwsi_role_http(wsi)) { @@ -278,8 +278,8 @@ lws_header_table_attach(struct lws *wsi, int autoservice) _lws_change_pollfd(wsi, 0, LWS_POLLIN, &pa); - lwsl_info("%s: did attach wsi %p: ah %p: count %d (on exit)\n", __func__, - (void *)wsi, (void *)wsi->http.ah, pt->http.ah_count_in_use); + lwsl_info("%s: did attach wsi %s: ah %p: count %d (on exit)\n", __func__, + lws_wsi_tag(wsi), (void *)wsi->http.ah, pt->http.ah_count_in_use); reset: __lws_header_table_reset(wsi, autoservice); @@ -320,8 +320,8 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) if (!ah) return 0; - lwsl_info("%s: wsi %p: ah %p (tsi=%d, count = %d)\n", __func__, - (void *)wsi, (void *)ah, wsi->tsi, + lwsl_info("%s: %s: ah %p (tsi=%d, count = %d)\n", __func__, + lws_wsi_tag(wsi), (void *)ah, wsi->tsi, pt->http.ah_count_in_use); /* we did have an ah attached */ @@ -331,8 +331,9 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) * we're detaching the ah, but it was held an * unreasonably long time */ - lwsl_debug("%s: wsi %p: ah held %ds, role/state 0x%lx 0x%x," - "\n", __func__, wsi, (int)(now - ah->assigned), + lwsl_debug("%s: %s: ah held %ds, role/state 0x%lx 0x%x," + "\n", __func__, lws_wsi_tag(wsi), + (int)(now - ah->assigned), (unsigned long)lwsi_role(wsi), lwsi_state(wsi)); } @@ -361,7 +362,7 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) * at least one wsi on the same tsi is waiting, give it to oldest guy * who is allowed to take it (if any) */ - lwsl_info("pt wait list %p\n", *pwsi); + lwsl_info("%s: pt wait list %s\n", __func__, lws_wsi_tag(*pwsi)); wsi = NULL; pwsi_eligible = NULL; @@ -387,7 +388,7 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) goto nobody_usable_waiting; lwsl_info("%s: transferring ah to last eligible wsi in wait list " - "%p (wsistate 0x%lx)\n", __func__, wsi, + "%s (wsistate 0x%lx)\n", __func__, lws_wsi_tag(wsi), (unsigned long)wsi->wsistate); wsi->http.ah = ah; @@ -404,7 +405,7 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) /* clients acquire the ah and then insert themselves in fds table... */ if (wsi->position_in_fds_table != LWS_NO_FDS_POS) { - lwsl_info("%s: Enabling %p POLLIN\n", __func__, wsi); + lwsl_info("%s: Enabling %s POLLIN\n", __func__, lws_wsi_tag(wsi)); /* he has been stuck waiting for an ah, but now his wait is * over, let him progress */ @@ -436,8 +437,8 @@ int __lws_header_table_detach(struct lws *wsi, int autoservice) assert(!!pt->http.ah_wait_list_length == !!(lws_intptr_t)pt->http.ah_wait_list); bail: - lwsl_info("%s: wsi %p: ah %p (tsi=%d, count = %d)\n", __func__, - (void *)wsi, (void *)ah, pt->tid, pt->http.ah_count_in_use); + lwsl_info("%s: %s: ah %p (tsi=%d, count = %d)\n", __func__, + lws_wsi_tag(wsi), (void *)ah, pt->tid, pt->http.ah_count_in_use); return 0; diff --git a/lib/roles/http/server/server.c b/lib/roles/http/server/server.c index 2dbec559a..edd0d3dae 100644 --- a/lib/roles/http/server/server.c +++ b/lib/roles/http/server/server.c @@ -322,6 +322,13 @@ done_list: __remove_wsi_socket_from_fds(wsi); goto bail; } + + if (wsi) + __lws_lc_tag(&vhost->context->lcg[LWSLCG_WSI], + &wsi->lc, "listen|%s|%s|%d", vhost->name, + vhost->iface ? vhost->iface : "", + (int)vhost->listen_port); + } /* for each thread able to independently listen */ if (!lws_check_opt(vhost->context->options, @@ -1271,8 +1278,8 @@ lws_http_proxy_start(struct lws *wsi, const struct lws_http_mount *hit, return 1; } - lwsl_info("%s: setting proxy clientside on %p (parent %p)\n", - __func__, cwsi, lws_get_parent(cwsi)); + lwsl_info("%s: setting proxy clientside on %s (parent %s)\n", + __func__, lws_wsi_tag(cwsi), lws_wsi_tag(lws_get_parent(cwsi))); cwsi->http.proxy_clientside = 1; if (ws) { @@ -1813,8 +1820,8 @@ deal_body: if (lwsi_state(wsi) != LRS_DISCARD_BODY) { lwsi_set_state(wsi, LRS_BODY); - lwsl_info("%s: %p: LRS_BODY state set (0x%x)\n", __func__, wsi, - (int)wsi->wsistate); + lwsl_info("%s: %s: LRS_BODY state set (0x%x)\n", __func__, + lws_wsi_tag(wsi), (int)wsi->wsistate); } wsi->http.rx_content_remain = wsi->http.rx_content_length; @@ -2223,7 +2230,7 @@ raw_transition: /* no upgrade ack... he remained as HTTP */ - lwsl_info("%s: %p: No upgrade\n", __func__, wsi); + lwsl_info("%s: %s: No upgrade\n", __func__, lws_wsi_tag(wsi)); lwsi_set_state(wsi, LRS_ESTABLISHED); #if defined(LWS_WITH_FILE_OPS) @@ -2234,7 +2241,7 @@ raw_transition: lws_http_compression_validate(wsi); #endif - lwsl_debug("%s: wsi %p: ah %p\n", __func__, (void *)wsi, + lwsl_debug("%s: %s: ah %p\n", __func__, lws_wsi_tag(wsi), (void *)wsi->http.ah); n = lws_http_action(wsi); @@ -2337,7 +2344,8 @@ lws_http_transaction_completed(struct lws *wsi) * Defer the transaction completed until the last part of the * partial is sent. */ - lwsl_debug("%s: %p: deferring due to partial\n", __func__, wsi); + lwsl_debug("%s: %s: deferring due to partial\n", __func__, + lws_wsi_tag(wsi)); wsi->http.deferred_transaction_completed = 1; lws_callback_on_writable(wsi); @@ -2366,7 +2374,7 @@ lws_http_transaction_completed(struct lws *wsi) return 0; } - lwsl_info("%s: wsi %p\n", __func__, wsi); + lwsl_info("%s: %s\n", __func__, lws_wsi_tag(wsi)); #if defined(LWS_WITH_HTTP_STREAM_COMPRESSION) lws_http_compression_destroy(wsi); @@ -2412,7 +2420,7 @@ lws_http_transaction_completed(struct lws *wsi) return 1; if (wsi->http.conn_type != HTTP_CONNECTION_KEEP_ALIVE) { - lwsl_info("%s: %p: close connection\n", __func__, wsi); + lwsl_info("%s: %s: close connection\n", __func__, lws_wsi_tag(wsi)); return 1; } @@ -2425,8 +2433,8 @@ lws_http_transaction_completed(struct lws *wsi) * until we can verify POLLOUT. The part of this that confirms POLLOUT * with no partials is in lws_server_socket_service() below. */ - lwsl_debug("%s: %p: setting DEF_ACT from 0x%x: %p\n", __func__, - wsi, (int)wsi->wsistate, wsi->buflist); + lwsl_debug("%s: %s: setting DEF_ACT from 0x%x: %p\n", __func__, + lws_wsi_tag(wsi), (int)wsi->wsistate, wsi->buflist); lwsi_set_state(wsi, LRS_DEFERRING_ACTION); wsi->http.tx_content_length = 0; wsi->http.tx_content_remain = 0; @@ -2461,8 +2469,8 @@ lws_http_transaction_completed(struct lws *wsi) if (wsi->http.ah) { // lws_buflist_describe(&wsi->buflist, wsi, __func__); if (!lws_buflist_next_segment_len(&wsi->buflist, NULL)) { - lwsl_debug("%s: %p: nothing in buflist, detaching ah\n", - __func__, wsi); + lwsl_debug("%s: %s: nothing in buflist, detaching ah\n", + __func__, lws_wsi_tag(wsi)); lws_header_table_detach(wsi, 1); #ifdef LWS_WITH_TLS /* @@ -2481,8 +2489,8 @@ lws_http_transaction_completed(struct lws *wsi) } #endif } else { - lwsl_info("%s: %p: resetting/keeping ah as pipeline\n", - __func__, wsi); + lwsl_info("%s: %s: resetting/keeping ah as pipeline\n", + __func__, lws_wsi_tag(wsi)); lws_header_table_reset(wsi, 0); /* * If we kept the ah, we should restrict the amount @@ -2503,8 +2511,8 @@ lws_http_transaction_completed(struct lws *wsi) if (lws_header_table_attach(wsi, 0)) lwsl_debug("acquired ah\n"); - lwsl_debug("%s: %p: keep-alive await new transaction (state 0x%x)\n", - __func__, wsi, (int)wsi->wsistate); + lwsl_debug("%s: %s: keep-alive await new transaction (state 0x%x)\n", + __func__, lws_wsi_tag(wsi), (int)wsi->wsistate); lws_callback_on_writable(wsi); return 0; @@ -2929,8 +2937,8 @@ int lws_serve_http_file_fragment(struct lws *wsi) * We shouldn't've been able to get the * WRITEABLE if we are skint */ - lwsl_notice("%s: %p: no tx credit\n", __func__, - wsi); + lwsl_notice("%s: %s: no tx credit\n", __func__, + lws_wsi_tag(wsi)); return 0; } diff --git a/lib/roles/listen/ops-listen.c b/lib/roles/listen/ops-listen.c index 37c55ea74..e8fdbe77b 100644 --- a/lib/roles/listen/ops-listen.c +++ b/lib/roles/listen/ops-listen.c @@ -160,8 +160,8 @@ rops_handle_POLLIN_listen(struct lws_context_per_thread *pt, struct lws *wsi, return LWS_HPI_RET_WSI_ALREADY_DIED; } - lwsl_info("%s: new wsi %p: wsistate 0x%lx, role_ops %s\n", - __func__, cwsi, (unsigned long)cwsi->wsistate, + lwsl_info("%s: new %s: wsistate 0x%lx, role_ops %s\n", + __func__, lws_wsi_tag(cwsi), (unsigned long)cwsi->wsistate, cwsi->role_ops->name); */ diff --git a/lib/roles/mqtt/client/client-mqtt.c b/lib/roles/mqtt/client/client-mqtt.c index d50a99826..902ad6f9e 100644 --- a/lib/roles/mqtt/client/client-mqtt.c +++ b/lib/roles/mqtt/client/client-mqtt.c @@ -290,8 +290,8 @@ start_ws_handshake: /* * we should be ready to send out MQTT CONNECT */ - lwsl_info("%s: wsi %p: Transport established, send out CONNECT\n", - __func__, wsi); + lwsl_info("%s: %s: Transport established, send out CONNECT\n", + __func__, lws_wsi_tag(wsi)); if (lws_change_pollfd(wsi, LWS_POLLOUT, 0)) return -1; if (!lws_mqtt_client_send_connect(wsi)) { diff --git a/lib/roles/mqtt/mqtt.c b/lib/roles/mqtt/mqtt.c index 0abca906e..c6ef724ad 100644 --- a/lib/roles/mqtt/mqtt.c +++ b/lib/roles/mqtt/mqtt.c @@ -383,8 +383,9 @@ _lws_mqtt_rx_parser(struct lws *wsi, lws_mqtt_parser_t *par, */ if ((n & LMQCP_LUT_FLAG_RESERVED_FLAGS) && ((par->packet_type_flags & 0x0f) != (n & 0x0f))) { - lwsl_notice("%s: wsi %p: bad flags, 0x%02x mask 0x%02x (len %d)\n", - __func__, wsi, par->packet_type_flags, n, (int)len + 1); + lwsl_notice("%s: %s: bad flags, 0x%02x mask 0x%02x (len %d)\n", + __func__, lws_wsi_tag(wsi), + par->packet_type_flags, n, (int)len + 1); lwsl_hexdump_err(buf - 1, len + 1); goto send_protocol_error_and_close; } @@ -991,7 +992,7 @@ cmd_completion: lws_set_timeout(wsi, 0, 0); w = lws_create_new_server_wsi(wsi->a.vhost, - wsi->tsi); + wsi->tsi, "mqtt"); if (!w) { lwsl_notice("%s: sid 1 migrate failed\n", __func__); @@ -1037,8 +1038,9 @@ cmd_completion: lws_mux_mark_immortal(w); - lwsl_notice("%s: migrated nwsi %p to sid 1 %p\n", - __func__, wsi, w); + lwsl_notice("%s: migrated nwsi %s to sid 1 %s\n", + __func__, lws_wsi_tag(wsi), + lws_wsi_tag(w)); #if defined(LWS_WITH_SERVER_STATUS) wsi->a.vhost->conn_stats.h2_subs++; @@ -1580,7 +1582,7 @@ lws_mqtt_publish_resend(struct lws_sorted_usec_list *sul) struct _lws_mqtt_related *mqtt = lws_container_of(sul, struct _lws_mqtt_related, sul_qos1_puback_wait); - lwsl_notice("%s: wsi %p\n", __func__, mqtt->wsi); + lwsl_notice("%s: %s\n", __func__, lws_wsi_tag(mqtt->wsi)); if (mqtt->wsi->a.protocol->callback(mqtt->wsi, LWS_CALLBACK_MQTT_RESEND, mqtt->wsi->user_space, NULL, 0)) @@ -1603,8 +1605,8 @@ lws_mqtt_client_send_publish(struct lws *wsi, lws_mqtt_publish_param_t *pub, __func__, (int)len, (int)is_complete); if (lwsi_state(wsi) != LRS_ESTABLISHED) { - lwsl_err("%s: wsi %p: unknown state 0x%x\n", __func__, wsi, - lwsi_state(wsi)); + lwsl_err("%s: %s: unknown state 0x%x\n", __func__, + lws_wsi_tag(wsi), lwsi_state(wsi)); assert(0); return 1; } diff --git a/lib/roles/mqtt/ops-mqtt.c b/lib/roles/mqtt/ops-mqtt.c index 3156bb423..fbaa83552 100644 --- a/lib/roles/mqtt/ops-mqtt.c +++ b/lib/roles/mqtt/ops-mqtt.c @@ -181,7 +181,7 @@ drain: if (buffered && /* were draining, now nothing left */ !lws_buflist_next_segment_len(&wsi->buflist, NULL)) { - lwsl_info("%s: %p flow buf: drained\n", __func__, wsi); + lwsl_info("%s: %s flow buf: drained\n", __func__, lws_wsi_tag(wsi)); /* having drained the rxflow buffer, can rearm POLLIN */ #if !defined(LWS_WITH_SERVER) n = @@ -343,8 +343,8 @@ rops_handle_POLLOUT_mqtt(struct lws *wsi) goto next_child; } - lwsl_debug("%s: child %p (wsistate 0x%x)\n", __func__, w, - (unsigned int)w->wsistate); + lwsl_debug("%s: child %s (wsistate 0x%x)\n", __func__, + lws_wsi_tag(w), (unsigned int)w->wsistate); if (lwsi_state(wsi) == LRS_ESTABLISHED && !wsi->mqtt->inside_payload && @@ -372,7 +372,7 @@ rops_handle_POLLOUT_mqtt(struct lws *wsi) } if (lws_callback_as_writeable(w)) { - lwsl_notice("%s: Closing child %p\n", __func__, w); + lwsl_notice("%s: Closing child %s\n", __func__, lws_wsi_tag(w)); lws_close_free_wsi(w, LWS_CLOSE_STATUS_NOSTATUS, "mqtt pollout handle"); wa = &wsi->mux.child_list; @@ -470,7 +470,8 @@ rops_callback_on_writable_mqtt(struct lws *wsi) #endif int already; - lwsl_debug("%s: %p (wsistate 0x%x)\n", __func__, wsi, (unsigned int)wsi->wsistate); + lwsl_debug("%s: %s (wsistate 0x%x)\n", __func__, lws_wsi_tag(wsi), + (unsigned int)wsi->wsistate); if (wsi->mux.requested_POLLOUT #if defined(LWS_WITH_CLIENT) @@ -520,8 +521,9 @@ rops_callback_on_writable_mqtt(struct lws *wsi) static int rops_close_kill_connection_mqtt(struct lws *wsi, enum lws_close_status reason) { - lwsl_info(" wsi: %p, his parent %p: child list %p, siblings:\n", wsi, - wsi->mux.parent_wsi, wsi->mux.child_list); + lwsl_info(" %s, his parent %s: child list %p, siblings:\n", + lws_wsi_tag(wsi), + lws_wsi_tag(wsi->mux.parent_wsi), wsi->mux.child_list); //lws_wsi_mux_dump_children(wsi); if (wsi->mux_substream @@ -529,11 +531,13 @@ rops_close_kill_connection_mqtt(struct lws *wsi, enum lws_close_status reason) || wsi->client_mux_substream #endif ) { - lwsl_info("closing %p: parent %p: first child %p\n", wsi, - wsi->mux.parent_wsi, wsi->mux.child_list); + lwsl_info("closing %s: parent %s: first child %p\n", + lws_wsi_tag(wsi), + lws_wsi_tag(wsi->mux.parent_wsi), + wsi->mux.child_list); if (wsi->mux.child_list && lwsl_visible(LLL_INFO)) { - lwsl_info(" parent %p: closing children: list:\n", wsi); + lwsl_info(" parent %s: closing children: list:\n", lws_wsi_tag(wsi)); lws_wsi_mux_dump_children(wsi); } diff --git a/lib/roles/netlink/ops-netlink.c b/lib/roles/netlink/ops-netlink.c index 3bf19736b..52ed0665a 100644 --- a/lib/roles/netlink/ops-netlink.c +++ b/lib/roles/netlink/ops-netlink.c @@ -366,6 +366,8 @@ rops_pt_init_destroy_netlink(struct lws_context *context, goto bail1; } + __lws_lc_tag(&context->lcg[LWSLCG_VHOST], &wsi->lc, "netlink"); + memset(&sanl, 0, sizeof(sanl)); sanl.nl_family = AF_NETLINK; sanl.nl_pid = getpid(); diff --git a/lib/roles/raw-skt/ops-raw-skt.c b/lib/roles/raw-skt/ops-raw-skt.c index 0728b5e17..53c06749b 100644 --- a/lib/roles/raw-skt/ops-raw-skt.c +++ b/lib/roles/raw-skt/ops-raw-skt.c @@ -55,7 +55,7 @@ rops_handle_POLLIN_raw_skt(struct lws_context_per_thread *pt, struct lws *wsi, #if defined(LWS_WITH_SERVER) if (!lwsi_role_client(wsi) && lwsi_state(wsi) != LRS_ESTABLISHED) { - lwsl_debug("%s: %p: wsistate 0x%x\n", __func__, wsi, + lwsl_debug("%s: %s: wsistate 0x%x\n", __func__, lws_wsi_tag(wsi), (int)wsi->wsistate); if (lwsi_state(wsi) != LRS_SSL_INIT) @@ -72,8 +72,8 @@ rops_handle_POLLIN_raw_skt(struct lws_context_per_thread *pt, struct lws *wsi, !(wsi->favoured_pollin && (pollfd->revents & pollfd->events & LWS_POLLOUT))) { - lwsl_debug("%s: POLLIN: wsi %p, state 0x%x\n", __func__, - wsi, lwsi_state(wsi)); + lwsl_debug("%s: POLLIN: %s, state 0x%x\n", __func__, + lws_wsi_tag(wsi), lwsi_state(wsi)); switch (lwsi_state(wsi)) { diff --git a/lib/roles/ws/client-parser-ws.c b/lib/roles/ws/client-parser-ws.c index 688e1ebda..317ca0c0f 100644 --- a/lib/roles/ws/client-parser-ws.c +++ b/lib/roles/ws/client-parser-ws.c @@ -483,7 +483,7 @@ ping_drop: break; case LWSWSOPC_PONG: - lwsl_info("%s: client %p received pong\n", __func__, wsi); + lwsl_info("%s: %s received pong\n", __func__, lws_wsi_tag(wsi)); lwsl_hexdump(&wsi->ws->rx_ubuf[LWS_PRE], wsi->ws->rx_ubuf_head); diff --git a/lib/roles/ws/ops-ws.c b/lib/roles/ws/ops-ws.c index de468f831..dff2490fa 100644 --- a/lib/roles/ws/ops-ws.c +++ b/lib/roles/ws/ops-ws.c @@ -1302,8 +1302,8 @@ int rops_handle_POLLOUT_ws(struct lws *wsi) wsi->ws->ping_pending_flag = 0; return LWS_HP_RET_BAIL_OK; } - lwsl_info("issuing pong %d on wsi %p\n", - wsi->ws->ping_payload_len, wsi); + lwsl_info("issuing pong %d on %s\n", + wsi->ws->ping_payload_len, lws_wsi_tag(wsi)); } n = lws_write(wsi, &wsi->ws->ping_payload_buf[LWS_PRE], @@ -1326,7 +1326,8 @@ int rops_handle_POLLOUT_ws(struct lws *wsi) if (!wsi->socket_is_permanently_unusable && wsi->ws->send_check_ping) { - lwsl_info("%s: issuing ping on wsi %p: %s %s h2: %d\n", __func__, wsi, + lwsl_info("%s: issuing ping on wsi %s: %s %s h2: %d\n", __func__, + lws_wsi_tag(wsi), wsi->role_ops->name, wsi->a.protocol->name, wsi->mux_substream); wsi->ws->send_check_ping = 0; diff --git a/lib/roles/ws/server-ws.c b/lib/roles/ws/server-ws.c index ca929cd98..5f01b0006 100644 --- a/lib/roles/ws/server-ws.c +++ b/lib/roles/ws/server-ws.c @@ -312,8 +312,8 @@ lws_process_ws_upgrade2(struct lws *wsi) * protocol handler too */ if (wsi->a.vhost->ss_handle) { - lwsl_info("%s: Server SS %p switching to ws protocol\n", - __func__, wsi->a.vhost->ss_handle); + lwsl_info("%s: %s switching to ws protocol\n", + __func__, lws_ss_tag(wsi->a.vhost->ss_handle)); wsi->a.protocol = &protocol_secstream_ws; /* @@ -429,7 +429,7 @@ lws_process_ws_upgrade2(struct lws *wsi) } #endif - lwsl_info("%s: %p: dropping ah on ws upgrade\n", __func__, wsi); + lwsl_info("%s: %s: dropping ah on ws upgrade\n", __func__, lws_wsi_tag(wsi)); lws_header_table_detach(wsi, 1); return 0; diff --git a/lib/secure-streams/policy-common.c b/lib/secure-streams/policy-common.c index 9f5483e5f..01a3497a7 100644 --- a/lib/secure-streams/policy-common.c +++ b/lib/secure-streams/policy-common.c @@ -329,7 +329,7 @@ lws_ss_policy_set(struct lws_context *context, const char *name) while (v) { if (v->from_ss_policy) { struct lws_vhost *vh = v->vhost_next; - lwsl_debug("%s: destroying vh %p\n", __func__, v); + lwsl_debug("%s: destroying %s\n", __func__, lws_vh_tag(v)); lws_vhost_destroy(v); v = vh; continue; diff --git a/lib/secure-streams/private-lib-secure-streams.h b/lib/secure-streams/private-lib-secure-streams.h index 29a1fe682..524019911 100644 --- a/lib/secure-streams/private-lib-secure-streams.h +++ b/lib/secure-streams/private-lib-secure-streams.h @@ -44,6 +44,8 @@ typedef enum { typedef struct lws_ss_handle { lws_ss_info_t info; /**< copy of stream creation info */ + lws_lifecycle_t lc; + struct lws_dll2 list; /**< pt lists active ss */ struct lws_dll2 to_list; /**< pt lists ss with pending to-s */ #if defined(LWS_WITH_SERVER) @@ -258,6 +260,9 @@ enum { typedef struct lws_sspc_handle { char rideshare_list[128]; + + lws_lifecycle_t lc; + lws_ss_info_t ssi; lws_sorted_usec_list_t sul_retry; @@ -435,6 +440,9 @@ _lws_ss_set_metadata(lws_ss_metadata_t *omd, const char *name, lws_ss_state_return_t _lws_ss_client_connect(lws_ss_handle_t *h, int is_retry); +void +__lws_ss_proxy_bind_ss_to_conn_wsi(void * parconn); + struct lws_vhost * lws_ss_policy_ref_trust_store(struct lws_context *context, const lws_ss_policy_t *pol, char doref); diff --git a/lib/secure-streams/protocols/ss-h1.c b/lib/secure-streams/protocols/ss-h1.c index 41108b959..2e96911c9 100644 --- a/lib/secure-streams/protocols/ss-h1.c +++ b/lib/secure-streams/protocols/ss-h1.c @@ -375,11 +375,13 @@ secstream_h1(struct lws *wsi, enum lws_callback_reasons reason, void *user, switch (reason) { case LWS_CALLBACK_CLIENT_CONNECTION_ERROR: - if (!h) + if (!h) { + lwsl_err("%s: CCE with no ss handle %s\n", __func__, lws_wsi_tag(wsi)); break; + } assert(h->policy); - lwsl_info("%s: h: %p, %s CLIENT_CONNECTION_ERROR: %s\n", __func__, - h, h->policy->streamtype, in ? (char *)in : "(null)"); + lwsl_info("%s: %s CLIENT_CONNECTION_ERROR: %s\n", __func__, + h->lc.gutag, in ? (const char *)in : "none"); /* already disconnected, no action for DISCONNECT_ME */ r = lws_ss_event_helper(h, LWSSSCS_UNREACHABLE); if (r) @@ -404,9 +406,8 @@ secstream_h1(struct lws *wsi, enum lws_callback_reasons reason, void *user, break; lws_sul_cancel(&h->sul_timeout); - lwsl_notice("%s: wsi: %p, h: %p, %s LWS_CALLBACK_CLOSED_CLIENT_HTTP\n", - __func__, wsi, h, - h->policy ? h->policy->streamtype : "no policy"); + lwsl_notice("%s: %s LWS_CALLBACK_CLOSED_CLIENT_HTTP\n", + __func__, wsi->lc.gutag); h->wsi = NULL; #if defined(LWS_WITH_SERVER) @@ -726,10 +727,9 @@ malformed: case LWS_CALLBACK_HTTP_WRITEABLE: case LWS_CALLBACK_CLIENT_HTTP_WRITEABLE: - //lwsl_info("%s: wsi %p, par %p, HTTP_WRITEABLE\n", __func__, - // wsi, wsi->mux.parent_wsi); + if (!h || !h->info.tx) { - lwsl_notice("%s: no handle / tx %p\n", __func__, h); + lwsl_notice("%s: %s no handle / tx\n", __func__, h->lc.gutag); return 0; } diff --git a/lib/secure-streams/protocols/ss-h2.c b/lib/secure-streams/protocols/ss-h2.c index 721a74c60..4055e65a2 100644 --- a/lib/secure-streams/protocols/ss-h2.c +++ b/lib/secure-streams/protocols/ss-h2.c @@ -56,8 +56,8 @@ secstream_h2(struct lws *wsi, enum lws_callback_reasons reason, void *user, n = secstream_h1(wsi, reason, user, in, len); if (!n && (h->policy->flags & LWSSSPOLF_LONG_POLL)) { - lwsl_notice("%s: h2 client %p entering LONG_POLL\n", - __func__, wsi); + lwsl_notice("%s: h2 client %s entering LONG_POLL\n", + __func__, lws_wsi_tag(wsi)); lws_h2_client_stream_long_poll_rxonly(wsi); } return n; @@ -69,13 +69,15 @@ secstream_h2(struct lws *wsi, enum lws_callback_reasons reason, void *user, case LWS_CALLBACK_COMPLETED_CLIENT_HTTP: // lwsl_err("%s: h2 COMPLETED_CLIENT_HTTP\n", __func__); - r = h->info.rx(ss_to_userobj(h), NULL, 0, LWSSS_FLAG_EOM); + if (h->hanging_som) + r = h->info.rx(ss_to_userobj(h), NULL, 0, LWSSS_FLAG_EOM); /* decouple the fates of the wsi and the ss */ h->wsi = NULL; h->txn_ok = 1; lws_cancel_service(lws_get_context(wsi)); /* abort poll wait */ - if (r != LWSSSSRET_OK) + if (h->hanging_som && r == LWSSSSRET_DESTROY_ME) return _lws_ss_handle_state_ret_CAN_DESTROY_HANDLE(r, wsi, &h); + h->hanging_som = 0; break; case LWS_CALLBACK_WSI_TX_CREDIT_GET: @@ -174,7 +176,7 @@ secstream_connect_munge_h2(lws_ss_handle_t *h, char *buf, size_t len, static int secstream_tx_credit_add_h2(lws_ss_handle_t *h, int add) { - lwsl_info("%s: h %p: add %d\n", __func__, h, add); + lwsl_info("%s: %s: add %d\n", __func__, lws_ss_tag(h), add); if (h->wsi) return lws_h2_update_peer_txcredit(h->wsi, LWS_H2_STREAM_SID, add); @@ -185,13 +187,13 @@ static int secstream_tx_credit_est_h2(lws_ss_handle_t *h) { if (h->wsi) { - lwsl_info("%s: h %p: est %d\n", __func__, h, + lwsl_info("%s: %s: est %d\n", __func__, lws_ss_tag(h), lws_h2_get_peer_txcredit_estimate(h->wsi)); return lws_h2_get_peer_txcredit_estimate(h->wsi); } - lwsl_info("%s: h %p: Unknown (0)\n", __func__, h); + lwsl_info("%s: %s: Unknown (0)\n", __func__, lws_ss_tag(h)); return 0; } diff --git a/lib/secure-streams/protocols/ss-mqtt.c b/lib/secure-streams/protocols/ss-mqtt.c index ba449d3a6..83b4eb98f 100644 --- a/lib/secure-streams/protocols/ss-mqtt.c +++ b/lib/secure-streams/protocols/ss-mqtt.c @@ -143,7 +143,7 @@ secstream_mqtt(struct lws *wsi, enum lws_callback_reasons reason, void *user, if (!h || !h->info.tx) return 0; - lwsl_notice("%s: ss %p: WRITEABLE\n", __func__, h); + lwsl_notice("%s: %s: WRITEABLE\n", __func__, lws_ss_tag(h)); if (h->seqstate != SSSEQ_CONNECTED) { lwsl_warn("%s: seqstate %d\n", __func__, h->seqstate); diff --git a/lib/secure-streams/protocols/ss-raw.c b/lib/secure-streams/protocols/ss-raw.c index 043b71935..f0e2ae4b7 100644 --- a/lib/secure-streams/protocols/ss-raw.c +++ b/lib/secure-streams/protocols/ss-raw.c @@ -45,8 +45,8 @@ secstream_raw(struct lws *wsi, enum lws_callback_reasons reason, void *user, case LWS_CALLBACK_CLIENT_CONNECTION_ERROR: assert(h); assert(h->policy); - lwsl_info("%s: h: %p, %s CLIENT_CONNECTION_ERROR: %s\n", __func__, - h, h->policy->streamtype, in ? (char *)in : "(null)"); + lwsl_info("%s: %s, %s CLIENT_CONNECTION_ERROR: %s\n", __func__, + lws_ss_tag(h), h->policy->streamtype, in ? (char *)in : "(null)"); r = lws_ss_event_helper(h, LWSSSCS_UNREACHABLE); if (r == LWSSSSRET_DESTROY_ME) return _lws_ss_handle_state_ret_CAN_DESTROY_HANDLE(r, wsi, &h); @@ -60,8 +60,8 @@ secstream_raw(struct lws *wsi, enum lws_callback_reasons reason, void *user, if (!h) break; lws_sul_cancel(&h->sul_timeout); - lwsl_info("%s: h: %p, %s LWS_CALLBACK_CLOSED_CLIENT_HTTP\n", - __func__, h, + lwsl_info("%s: %s, %s LWS_CALLBACK_CLOSED_CLIENT_HTTP\n", + __func__, lws_ss_tag(h), h->policy ? h->policy->streamtype : "no policy"); h->wsi = NULL; #if defined(LWS_WITH_SERVER) diff --git a/lib/secure-streams/protocols/ss-ws.c b/lib/secure-streams/protocols/ss-ws.c index b62368afc..60009d914 100644 --- a/lib/secure-streams/protocols/ss-ws.c +++ b/lib/secure-streams/protocols/ss-ws.c @@ -132,7 +132,7 @@ secstream_ws(struct lws *wsi, enum lws_callback_reasons reason, void *user, case LWS_CALLBACK_SERVER_WRITEABLE: case LWS_CALLBACK_CLIENT_WRITEABLE: - // lwsl_notice("%s: ss %p: WRITEABLE\n", __func__, h); + // lwsl_notice("%s: %s: WRITEABLE\n", __func__, lws_ss_tag(h)); if (!h || !h->info.tx) return 0; diff --git a/lib/secure-streams/secure-streams-client.c b/lib/secure-streams/secure-streams-client.c index f2e24735e..a30cd2547 100644 --- a/lib/secure-streams/secure-streams-client.c +++ b/lib/secure-streams/secure-streams-client.c @@ -54,6 +54,8 @@ lws_sspc_sul_retry_cb(lws_sorted_usec_list_t *sul) i.path = ""; i.pwsi = &h->cwsi; i.opaque_user_data = (void *)h; + i.ssl_connection = LCCSCF_SECSTREAM_PROXY_LINK; + /* this wsi is the link to the proxy */ if (!lws_client_connect_via_info(&i)) { lws_sul_schedule(h->context, 0, &h->sul_retry, @@ -62,7 +64,7 @@ lws_sspc_sul_retry_cb(lws_sorted_usec_list_t *sul) return; } - lwsl_notice("%s: sspc ss wsi %p\n", __func__, h->cwsi); + lwsl_notice("%s: %s\n", __func__, h->cwsi->lc.gutag); } static int @@ -207,8 +209,8 @@ callback_sspc_client(struct lws *wsi, enum lws_callback_reasons reason, if (!h) break; - lwsl_debug("%s: WRITEABLE %p: (%s) state %d\n", __func__, wsi, - h->ssi.streamtype, h->state); + lwsl_debug("%s: WRITEABLE %s, state %d\n", __func__, + wsi->lc.gutag, h->state); /* * Management of ss timeout can happen any time and doesn't @@ -444,8 +446,6 @@ lws_sspc_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, uint8_t *ua; char *p; - lwsl_notice("%s: streamtype %s\n", __func__, ssi->streamtype); - /* allocate the handle (including ssi), the user alloc, * and the streamname */ @@ -454,6 +454,9 @@ lws_sspc_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, if (!h) return 1; memset(h, 0, sizeof(*h)); + + __lws_lc_tag(&context->lcg[LWSLCG_SSP_CLIENT], &h->lc, ssi->streamtype); + memcpy(&h->ssi, ssi, sizeof(*ssi)); ua = (uint8_t *)&h[1]; memset(ua, 0, ssi->user_alloc); @@ -558,6 +561,8 @@ lws_sspc_destroy(lws_sspc_handle_t **ph) h->ssi.state(m, NULL, LWSSSCS_DESTROYING, 0); *ph = NULL; + + __lws_lc_untag(&h->lc); free(h); } @@ -608,7 +613,7 @@ lws_sspc_request_tx_len(lws_sspc_handle_t *h, unsigned long len) if (!h) return LWSSSSRET_OK; - lwsl_notice("%s: setting h %p writeable_len %u\n", __func__, h, + lwsl_notice("%s: setting %s writeable_len %u\n", __func__, h->lc.gutag, (unsigned int)len); h->writeable_len = len; h->pending_writeable_len = 1; @@ -834,3 +839,9 @@ lws_sspc_change_handlers(struct lws_sspc_handle *h, if (state) h->ssi.state = state; } + +const char * +lws_sspc_tag(struct lws_sspc_handle *h) +{ + return lws_lc_tag(&h->lc); +} diff --git a/lib/secure-streams/secure-streams-process.c b/lib/secure-streams/secure-streams-process.c index c8c8b4e17..2f6622781 100644 --- a/lib/secure-streams/secure-streams-process.c +++ b/lib/secure-streams/secure-streams-process.c @@ -82,6 +82,17 @@ typedef struct ss_proxy_onward { } ss_proxy_t; +void +__lws_ss_proxy_bind_ss_to_conn_wsi(void * parconn) +{ + struct conn *conn = (struct conn *)parconn; + + if (!conn || !conn->wsi || !conn->ss) + return; + + __lws_lc_tag_append(&conn->wsi->lc, lws_ss_tag(conn->ss)); +} + /* secure streams payload interface */ static lws_ss_state_return_t @@ -304,11 +315,12 @@ callback_ss_proxy(struct lws *wsi, enum lws_callback_reasons reason, /* * The onward connection is around */ - lwsl_info("%s: destroying ss.h=%p, ss.wsi=%p\n", - __func__, conn->ss, conn->ss->wsi); + lwsl_info("%s: destroying %s, wsi %s\n", + __func__, lws_ss_tag(conn->ss), + lws_wsi_tag(conn->ss->wsi)); /* sever relationship with ss about to be deleted */ lws_set_opaque_user_data(wsi, NULL); - if (wsi != cw) + if (cw && wsi != cw) /* * The wsi doing the onward connection can no * longer relate to the conn... otherwise when @@ -333,7 +345,7 @@ callback_ss_proxy(struct lws *wsi, enum lws_callback_reasons reason, free(conn); pss->conn = NULL; } else - lwsl_debug("%s: CLOSE; ss=%p\n", __func__, conn->ss); + lwsl_debug("%s: CLOSE; %s\n", __func__, lws_ss_tag(conn->ss)); break; @@ -581,7 +593,8 @@ lws_ss_proxy_create(struct lws_context *context, const char *bind, int port) memset(&info, 0, sizeof(info)); info.vhost_name = "ssproxy"; - info.options = LWS_SERVER_OPTION_ADOPT_APPLY_LISTEN_ACCEPT_CONFIG; + info.options = LWS_SERVER_OPTION_ADOPT_APPLY_LISTEN_ACCEPT_CONFIG | + LWS_SERVER_OPTION_SS_PROXY; info.port = port; if (!port) { if (!bind) diff --git a/lib/secure-streams/secure-streams-serialize.c b/lib/secure-streams/secure-streams-serialize.c index 4440cdb45..968169aff 100644 --- a/lib/secure-streams/secure-streams-serialize.c +++ b/lib/secure-streams/secure-streams-serialize.c @@ -1116,6 +1116,8 @@ payload_ff: *state = LPCSPROX_REPORTING_OK; } + __lws_ss_proxy_bind_ss_to_conn_wsi(parconn); + if (*pss) { (*pss)->being_serialized = 1; #if defined(LWS_WITH_SYS_SMD) diff --git a/lib/secure-streams/secure-streams.c b/lib/secure-streams/secure-streams.c index 28737adc0..a7e8e1ccc 100644 --- a/lib/secure-streams/secure-streams.c +++ b/lib/secure-streams/secure-streams.c @@ -118,8 +118,8 @@ _lws_ss_handle_state_ret_CAN_DESTROY_HANDLE(lws_ss_state_return_t r, struct lws lws_ss_handle_t **ph) { if (r == LWSSSSRET_DESTROY_ME) { - lwsl_info("%s: DESTROY ME: wsi %p, h->wsi %p\n", __func__, - wsi, (*ph)->wsi); + lwsl_info("%s: DESTROY ME: %s, %s\n", __func__, + lws_wsi_tag(wsi), lws_ss_tag(*ph)); if (wsi) { lws_set_opaque_user_data(wsi, NULL); lws_set_timeout(wsi, 1, LWS_TO_KILL_ASYNC); @@ -141,8 +141,7 @@ lws_ss_timeout_sul_check_cb(lws_sorted_usec_list_t *sul) { lws_ss_handle_t *h = lws_container_of(sul, lws_ss_handle_t, sul); - lwsl_notice("%s: retrying ss h %p (%s) after backoff\n", __func__, h, - h->policy->streamtype); + lwsl_info("%s: retrying %s after backoff\n", __func__, lws_ss_tag(h)); /* we want to retry... */ h->seqstate = SSSEQ_DO_RETRY; @@ -208,11 +207,11 @@ _lws_ss_backoff(lws_ss_handle_t *h, lws_usec_t us_override) /* figure out what we should do about another retry */ - lwsl_info("%s: ss %p: retry backoff after failure\n", __func__, h); + lwsl_info("%s: %s: retry backoff after failure\n", __func__, lws_ss_tag(h)); ms = lws_retry_get_delay_ms(h->context, h->policy->retry_bo, &h->retry, &conceal); if (!conceal) { - lwsl_info("%s: ss %p: abandon conn attempt \n",__func__, h); + lwsl_info("%s: %s: abandon conn attempt \n",__func__, lws_ss_tag(h)); if (h->seqstate == SSSEQ_IDLE) /* been here? */ return LWSSSSRET_OK; @@ -230,7 +229,7 @@ _lws_ss_backoff(lws_ss_handle_t *h, lws_usec_t us_override) h->seqstate = SSSEQ_RECONNECT_WAIT; lws_ss_set_timeout_us(h, us_override); - lwsl_info("%s: ss %p: retry wait %dms\n", __func__, h, + lwsl_info("%s: %s: retry wait %dms\n", __func__, lws_ss_tag(h), (int)(us_override / 1000)); return LWSSSSRET_OK; @@ -606,6 +605,8 @@ lws_ss_create(struct lws_context *context, int tsi, const lws_ss_info_t *ssi, if (!h) return 2; + __lws_lc_tag(&context->lcg[LWSLCG_WSI_SS_CLIENT], &h->lc, ssi->streamtype ? ssi->streamtype : "nostreamtype"); + h->info = *ssi; h->policy = pol; h->context = context; @@ -951,6 +952,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_free_set_NULL(h); } @@ -1122,7 +1124,7 @@ lws_ss_to_cb(lws_sorted_usec_list_t *sul) lws_ss_handle_t *h = lws_container_of(sul, lws_ss_handle_t, sul_timeout); lws_ss_state_return_t r; - lwsl_info("%s: ss %p timeout fired\n", __func__, h); + lwsl_info("%s: %s timeout fired\n", __func__, lws_ss_tag(h)); r = lws_ss_event_helper(h, LWSSSCS_TIMEOUT); if (r != LWSSSSRET_DISCONNECT_ME && r != LWSSSSRET_DESTROY_ME) @@ -1168,3 +1170,9 @@ lws_ss_change_handlers(struct lws_ss_handle *h, if (state) h->info.state = state; } + +const char * +lws_ss_tag(struct lws_ss_handle *h) +{ + return lws_lc_tag(&h->lc); +} diff --git a/lib/system/async-dns/async-dns.c b/lib/system/async-dns/async-dns.c index a8c3ae14c..c8b91742b 100644 --- a/lib/system/async-dns/async-dns.c +++ b/lib/system/async-dns/async-dns.c @@ -442,7 +442,7 @@ lws_async_dns_trim_cache(lws_async_dns_t *dns) c1 = lws_container_of(lws_dll2_get_tail(&dns->cached), lws_adns_cache_t, list); if (c1->refcount) - lwsl_notice("%s: wsi %p: refcount %d on purge\n", + lwsl_notice("%s: acache %p: refcount %d on purge\n", __func__, c1, c1->refcount); else lws_adns_cache_destroy(c1); @@ -578,8 +578,8 @@ lws_async_dns_query(struct lws_context *context, int tsi, const char *name, if (wsi) { if (!lws_dll2_is_detached(&wsi->adns)) { - lwsl_err("%s: wsi %p already bound to query %p\n", - __func__, wsi, wsi->adns.owner); + lwsl_err("%s: %s already bound to query %p\n", __func__, + lws_wsi_tag(wsi), wsi->adns.owner); goto failed; } wsi->adns_cb = cb; @@ -589,7 +589,7 @@ lws_async_dns_query(struct lws_context *context, int tsi, const char *name, c = lws_adns_get_cache(dns, name); if (c) { - lwsl_err("%s: using cached, c->results %p\n", __func__, c->results); + lwsl_info("%s: using cached, c->results %p\n", __func__, c->results); m = c->results ? LADNS_RET_FOUND : LADNS_RET_FAILED; if (c->results) c->refcount++; diff --git a/lib/system/dhcpclient/dhcpclient.c b/lib/system/dhcpclient/dhcpclient.c index 5e870dc02..1db442ff1 100644 --- a/lib/system/dhcpclient/dhcpclient.c +++ b/lib/system/dhcpclient/dhcpclient.c @@ -202,7 +202,7 @@ lws_dhcpc_retry_conn(struct lws_sorted_usec_list *sul) LWS_CAUDP_BROADCAST, "lws-dhcpclient", (const char *)&r[1], NULL, NULL, &bo2); - lwsl_debug("%s: created wsi_raw: %p\n", __func__, r->wsi_raw); + lwsl_debug("%s: created wsi_raw: %s\n", __func__, lws_wsi_tag(r->wsi_raw)); if (!r->wsi_raw) { lwsl_err("%s: unable to create udp skt\n", __func__); diff --git a/lib/system/ntpclient/ntpclient.c b/lib/system/ntpclient/ntpclient.c index 4fb82e305..1ea5bbc19 100644 --- a/lib/system/ntpclient/ntpclient.c +++ b/lib/system/ntpclient/ntpclient.c @@ -71,7 +71,7 @@ lws_ntpc_retry_conn(struct lws_sorted_usec_list *sul) { struct vhd_ntpc *v = lws_container_of(sul, struct vhd_ntpc, sul_conn); - lwsl_debug("%s: wsi_udp: %p\n", __func__, v->wsi_udp); + lwsl_debug("%s: wsi_udp: %s\n", __func__, lws_wsi_tag(v->wsi_udp)); if (v->wsi_udp || !lws_dll2_is_detached(&v->sul_conn.list)) return; @@ -84,7 +84,7 @@ lws_ntpc_retry_conn(struct lws_sorted_usec_list *sul) v->wsi_udp = lws_create_adopt_udp(v->vhost, v->ntp_server_ads, 123, 0, v->protocol->name, NULL, NULL, NULL, &bo2); - lwsl_debug("%s: created wsi_udp: %p\n", __func__, v->wsi_udp); + lwsl_debug("%s: created wsi_udp: %s\n", __func__, lws_wsi_tag(v->wsi_udp)); if (!v->wsi_udp) { lwsl_err("%s: unable to create udp skt\n", __func__); diff --git a/lib/tls/mbedtls/mbedtls-client.c b/lib/tls/mbedtls/mbedtls-client.c index 6cc3febda..97e600908 100644 --- a/lib/tls/mbedtls/mbedtls-client.c +++ b/lib/tls/mbedtls/mbedtls-client.c @@ -89,8 +89,8 @@ lws_ssl_client_bio_create(struct lws *wsi) alpn_comma = hostname; } - lwsl_info("%s: %p: client conn sending ALPN list '%s'\n", - __func__, wsi, alpn_comma); + lwsl_info("%s: %s: client conn sending ALPN list '%s'\n", + __func__, lws_wsi_tag(wsi), alpn_comma); protos.len = lws_alpn_comma_to_openssl(alpn_comma, protos.data, sizeof(protos.data) - 1); diff --git a/lib/tls/mbedtls/mbedtls-server.c b/lib/tls/mbedtls/mbedtls-server.c index bad43dbd8..80307f7d2 100644 --- a/lib/tls/mbedtls/mbedtls-server.c +++ b/lib/tls/mbedtls/mbedtls-server.c @@ -315,8 +315,8 @@ lws_tls_server_accept(struct lws *wsi) } m = SSL_get_error(wsi->tls.ssl, n); - lwsl_notice("%s: %p: accept SSL_get_error %d errno %d\n", __func__, - wsi, m, errno); + lwsl_notice("%s: %s: accept SSL_get_error %d errno %d\n", __func__, + lws_wsi_tag(wsi), m, errno); // mbedtls wrapper only if (m == SSL_ERROR_SYSCALL && errno == 11) diff --git a/lib/tls/mbedtls/mbedtls-ssl.c b/lib/tls/mbedtls/mbedtls-ssl.c index c764f3da4..91aab7e90 100644 --- a/lib/tls/mbedtls/mbedtls-ssl.c +++ b/lib/tls/mbedtls/mbedtls-ssl.c @@ -57,7 +57,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) n = SSL_read(wsi->tls.ssl, buf, len); #if defined(LWS_PLAT_FREERTOS) if (!n && errno == LWS_ENOTCONN) { - lwsl_debug("%p: SSL_read ENOTCONN\n", wsi); + lwsl_debug("%s: SSL_read ENOTCONN\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_ERROR; } #endif @@ -71,7 +71,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) #endif - lwsl_debug("%p: SSL_read says %d\n", wsi, n); + lwsl_debug("%s: %s: SSL_read says %d\n", __func__, lws_wsi_tag(wsi), n); /* manpage: returning 0 means connection shut down */ if (!n) { wsi->socket_is_permanently_unusable = 1; @@ -81,7 +81,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) if (n < 0) { m = SSL_get_error(wsi->tls.ssl, n); - lwsl_debug("%p: ssl err %d errno %d\n", wsi, m, errno); + lwsl_debug("%s: %s: ssl err %d errno %d\n", __func__, lws_wsi_tag(wsi), m, errno); if (errno == LWS_ENOTCONN) { /* If the socket isn't connected anymore, bail out. */ wsi->socket_is_permanently_unusable = 1; @@ -93,12 +93,12 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) if (m == SSL_ERROR_WANT_READ || SSL_want_read(wsi->tls.ssl)) { lwsl_debug("%s: WANT_READ\n", __func__); - lwsl_debug("%p: LWS_SSL_CAPABLE_MORE_SERVICE\n", wsi); + lwsl_debug("%s: LWS_SSL_CAPABLE_MORE_SERVICE\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_MORE_SERVICE; } if (m == SSL_ERROR_WANT_WRITE || SSL_want_write(wsi->tls.ssl)) { lwsl_debug("%s: WANT_WRITE\n", __func__); - lwsl_debug("%p: LWS_SSL_CAPABLE_MORE_SERVICE\n", wsi); + lwsl_debug("%s: LWS_SSL_CAPABLE_MORE_SERVICE\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_MORE_SERVICE; } wsi->socket_is_permanently_unusable = 1; diff --git a/lib/tls/openssl/openssl-ssl.c b/lib/tls/openssl/openssl-ssl.c index 0943d2436..bcf700c00 100644 --- a/lib/tls/openssl/openssl-ssl.c +++ b/lib/tls/openssl/openssl-ssl.c @@ -41,7 +41,7 @@ int lws_openssl_describe_cipher(struct lws *wsi) SSL *s = wsi->tls.ssl; SSL_get_cipher_bits(s, &np); - lwsl_info("%s: wsi %p: %s, %s, %d bits, %s\n", __func__, wsi, + lwsl_info("%s: %s: %s, %s, %d bits, %s\n", __func__, lws_wsi_tag(wsi), SSL_get_cipher_name(s), SSL_get_cipher(s), np, SSL_get_cipher_version(s)); #endif @@ -216,7 +216,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) n = SSL_read(wsi->tls.ssl, buf, len); #if defined(LWS_PLAT_FREERTOS) if (!n && errno == LWS_ENOTCONN) { - lwsl_debug("%p: SSL_read ENOTCONN\n", wsi); + lwsl_debug("%s: SSL_read ENOTCONN\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_ERROR; } #endif @@ -231,7 +231,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) #endif - lwsl_debug("%p: SSL_read says %d\n", wsi, n); + lwsl_debug("%s: SSL_read says %d\n", lws_wsi_tag(wsi), n); /* manpage: returning 0 means connection shut down * * 2018-09-10: https://github.com/openssl/openssl/issues/1903 @@ -258,7 +258,7 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) */ if (n <= 0) { m = lws_ssl_get_error(wsi, n); - lwsl_debug("%p: ssl err %d errno %d\n", wsi, m, errno); + lwsl_debug("%s: ssl err %d errno %d\n", lws_wsi_tag(wsi), m, errno); if (m == SSL_ERROR_ZERO_RETURN) /* cleanly shut down */ return LWS_SSL_CAPABLE_ERROR; @@ -278,12 +278,12 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) if (SSL_want_read(wsi->tls.ssl)) { lwsl_debug("%s: WANT_READ\n", __func__); - lwsl_debug("%p: LWS_SSL_CAPABLE_MORE_SERVICE\n", wsi); + lwsl_debug("%s: LWS_SSL_CAPABLE_MORE_SERVICE\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_MORE_SERVICE; } if (SSL_want_write(wsi->tls.ssl)) { lwsl_debug("%s: WANT_WRITE\n", __func__); - lwsl_debug("%p: LWS_SSL_CAPABLE_MORE_SERVICE\n", wsi); + lwsl_debug("%s: LWS_SSL_CAPABLE_MORE_SERVICE\n", lws_wsi_tag(wsi)); return LWS_SSL_CAPABLE_MORE_SERVICE; } diff --git a/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c b/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c index 1dfad888d..4a77fb8fd 100644 --- a/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c +++ b/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c @@ -108,13 +108,13 @@ callback_http(struct lws *wsi, enum lws_callback_reasons reason, return 0; /* don't passthru */ case LWS_CALLBACK_COMPLETED_CLIENT_HTTP: - lwsl_user("LWS_CALLBACK_COMPLETED_CLIENT_HTTP %p: idx %d\n", - wsi, idx); + lwsl_user("LWS_CALLBACK_COMPLETED_CLIENT_HTTP %s: idx %d\n", + lws_wsi_tag(wsi), idx); client_wsi[idx] = NULL; goto finished; case LWS_CALLBACK_CLOSED_CLIENT_HTTP: - lwsl_info("%s: closed: %p\n", __func__, client_wsi[idx]); + lwsl_info("%s: closed: %s\n", __func__, lws_wsi_tag(client_wsi[idx])); if (client_wsi[idx]) { /* * If it completed normally, it will have been set to @@ -132,8 +132,8 @@ callback_http(struct lws *wsi, enum lws_callback_reasons reason, break; if (lws_http_is_redirected_to_get(wsi)) break; - lwsl_info("LWS_CALLBACK_CLIENT_HTTP_WRITEABLE: %p, idx %d," - " part %d\n", wsi, idx, pss->body_part); + lwsl_info("LWS_CALLBACK_CLIENT_HTTP_WRITEABLE: %s, idx %d," + " part %d\n", lws_wsi_tag(wsi), idx, pss->body_part); n = LWS_WRITE_HTTP; @@ -290,8 +290,8 @@ lws_try_client_connection(struct lws_client_connect_info *i, int m) lws_context_destroy(context); } } else - lwsl_user("started connection %p: idx %d (%s)\n", - client_wsi[m], m, i->path); + lwsl_user("started connection %s: idx %d (%s)\n", + lws_wsi_tag(client_wsi[m]), m, i->path); } static void diff --git a/minimal-examples/secure-streams/minimal-secure-streams-testsfail/minimal-secure-streams-testsfail.c b/minimal-examples/secure-streams/minimal-secure-streams-testsfail/minimal-secure-streams-testsfail.c index 944cda9f9..857a0f74c 100644 --- a/minimal-examples/secure-streams/minimal-secure-streams-testsfail/minimal-secure-streams-testsfail.c +++ b/minimal-examples/secure-streams/minimal-secure-streams-testsfail/minimal-secure-streams-testsfail.c @@ -560,7 +560,8 @@ myss_rx(void *userobj, const uint8_t *buf, size_t len, int flags) m->rx_seen += len; if (flags & LWSSS_FLAG_EOM) - lwsl_notice("%s: received %u bytes\n", __func__, + lwsl_notice("%s: %s len %d, fl %d, received %u bytes\n", + __func__, lws_ss_tag(m->ss), (int)len, flags, (unsigned int)m->rx_seen); return 0; @@ -586,7 +587,7 @@ myss_state(void *userobj, void *sh, lws_ss_constate_t state, char buf[8]; size_t sl; - lwsl_info("%s: ss %p: %s (%d), ord 0x%x\n", __func__, m->ss, + lwsl_info("%s: %s: %s (%d), ord 0x%x\n", __func__, lws_ss_tag(m->ss), lws_ss_state_name((int)state), state, (unsigned int)ack); if (curr_test->mask_unexpected & (1u << state)) { @@ -615,7 +616,7 @@ fail: goto fail; } - lwsl_notice("%s: saw expected state %s\n", + lwsl_warn("%s: saw expected state %s\n", __func__, lws_ss_state_name((int)state)); m->result_reported = 1; tests_pass++; @@ -664,7 +665,7 @@ tests_start_next(lws_sorted_usec_list_t *sul) /* destroy the old one */ if (h) { - lwsl_notice("%s: destroying previous stream\n", __func__); + lwsl_info("%s: destroying previous stream\n", __func__); lws_ss_destroy(&h); } diff --git a/plugins/protocol_post_demo.c b/plugins/protocol_post_demo.c index cf9ab04e0..39c599ce8 100644 --- a/plugins/protocol_post_demo.c +++ b/plugins/protocol_post_demo.c @@ -190,7 +190,7 @@ callback_post_demo(struct lws *wsi, enum lws_callback_reasons reason, break; case LWS_CALLBACK_HTTP_BODY_COMPLETION: - lwsl_debug("LWS_CALLBACK_HTTP_BODY_COMPLETION: %p\n", wsi); + lwsl_debug("LWS_CALLBACK_HTTP_BODY_COMPLETION: %s\n", lws_wsi_tag(wsi)); /* call to inform no more payload data coming */ lws_spa_finalize(pss->spa);