From 78c7b0651e3c8f85ed4e315fa6c1835e0ed62cad Mon Sep 17 00:00:00 2001 From: Andy Green Date: Thu, 12 Sep 2019 05:41:19 +0100 Subject: [PATCH] buflist: add static reason logging to internal aware apis --- include/libwebsockets/lws-misc.h | 14 +++++++++-- lib/core-net/private-lib-core-net.h | 4 +-- lib/core-net/service.c | 39 ++++++++++++++++++++++------- lib/core-net/wsi.c | 2 +- lib/core/buflist.c | 39 +++++++++++++---------------- lib/roles/h1/ops-h1.c | 8 +++--- lib/roles/h2/http2.c | 2 +- lib/roles/h2/ops-h2.c | 4 +-- lib/roles/http/server/server.c | 4 +-- lib/roles/raw-proxy/ops-raw-proxy.c | 5 ++-- lib/roles/raw-skt/ops-raw-skt.c | 5 ++-- lib/roles/ws/ops-ws.c | 8 +++--- 12 files changed, 81 insertions(+), 53 deletions(-) diff --git a/include/libwebsockets/lws-misc.h b/include/libwebsockets/lws-misc.h index 5f2fdbe4a..d54687a37 100644 --- a/include/libwebsockets/lws-misc.h +++ b/include/libwebsockets/lws-misc.h @@ -393,8 +393,18 @@ lws_buflist_use_segment(struct lws_buflist **head, size_t len); LWS_VISIBLE LWS_EXTERN void lws_buflist_destroy_all_segments(struct lws_buflist **head); -void -lws_buflist_describe(struct lws_buflist **head, void *id); +/** + * lws_buflist_describe(): debug helper logging buflist status + * + * \param head: list head + * \param id: pointer shown in debug list + * \param reason: reason string show in debug list + * + * Iterates through the buflist segments showing position and size. + * This only exists when lws was built in debug mode + */ +LWS_VISIBLE LWS_EXTERN void +lws_buflist_describe(struct lws_buflist **head, void *id, const char *reason); /** * lws_ptr_diff(): helper to report distance between pointers as an int diff --git a/lib/core-net/private-lib-core-net.h b/lib/core-net/private-lib-core-net.h index bad7f26c9..2fd63d631 100644 --- a/lib/core-net/private-lib-core-net.h +++ b/lib/core-net/private-lib-core-net.h @@ -1191,10 +1191,10 @@ lws_seq_pt_init(struct lws_context_per_thread *pt); int lws_buflist_aware_read(struct lws_context_per_thread *pt, struct lws *wsi, - struct lws_tokens *ebuf); + struct lws_tokens *ebuf, const char *hint); int lws_buflist_aware_consume(struct lws *wsi, struct lws_tokens *ebuf, int used, - int buffered); + int buffered, const char *hint); extern const struct lws_protocols protocol_abs_client_raw_skt, protocol_abs_client_unit_test; diff --git a/lib/core-net/service.c b/lib/core-net/service.c index 1bfc604fc..c83af8e80 100644 --- a/lib/core-net/service.c +++ b/lib/core-net/service.c @@ -347,15 +347,29 @@ lws_service_adjust_timeout(struct lws_context *context, int timeout_ms, int tsi) */ int lws_buflist_aware_read(struct lws_context_per_thread *pt, struct lws *wsi, - struct lws_tokens *ebuf) + struct lws_tokens *ebuf, const char *hint) { int n, prior = (int)lws_buflist_next_segment_len(&wsi->buflist, NULL); - ebuf->token = pt->serv_buf; - ebuf->len = lws_ssl_capable_read(wsi, pt->serv_buf, - wsi->context->pt_serv_buf_size); - if (ebuf->len == LWS_SSL_CAPABLE_MORE_SERVICE && prior) + // lwsl_debug("%s: wsi %p: %s: prior %d\n", __func__, wsi, hint, prior); + // lws_buflist_describe(&wsi->buflist, wsi, __func__); + + (void)hint; + ebuf->token = pt->serv_buf; + n = lws_ssl_capable_read(wsi, pt->serv_buf, + wsi->context->pt_serv_buf_size); + ebuf->len = n; + + lwsl_info("%s: wsi %p: %s: ssl_capable_read %d (prior %d)\n", __func__, + wsi, hint, ebuf->len, prior); + + if (n == LWS_SSL_CAPABLE_ERROR && !prior) { + lwsl_info("%s: SSL_CAPABLE_ERROR with no prior\n", __func__); + return -1; + } + + if (ebuf->len < 0 && prior) goto get_from_buflist; if (ebuf->len <= 0) @@ -385,16 +399,23 @@ get_from_buflist: ebuf->len = (int)lws_buflist_next_segment_len(&wsi->buflist, &ebuf->token); + lwsl_debug("%s: wsi %p: get from buflist told %d\n", __func__, wsi, ebuf->len); + return 1; /* came from buflist */ } int lws_buflist_aware_consume(struct lws *wsi, struct lws_tokens *ebuf, int used, - int buffered) + int buffered, const char *hint) { struct lws_context_per_thread *pt = &wsi->context->pt[(int)wsi->tsi]; int m; + //lwsl_debug("%s %s consuming buffered %d used %zu / %zu\n", __func__, hint, + // buffered, (size_t)used, (size_t)ebuf->len); + + // lws_buflist_describe(&wsi->buflist, wsi, __func__); + /* it's in the buflist; we didn't use any */ if (!used && buffered) @@ -402,8 +423,8 @@ lws_buflist_aware_consume(struct lws *wsi, struct lws_tokens *ebuf, int used, if (used && buffered) { m = lws_buflist_use_segment(&wsi->buflist, used); - lwsl_info("%s: draining rxflow: used %d, next %d\n", - __func__, used, m); + // lwsl_notice("%s: used %d, next %d\n", __func__, used, m); + // lws_buflist_describe(&wsi->buflist, wsi, __func__); if (m) return 0; @@ -428,7 +449,7 @@ lws_buflist_aware_consume(struct lws *wsi, struct lws_tokens *ebuf, int used, lws_dll2_add_head(&wsi->dll_buflist, &pt->dll_buflist_owner); } - // lws_buflist_describe(&wsi->buflist, wsi); + // lws_buflist_describe(&wsi->buflist, wsi, __func__); } return 0; diff --git a/lib/core-net/wsi.c b/lib/core-net/wsi.c index 66dda34c5..11c14f968 100644 --- a/lib/core-net/wsi.c +++ b/lib/core-net/wsi.c @@ -346,7 +346,7 @@ __lws_rx_flow_control(struct lws *wsi) if (wsi->rxflow_change_to & LWS_RXFLOW_ALLOW) { lwsl_info("%s: reenable POLLIN\n", __func__); - // lws_buflist_describe(&wsi->buflist, NULL); + // lws_buflist_describe(&wsi->buflist, NULL, __func__); if (__lws_change_pollfd(wsi, 0, LWS_POLLIN)) { lwsl_info("%s: fail\n", __func__); return -1; diff --git a/lib/core/buflist.c b/lib/core/buflist.c index c220ae4ff..595cb34dd 100644 --- a/lib/core/buflist.c +++ b/lib/core/buflist.c @@ -113,22 +113,19 @@ lws_buflist_next_segment_len(struct lws_buflist **head, uint8_t **buf) { struct lws_buflist *b = (*head); - if (!b) { - if (buf) - *buf = NULL; + if (buf) + *buf = NULL; - return 0; - } + if (!b) + return 0; /* there is no next segment len */ if (!b->len && b->next) - lws_buflist_destroy_segment(head); + if (lws_buflist_destroy_segment(head)) + return 0; - if (!b) { - if (buf) - *buf = NULL; - - return 0; - } + b = (*head); + if (!b) + return 0; /* there is no next segment len */ assert(b->pos < b->len); @@ -154,28 +151,26 @@ lws_buflist_use_segment(struct lws_buflist **head, size_t len) if (b->pos < b->len) return (int)(b->len - b->pos); - if (b->pos == b->len) { - if (lws_buflist_destroy_segment(head)) - return 0; + if (lws_buflist_destroy_segment(head)) + /* last segment was just destroyed */ + return 0; - return lws_buflist_next_segment_len(head, NULL); - } - - return 0; + return lws_buflist_next_segment_len(head, NULL); } #if defined(_DEBUG) void -lws_buflist_describe(struct lws_buflist **head, void *id) +lws_buflist_describe(struct lws_buflist **head, void *id, const char *reason) { struct lws_buflist *old; int n = 0; if (*head == NULL) - lwsl_notice("%p: buflist empty\n", id); + lwsl_notice("%p: %sL buflist empty\n", id, reason); while (*head) { - lwsl_notice("%p: %d: %llu / %llu (%llu left)\n", id, n, + lwsl_notice("%p: %s: %d: %llu / %llu (%llu left)\n", id, + reason, n, (unsigned long long)(*head)->pos, (unsigned long long)(*head)->len, (unsigned long long)(*head)->len - (*head)->pos); diff --git a/lib/roles/h1/ops-h1.c b/lib/roles/h1/ops-h1.c index cb21838fe..4788c84aa 100644 --- a/lib/roles/h1/ops-h1.c +++ b/lib/roles/h1/ops-h1.c @@ -352,7 +352,7 @@ lws_h1_server_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) * exhausted and we tried to do a read of some kind. */ - buffered = lws_buflist_aware_read(pt, wsi, &ebuf); + buffered = lws_buflist_aware_read(pt, wsi, &ebuf, __func__); switch (ebuf.len) { case 0: lwsl_info("%s: read 0 len a\n", __func__); @@ -389,7 +389,7 @@ lws_h1_server_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) if (lwsi_state(wsi) == LRS_ISSUING_FILE) { // lwsl_notice("stashing: wsi %p: bd %d\n", wsi, buffered); - if (lws_buflist_aware_consume(wsi, &ebuf, 0, buffered)) + if (lws_buflist_aware_consume(wsi, &ebuf, 0, buffered, __func__)) return LWS_HPI_RET_PLEASE_CLOSE_ME; goto try_pollout; @@ -408,9 +408,9 @@ lws_h1_server_socket_service(struct lws *wsi, struct lws_pollfd *pollfd) if (n < 0) /* we closed wsi */ return LWS_HPI_RET_WSI_ALREADY_DIED; - lwsl_debug("%s: consumed %d\n", __func__, n); + // lwsl_notice("%s: consumed %d\n", __func__, n); - if (lws_buflist_aware_consume(wsi, &ebuf, n, buffered)) + if (lws_buflist_aware_consume(wsi, &ebuf, n, buffered, __func__)) return LWS_HPI_RET_PLEASE_CLOSE_ME; /* diff --git a/lib/roles/h2/http2.c b/lib/roles/h2/http2.c index b30a0ba28..331646c17 100644 --- a/lib/roles/h2/http2.c +++ b/lib/roles/h2/http2.c @@ -1938,7 +1938,7 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t inlen, { if (lwsi_state(h2n->swsi) == LRS_DEFERRING_ACTION) { - // lwsl_notice("appending because we are in LRS_DEFERRING_ACTION\n"); + // lwsl_notice("%s: appending because we are in LRS_DEFERRING_ACTION\n", __func__); m = lws_buflist_append_segment( &h2n->swsi->buflist, in - 1, n); diff --git a/lib/roles/h2/ops-h2.c b/lib/roles/h2/ops-h2.c index 765aebe34..6f4178ff2 100644 --- a/lib/roles/h2/ops-h2.c +++ b/lib/roles/h2/ops-h2.c @@ -179,7 +179,7 @@ rops_handle_POLLIN_h2(struct lws_context_per_thread *pt, struct lws *wsi, read: /* 3: network wsi buflist needs to be drained */ - // lws_buflist_describe(&wsi->buflist, wsi); + // lws_buflist_describe(&wsi->buflist, wsi, __func__); ebuf.len = (int)lws_buflist_next_segment_len(&wsi->buflist, &ebuf.token); @@ -298,7 +298,7 @@ drain: } } - // lws_buflist_describe(&wsi->buflist, wsi); + // lws_buflist_describe(&wsi->buflist, wsi, __func__); #if 0 diff --git a/lib/roles/http/server/server.c b/lib/roles/http/server/server.c index 989994d42..4c7a2a6fe 100644 --- a/lib/roles/http/server/server.c +++ b/lib/roles/http/server/server.c @@ -1700,7 +1700,7 @@ deal_body: if (m < 0) return -1; - if (lws_buflist_aware_consume(wsi, &ebuf, m, 1)) + if (lws_buflist_aware_consume(wsi, &ebuf, m, 1, __func__)) return -1; } } @@ -2264,7 +2264,7 @@ lws_http_transaction_completed(struct lws *wsi) * reset the existing header table and keep it. */ if (wsi->http.ah) { - // lws_buflist_describe(&wsi->buflist, wsi); + // 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); diff --git a/lib/roles/raw-proxy/ops-raw-proxy.c b/lib/roles/raw-proxy/ops-raw-proxy.c index 772455197..8a5d8958c 100644 --- a/lib/roles/raw-proxy/ops-raw-proxy.c +++ b/lib/roles/raw-proxy/ops-raw-proxy.c @@ -54,7 +54,7 @@ rops_handle_POLLIN_raw_proxy(struct lws_context_per_thread *pt, struct lws *wsi, !(wsi->favoured_pollin && (pollfd->revents & pollfd->events & LWS_POLLOUT))) { - buffered = lws_buflist_aware_read(pt, wsi, &ebuf); + buffered = lws_buflist_aware_read(pt, wsi, &ebuf, __func__); switch (ebuf.len) { case 0: lwsl_info("%s: read 0 len\n", __func__); @@ -86,7 +86,8 @@ rops_handle_POLLIN_raw_proxy(struct lws_context_per_thread *pt, struct lws *wsi, goto fail; } - if (lws_buflist_aware_consume(wsi, &ebuf, ebuf.len, buffered)) + if (lws_buflist_aware_consume(wsi, &ebuf, ebuf.len, buffered, + __func__)) return LWS_HPI_RET_PLEASE_CLOSE_ME; } else if (wsi->favoured_pollin && diff --git a/lib/roles/raw-skt/ops-raw-skt.c b/lib/roles/raw-skt/ops-raw-skt.c index cc505531b..793098a3d 100644 --- a/lib/roles/raw-skt/ops-raw-skt.c +++ b/lib/roles/raw-skt/ops-raw-skt.c @@ -70,7 +70,7 @@ rops_handle_POLLIN_raw_skt(struct lws_context_per_thread *pt, struct lws *wsi, !(wsi->favoured_pollin && (pollfd->revents & pollfd->events & LWS_POLLOUT))) { - buffered = lws_buflist_aware_read(pt, wsi, &ebuf); + buffered = lws_buflist_aware_read(pt, wsi, &ebuf, __func__); switch (ebuf.len) { case 0: lwsl_info("%s: read 0 len\n", __func__); @@ -101,7 +101,8 @@ rops_handle_POLLIN_raw_skt(struct lws_context_per_thread *pt, struct lws *wsi, goto fail; } - if (lws_buflist_aware_consume(wsi, &ebuf, ebuf.len, buffered)) + if (lws_buflist_aware_consume(wsi, &ebuf, ebuf.len, buffered, + __func__)) return LWS_HPI_RET_PLEASE_CLOSE_ME; } else if (wsi->favoured_pollin && diff --git a/lib/roles/ws/ops-ws.c b/lib/roles/ws/ops-ws.c index d33e62296..08e5ad1b4 100644 --- a/lib/roles/ws/ops-ws.c +++ b/lib/roles/ws/ops-ws.c @@ -1150,7 +1150,7 @@ rops_handle_POLLIN_ws(struct lws_context_per_thread *pt, struct lws *wsi, /* 3: buflist needs to be drained */ read: - //lws_buflist_describe(&wsi->buflist, wsi); + //lws_buflist_describe(&wsi->buflist, wsi, __func__); ebuf.len = (int)lws_buflist_next_segment_len(&wsi->buflist, &ebuf.token); if (ebuf.len) { @@ -1236,7 +1236,7 @@ drain: do { /* service incoming data */ - //lws_buflist_describe(&wsi->buflist, wsi); + //lws_buflist_describe(&wsi->buflist, wsi, __func__); if (ebuf.len) { #if defined(LWS_ROLE_H2) if (lwsi_role_h2(wsi) && lwsi_state(wsi) != LRS_BODY && @@ -1253,9 +1253,9 @@ drain: n = 0; return LWS_HPI_RET_WSI_ALREADY_DIED; } - //lws_buflist_describe(&wsi->buflist, wsi); + //lws_buflist_describe(&wsi->buflist, wsi, __func__); //lwsl_notice("%s: consuming %d / %d\n", __func__, n, ebuf.len); - if (lws_buflist_aware_consume(wsi, &ebuf, n, buffered)) + if (lws_buflist_aware_consume(wsi, &ebuf, n, buffered, __func__)) return LWS_HPI_RET_PLEASE_CLOSE_ME; }