logs: migrate ws extension code to contextual logging

2 files changed, 55 insertions, 57 deletions

diff --git a/lib/roles/ws/ext/extension-permessage-deflate.c b/lib/roles/ws/ext/extension-permessage-deflate.c
index c442f7c1..79c70ea9 100644
--- a/lib/roles/ws/ext/extension-permessage-deflate.c
+++ b/lib/roles/ws/ext/extension-permessage-deflate.c
@@ -62,7 +62,7 @@ lws_extension_pmdeflate_restrict_args(struct lws *wsi,
 
 	if (extra < priv->args[PMD_RX_BUF_PWR2]) {
 		priv->args[PMD_RX_BUF_PWR2] = (unsigned char)extra;
-		lwsl_info(" Capping pmd rx to %d\n", 1 << extra);
+		lwsl_wsi_info(wsi, " Capping pmd rx to %d", 1 << extra);
 	}
 }
 
@@ -89,8 +89,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		oa = in;
 		if (!oa->option_name)
 			break;
-		lwsl_ext("%s: named option set: %s\n", __func__,
-			 oa->option_name);
+		lwsl_wsi_ext(wsi, "named option set: %s", oa->option_name);
 		for (n = 0; n < (int)LWS_ARRAY_SIZE(lws_ext_pm_deflate_options);
 		     n++)
 			if (!strcmp(lws_ext_pm_deflate_options[n].name,
@@ -105,7 +104,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 
 	case LWS_EXT_CB_OPTION_SET:
 		oa = in;
-		lwsl_ext("%s: option set: idx %d, %s, len %d\n", __func__,
+		lwsl_wsi_ext(wsi, "option set: idx %d, %s, len %d",
 			 oa->option_index, oa->start, oa->len);
 		if (oa->start)
 			priv->args[oa->option_index] = (unsigned char)atoi(oa->start);
@@ -134,8 +133,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 			n = (int)wsi->a.protocol->rx_buffer_size;
 
 		if (n < 128) {
-			lwsl_info(" permessage-deflate requires the protocol "
-				  "(%s) to have an RX buffer >= 128\n",
+			lwsl_wsi_info(wsi, " permessage-deflate requires the protocol "
+				  "(%s) to have an RX buffer >= 128",
 				  wsi->a.protocol->name);
 			return -1;
 		}
@@ -143,7 +142,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		/* fill in **user */
 		priv = lws_zalloc(sizeof(*priv), "pmd priv");
 		*((void **)user) = priv;
-		lwsl_ext("%s: LWS_EXT_CB_*CONSTRUCT\n", __func__);
+		lwsl_wsi_ext(wsi, "LWS_EXT_CB_*CONSTRUCT");
 		memset(priv, 0, sizeof(*priv));
 
 		/* fill in pointer to options list */
@@ -173,7 +172,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		break;
 
 	case LWS_EXT_CB_DESTROY:
-		lwsl_ext("%s: LWS_EXT_CB_DESTROY\n", __func__);
+		lwsl_wsi_ext(wsi, "LWS_EXT_CB_DESTROY");
 		lws_free(priv->buf_rx_inflated);
 		lws_free(priv->buf_tx_deflated);
 		if (priv->rx_init)
@@ -189,8 +188,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		/*
 		 * ie, we are INFLATING
 		 */
-		lwsl_ext(" %s: LWS_EXT_CB_PAYLOAD_RX: in %d, existing in %d\n",
-			 __func__, pmdrx->eb_in.len, priv->rx.avail_in);
+		lwsl_wsi_ext(wsi, " LWS_EXT_CB_PAYLOAD_RX: in %d, existing in %d",
+			 pmdrx->eb_in.len, priv->rx.avail_in);
 
 		/*
 		 * If this frame is not marked as compressed,
@@ -216,8 +215,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 
 		pmdrx->eb_out.len = 0;
 
-		lwsl_ext("%s: LWS_EXT_CB_PAYLOAD_RX: in %d, "
-			 "existing avail in %d, pkt fin: %d\n", __func__,
+		lwsl_wsi_ext(wsi, "LWS_EXT_CB_PAYLOAD_RX: in %d, "
+			 "existing avail in %d, pkt fin: %d",
 			 pmdrx->eb_in.len, priv->rx.avail_in, wsi->ws->final);
 
 		/* if needed, initialize the inflator */
@@ -225,7 +224,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		if (!priv->rx_init) {
 			if (inflateInit2(&priv->rx,
 			     -priv->args[PMD_SERVER_MAX_WINDOW_BITS]) != Z_OK) {
-				lwsl_err("%s: iniflateInit failed\n", __func__);
+				lwsl_wsi_err(wsi, "iniflateInit failed");
 				return PMDR_FAILED;
 			}
 			priv->rx_init = 1;
@@ -235,7 +234,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 					    (1 << priv->args[PMD_RX_BUF_PWR2])),
 					    "pmd rx inflate buf");
 			if (!priv->buf_rx_inflated) {
-				lwsl_err("%s: OOM\n", __func__);
+				lwsl_wsi_err(wsi, "OOM");
 				return PMDR_FAILED;
 			}
 		}
@@ -248,8 +247,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 
 		if (priv->rx.avail_in && pmdrx->eb_in.token &&
 					 pmdrx->eb_in.len) {
-			lwsl_warn("%s: priv->rx.avail_in %d while getting new in\n",
-					__func__, priv->rx.avail_in);
+			lwsl_wsi_warn(wsi, "priv->rx.avail_in %d while getting new in",
+					priv->rx.avail_in);
 	//		assert(0);
 		}
 #endif
@@ -277,7 +276,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		    wsi->ws->final &&
 		    !wsi->ws->rx_packet_length &&
 		    wsi->ws->pmd_trailer_application) {
-			lwsl_ext("%s: trailer apply 1\n", __func__);
+			lwsl_wsi_ext(wsi, "trailer apply 1");
 			was_fin = 1;
 			wsi->ws->pmd_trailer_application = 0;
 			priv->rx.next_in = trail;
@@ -293,15 +292,15 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 			return PMDR_DID_NOTHING;
 
 		n = inflate(&priv->rx, was_fin ? Z_SYNC_FLUSH : Z_NO_FLUSH);
-		lwsl_ext("inflate ret %d, avi %d, avo %d, wsifinal %d\n", n,
+		lwsl_wsi_ext(wsi, "inflate ret %d, avi %d, avo %d, wsifinal %d", n,
 			 priv->rx.avail_in, priv->rx.avail_out, wsi->ws->final);
 		switch (n) {
 		case Z_NEED_DICT:
 		case Z_STREAM_ERROR:
 		case Z_DATA_ERROR:
 		case Z_MEM_ERROR:
-			lwsl_err("%s: zlib error inflate %d: \"%s\"\n",
-				  __func__, n, priv->rx.msg);
+			lwsl_wsi_err(wsi, "zlib error inflate %d: \"%s\"",
+				  n, priv->rx.msg);
 			return PMDR_FAILED;
 		}
 
@@ -313,7 +312,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 				         ((unsigned int)pmdrx->eb_in.len - (unsigned int)priv->rx.avail_in);
 		pmdrx->eb_in.len = (int)priv->rx.avail_in;
 
-		lwsl_debug("%s: %d %d %d %d %d\n", __func__,
+		lwsl_wsi_debug(wsi, "%d %d %d %d %d",
 				priv->rx.avail_in,
 				wsi->ws->final,
 				(int)wsi->ws->rx_packet_length,
@@ -325,7 +324,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		    !wsi->ws->rx_packet_length &&
 		    !was_fin &&
 		    wsi->ws->pmd_trailer_application) {
-			lwsl_ext("%s: RX trailer apply 2\n", __func__);
+			lwsl_wsi_ext(wsi, "RX trailer apply 2");
 
 			/* we overallocated just for this situation where
 			 * we might issue something */
@@ -336,14 +335,14 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 			priv->rx.next_in = trail;
 			priv->rx.avail_in = sizeof(trail);
 			n = inflate(&priv->rx, Z_SYNC_FLUSH);
-			lwsl_ext("RX trailer infl ret %d, avi %d, avo %d\n",
+			lwsl_wsi_ext(wsi, "RX trailer infl ret %d, avi %d, avo %d",
 				 n, priv->rx.avail_in, priv->rx.avail_out);
 			switch (n) {
 			case Z_NEED_DICT:
 			case Z_STREAM_ERROR:
 			case Z_DATA_ERROR:
 			case Z_MEM_ERROR:
-				lwsl_info("zlib error inflate %d: %s\n",
+				lwsl_wsi_info(wsi, "zlib error inflate %d: %s",
 					  n, priv->rx.msg);
 				return -1;
 			}
@@ -355,16 +354,16 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 						 pmdrx->eb_out.token);
 		priv->count_rx_between_fin = priv->count_rx_between_fin + (size_t)pmdrx->eb_out.len;
 
-		lwsl_ext("  %s: RX leaving with new effbuff len %d, "
-			 "rx.avail_in=%d, TOTAL RX since FIN %lu\n",
-			 __func__, pmdrx->eb_out.len, priv->rx.avail_in,
+		lwsl_wsi_ext(wsi, "  RX leaving with new effbuff len %d, "
+			 "rx.avail_in=%d, TOTAL RX since FIN %lu",
+			 pmdrx->eb_out.len, priv->rx.avail_in,
 			 (unsigned long)priv->count_rx_between_fin);
 
 		if (was_fin) {
-			lwsl_ext("%s: was_fin\n", __func__);
+			lwsl_wsi_ext(wsi, "was_fin");
 			priv->count_rx_between_fin = 0;
 			if (priv->args[PMD_SERVER_NO_CONTEXT_TAKEOVER]) {
-				lwsl_ext("PMD_SERVER_NO_CONTEXT_TAKEOVER\n");
+				lwsl_wsi_ext(wsi, "PMD_SERVER_NO_CONTEXT_TAKEOVER");
 				(void)inflateEnd(&priv->rx);
 				priv->rx_init = 0;
 			}
@@ -393,7 +392,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 					 priv->args[PMD_MEM_LEVEL],
 					 Z_DEFAULT_STRATEGY);
 			if (n != Z_OK) {
-				lwsl_ext("inflateInit2 failed %d\n", n);
+				lwsl_wsi_ext(wsi, "inflateInit2 failed %d", n);
 				return PMDR_FAILED;
 			}
 			priv->tx_init = 1;
@@ -404,7 +403,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 					    (1 << priv->args[PMD_TX_BUF_PWR2])),
 					    "pmd tx deflate buf");
 		if (!priv->buf_tx_deflated) {
-			lwsl_err("%s: OOM\n", __func__);
+			lwsl_wsi_err(wsi, "OOM");
 			return PMDR_FAILED;
 		}
 
@@ -415,8 +414,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 			assert(!priv->tx.avail_in);
 
 			priv->count_tx_between_fin = priv->count_tx_between_fin + (size_t)pmdrx->eb_in.len;
-			lwsl_ext("%s: TX: eb_in length %d, "
-				    "TOTAL TX since FIN: %d\n", __func__,
+			lwsl_wsi_ext(wsi, "TX: eb_in length %d, "
+				    "TOTAL TX since FIN: %d",
 				    pmdrx->eb_in.len,
 				    (int)priv->count_tx_between_fin);
 			priv->tx.next_in = (unsigned char *)pmdrx->eb_in.token;
@@ -433,7 +432,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		pen = pen | (unsigned int)penbits;
 
 		if (!priv->tx.avail_in && (len & LWS_WRITE_NO_FIN)) {
-			lwsl_ext("%s: no available in, pen: %u\n", __func__, pen);
+			lwsl_wsi_ext(wsi, "no available in, pen: %u", pen);
 
 			if (!pen)
 				return PMDR_DID_NOTHING;
@@ -441,20 +440,20 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 
 		m = Z_NO_FLUSH;
 		if (!(len & LWS_WRITE_NO_FIN)) {
-			lwsl_ext("%s: deflate with SYNC_FLUSH, pkt len %d\n",
-					__func__, (int)wsi->ws->rx_packet_length);
+			lwsl_wsi_ext(wsi, "deflate with SYNC_FLUSH, pkt len %d",
+					(int)wsi->ws->rx_packet_length);
 			m = Z_SYNC_FLUSH;
 		}
 
 		n = deflate(&priv->tx, m);
 		if (n == Z_STREAM_ERROR) {
-			lwsl_notice("%s: Z_STREAM_ERROR\n", __func__);
+			lwsl_wsi_notice(wsi, "Z_STREAM_ERROR");
 			return PMDR_FAILED;
 		}
 
 		pen = (!priv->tx.avail_out) && n != Z_STREAM_END;
 
-		lwsl_ext("%s: deflate ret %d, len 0x%x\n", __func__, n,
+		lwsl_wsi_ext(wsi, "deflate ret %d, len 0x%x", n,
 				(unsigned int)len);
 
 		if ((len & 0xf) == LWS_WRITE_TEXT)
@@ -467,8 +466,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 
 		if (m == Z_SYNC_FLUSH && !(len & LWS_WRITE_NO_FIN) && !pen &&
 		    pmdrx->eb_out.len < 4) {
-			lwsl_err("%s: FAIL want to trim out length %d\n",
-					__func__, (int)pmdrx->eb_out.len);
+			lwsl_wsi_err(wsi, "FAIL want to trim out length %d",
+					(int)pmdrx->eb_out.len);
 			assert(0);
 		}
 
@@ -476,7 +475,7 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		    m == Z_SYNC_FLUSH &&
 		    !pen &&
 		    pmdrx->eb_out.len >= 4) {
-			// lwsl_err("%s: Trimming 4 from end of write\n", __func__);
+			// lwsl_wsi_err(wsi, "Trimming 4 from end of write");
 			priv->tx.next_out -= 4;
 			priv->tx.avail_out += 4;
 			priv->count_tx_between_fin = 0;
@@ -500,8 +499,8 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		pmdrx->eb_out.len = lws_ptr_diff(priv->tx.next_out,
 						 pmdrx->eb_out.token);
 
-		lwsl_ext("  TX rewritten with new eb_in len %d, "
-				"eb_out len %d, deflatePending %d\n",
+		lwsl_wsi_ext(wsi, "  TX rewritten with new eb_in len %d, "
+				"eb_out len %d, deflatePending %d",
 				pmdrx->eb_in.len, pmdrx->eb_out.len, pen);
 
 		if (pmdrx->eb_in.len || pen)
@@ -538,13 +537,13 @@ lws_extension_callback_pm_deflate(struct lws_context *context,
 		if (n == LWSWSOPC_TEXT_FRAME || n == LWSWSOPC_BINARY_FRAME)
 			*pmdrx->eb_in.token |= 0x40;
 
-		lwsl_ext("%s: PRESEND compressed: ws frame 0x%02X, len %d\n",
-			    __func__, ((*pmdrx->eb_in.token) & 0xff),
+		lwsl_wsi_ext(wsi, "PRESEND compressed: ws frame 0x%02X, len %d",
+			    ((*pmdrx->eb_in.token) & 0xff),
 			    pmdrx->eb_in.len);
 
 		if (((*pmdrx->eb_in.token) & 0x80) &&	/* fin */
 		    priv->args[PMD_CLIENT_NO_CONTEXT_TAKEOVER]) {
-			lwsl_debug("PMD_CLIENT_NO_CONTEXT_TAKEOVER\n");
+			lwsl_wsi_debug(wsi, "PMD_CLIENT_NO_CONTEXT_TAKEOVER");
 			(void)deflateEnd(&priv->tx);
 			priv->tx_init = 0;
 		}
diff --git a/lib/roles/ws/ext/extension.c b/lib/roles/ws/ext/extension.c
index 38fd2995..dd6539b7 100644
--- a/lib/roles/ws/ext/extension.c
+++ b/lib/roles/ws/ext/extension.c
@@ -30,7 +30,7 @@ void
 lws_context_init_extensions(const struct lws_context_creation_info *info,
 			    struct lws_context *context)
 {
-	lwsl_info(" LWS_MAX_EXTENSIONS_ACTIVE: %u\n", LWS_MAX_EXTENSIONS_ACTIVE);
+	lwsl_cx_info(context, " LWS_MAX_EXTENSIONS_ACTIVE: %u", LWS_MAX_EXTENSIONS_ACTIVE);
 }
 
 enum lws_ext_option_parser_states {
@@ -56,7 +56,7 @@ lws_ext_parse_options(const struct lws_extension *ext, struct lws *wsi,
 	while (opts[count_options].name)
 		count_options++;
 	while (len) {
-		lwsl_ext("'%c' %d", *in, leap);
+		lwsl_wsi_ext(wsi, "'%c' %d", *in, leap);
 		switch (leap) {
 		case LEAPS_SEEK_NAME:
 			if (*in == ' ')
@@ -83,12 +83,12 @@ lws_ext_parse_options(const struct lws_extension *ext, struct lws *wsi,
 					n++;
 					continue;
 				}
-				lwsl_ext("    m=%d, n=%d, w=%d\n", m, n, w);
+				lwsl_wsi_ext(wsi, "    m=%d, n=%d, w=%d", m, n, w);
 
 				if (*in == opts[n].name[w]) {
 					if (!opts[n].name[w + 1]) {
 						oa.option_index = (int)n;
-						lwsl_ext("hit %d\n",
+						lwsl_wsi_ext(wsi, "hit %d",
 							 oa.option_index);
 						leap = LEAPS_SEEK_VAL;
 						if (len == 1)
@@ -98,7 +98,7 @@ lws_ext_parse_options(const struct lws_extension *ext, struct lws *wsi,
 				} else {
 					match_map &= (unsigned int)~(1 << n);
 					if (!match_map) {
-						lwsl_ext("empty match map\n");
+						lwsl_wsi_ext(wsi, "empty match map");
 						return -1;
 					}
 				}
@@ -200,7 +200,7 @@ int lws_ext_cb_active(struct lws *wsi, int reason, void *arg, int len)
 			lws_get_context(wsi), wsi->ws->active_extensions[n],
 			wsi, (enum lws_extension_callback_reasons)reason, wsi->ws->act_ext_user[n], arg, (size_t)len);
 		if (m < 0) {
-			lwsl_ext("Ext '%s' failed to handle callback %d!\n",
+			lwsl_wsi_ext(wsi, "Ext '%s' failed to handle callback %d!",
 				 wsi->ws->active_extensions[n]->name, reason);
 			return -1;
 		}
@@ -229,7 +229,7 @@ int lws_ext_cb_all_exts(struct lws_context *context, struct lws *wsi,
 		m = ext->callback(context, ext, wsi, (enum lws_extension_callback_reasons)reason,
 				  (void *)(lws_intptr_t)n, arg, (size_t)len);
 		if (m < 0) {
-			lwsl_ext("Ext '%s' failed to handle callback %d!\n",
+			lwsl_wsi_ext(wsi, "Ext '%s' failed to handle callback %d!",
 				 wsi->ws->active_extensions[n]->name, reason);
 			return -1;
 		}
@@ -284,7 +284,7 @@ lws_issue_raw_ext_access(struct lws *wsi, unsigned char *buf, size_t len)
 		if (ebuf.len) {
 			n = lws_issue_raw(wsi, ebuf.token, (size_t)ebuf.len);
 			if (n < 0) {
-				lwsl_info("closing from ext access\n");
+				lwsl_wsi_info(wsi, "closing from ext access");
 				return -1;
 			}
 
@@ -292,8 +292,7 @@ lws_issue_raw_ext_access(struct lws *wsi, unsigned char *buf, size_t len)
 			if (wsi->ws->clean_buffer)
 				len = (size_t)n;
 
-			lwsl_ext("%s: written %d bytes to client\n",
-				 __func__, n);
+			lwsl_wsi_ext(wsi, "written %d bytes to client", n);
 		}
 
 		/* no extension has more to spill?  Then we can go */
@@ -315,7 +314,7 @@ lws_issue_raw_ext_access(struct lws *wsi, unsigned char *buf, size_t len)
 			/* no we could add more, lets's do that */
 			continue;
 
-		lwsl_debug("choked\n");
+		lwsl_wsi_debug(wsi, "choked");
 
 		/*
 		 * Yes, he's choked.  Don't spill the rest now get a callback