lws logging patch

gistfile1.txt

---
 include/libwebsockets/lws-logs.h    | 17 ++++-------
 lib/core-net/client/connect.c       |  7 +++--
 lib/core-net/client/connect3.c      | 23 +++++++++------
 lib/core-net/close.c                |  3 +-
 lib/core-net/pollfd.c               | 21 ++++++++++----
 lib/core-net/service.c              | 20 +++++++------
 lib/plat/windows/windows-service.c  | 44 +++++++++++++++++++----------
 lib/plat/windows/windows-sockets.c  |  2 +-
 lib/roles/h1/ops-h1.c               |  8 ++++--
 lib/roles/http/client/client-http.c |  9 ++++--
 10 files changed, 97 insertions(+), 57 deletions(-)

diff --git a/include/libwebsockets/lws-logs.h b/include/libwebsockets/lws-logs.h
index 795ba55c..718cb137 100644
--- a/include/libwebsockets/lws-logs.h
+++ b/include/libwebsockets/lws-logs.h
@@ -210,17 +210,12 @@ _lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
  /*
   * In DEBUG build, select all logs unless NO_LOGS
   */
- #if defined(LWS_WITH_NO_LOGS)
-  #define _LWS_LINIT (LLL_ERR | LLL_USER)
- #else
-   #define _LWS_LINIT ((1 << LLL_COUNT) - 1)
- #endif
+#define _LWS_LINIT ((1 << LLL_COUNT) - 1)
+
 #else /* not _DEBUG */
-#if defined(LWS_WITH_NO_LOGS)
-#define _LWS_LINIT (LLL_ERR | LLL_USER)
-#else
- #define _LWS_LINIT (LLL_ERR | LLL_USER | LLL_WARN | LLL_NOTICE)
-#endif
+
+#define _LWS_LINIT ((1 << LLL_COUNT) - 1)
+
 #endif /* _DEBUG */
 
 /*
@@ -247,7 +242,7 @@ _lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
 /*
  * Compute the final active logging bitfield for build
  */
-#define _LWS_ENABLED_LOGS (((_LWS_LINIT) | (_LWS_LBS)) & ~(_LWS_LBC))
+#define _LWS_ENABLED_LOGS ((_LWS_LINIT))
 
 /*
  * Individually enable or disable log levels for build
diff --git a/lib/core-net/client/connect.c b/lib/core-net/client/connect.c
index 23c4c367..ae650cf5 100644
--- a/lib/core-net/client/connect.c
+++ b/lib/core-net/client/connect.c
@@ -228,7 +228,7 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i)
 	 * caller without needing to call through to protocol CONNECTION_ERROR.
 	 */
 	wsi->client_suppress_CONNECTION_ERROR = 1;
-
+  lwsl_wsi_info(wsi, "xxxxxxxxxx supressing connection errors");
 	if (i->keep_warm_secs)
 		wsi->keep_warm_secs = i->keep_warm_secs;
 	else
@@ -520,9 +520,10 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i)
 		/*
 		 * If it subsequently fails, report CONNECTION_ERROR,
 		 * because we're going to return a non-error return now.
-		 */
+		 */{
 		wsi->client_suppress_CONNECTION_ERROR = 0;
-
+    lwsl_wsi_info(wsi, "xxxxxxxxxx unsupressing connection errors");
+  }
 	return wsi;
 
 #if defined(LWS_WITH_TLS)
diff --git a/lib/core-net/client/connect3.c b/lib/core-net/client/connect3.c
index a9d2e9e0..294ff227 100644
--- a/lib/core-net/client/connect3.c
+++ b/lib/core-net/client/connect3.c
@@ -116,11 +116,14 @@ lws_client_connect_check(struct lws *wsi, int *real_errno)
 
 	en = LWS_ERRNO;
 
-	if (en == WSAEISCONN) /* already connected */
+	if (en == WSAEISCONN) {/* already connected */
+    lwsl_wsi_info(wsi, "xxxx WSAEISCONN");
 		return LCCCR_CONNECTED;
+  }
 
 	if (en == WSAEALREADY) {
-		/* reset the POLLOUT wait */
+		lwsl_wsi_info(wsi, "xxxx WSAEALREADY");
+    /* reset the POLLOUT wait */
 		if (lws_change_pollfd(wsi, 0, LWS_POLLOUT))
 			lwsl_wsi_notice(wsi, "pollfd failed");
 	}
@@ -128,12 +131,12 @@ lws_client_connect_check(struct lws *wsi, int *real_errno)
 	if (!en || en == WSAEINVAL ||
 		   en == WSAEWOULDBLOCK ||
 		   en == WSAEALREADY) {
-		lwsl_wsi_debug(wsi, "errno %d", en);
+		lwsl_wsi_info(wsi, "errno %d", en);
 		return LCCCR_CONTINUE;
 	}
 #endif
 
-	lwsl_wsi_notice(wsi, "connect check FAILED: %d",
+	lwsl_wsi_info(wsi, "connect check FAILED: %d",
 			*real_errno || en);
 
 	return LCCCR_FAILED;
@@ -253,8 +256,10 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 			/*
 			 * Oh, it has happened...
 			 */
+      lwsl_wsi_warn(wsi, "xxxx connected");
 			goto conn_good;
 		case LCCCR_CONTINUE:
+      lwsl_wsi_warn(wsi, "xxxx continue");
 			return NULL;
 		default:
 			if (!real_errno)
@@ -263,7 +268,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 				     real_errno);
 
 			cce = dcce;
-			lwsl_wsi_debug(wsi, "%s", dcce);
+			lwsl_wsi_warn(wsi, "%s", dcce);
 			lws_metrics_caliper_report(wsi->cal_conn, METRES_NOGO);
 			goto try_next_dns_result_fds;
 		}
@@ -512,7 +517,7 @@ ads_known:
 #endif
 		m = connect(wsi->desc.sockfd, (const struct sockaddr *)psa,
 			    (socklen_t)n);
-
+    lwsl_wsi_warn(wsi, "xxxxxxx connect %d", m);
 #if defined(LWS_WITH_CONMON)
 	wsi->conmon_datum = lws_now_usecs();
 	wsi->conmon.ciu_sockconn = 0;
@@ -590,7 +595,7 @@ ads_known:
 #if defined(WIN32)
 		if (lws_plat_check_connection_error(wsi))
 			goto try_next_dns_result_fds;
-
+    lwsl_wsi_info(wsi, "xxxxxxxxxx errno copy %d", errno_copy);
 		if (errno_copy == WSAEISCONN)
 			goto conn_good;
 #endif
@@ -610,8 +615,10 @@ ads_known:
 		 * must do specifically a POLLOUT poll to hear
 		 * about the connect completion
 		 */
-		if (lws_change_pollfd(wsi, 0, LWS_POLLOUT))
+		if (lws_change_pollfd(wsi, 0, LWS_POLLOUT)) {
+      lwsl_wsi_info(wsi, "xxxxxxxxxx plloout failed");
 			goto try_next_dns_result_fds;
+    }
 
 		return wsi;
 	}
diff --git a/lib/core-net/close.c b/lib/core-net/close.c
index a8dd7209..286fdf42 100644
--- a/lib/core-net/close.c
+++ b/lib/core-net/close.c
@@ -306,7 +306,7 @@ void
 lws_inform_client_conn_fail(struct lws *wsi, void *arg, size_t len)
 {
 	lws_addrinfo_clean(wsi);
-
+  lwsl_wsi_info(wsi, "xxxxxxxxxx already_did_cce");
 	if (wsi->already_did_cce)
 		return;
 
@@ -315,6 +315,7 @@ lws_inform_client_conn_fail(struct lws *wsi, void *arg, size_t len)
 	if (!wsi->a.protocol)
 		return;
 
+  if (wsi->client_suppress_CONNECTION_ERROR) lwsl_wsi_info(wsi, "xxxxxxxxxx supressed connection errors");
 	if (!wsi->client_suppress_CONNECTION_ERROR)
 		wsi->a.protocol->callback(wsi,
 					LWS_CALLBACK_CLIENT_CONNECTION_ERROR,
diff --git a/lib/core-net/pollfd.c b/lib/core-net/pollfd.c
index dea85aec..c486b8a5 100644
--- a/lib/core-net/pollfd.c
+++ b/lib/core-net/pollfd.c
@@ -36,18 +36,23 @@ _lws_change_pollfd(struct lws *wsi, int _and, int _or, struct lws_pollargs *pa)
 	struct lws_pollfd *pfd;
 	int sampled_tid, tid;
 
-	if (!wsi)
+	if (!wsi) {
+    lwsl_wsi_info(wsi, "_lws_change_pollfd no wsi");
 		return 0;
+  }
 
 	assert(wsi->position_in_fds_table == LWS_NO_FDS_POS ||
 	       wsi->position_in_fds_table >= 0);
 
-	if (wsi->position_in_fds_table == LWS_NO_FDS_POS)
+	if (wsi->position_in_fds_table == LWS_NO_FDS_POS) {
+    lwsl_wsi_info(wsi, "_lws_change_pollfd LWS_NO_FDS_POS");
 		return 0;
+  }
 
 	if (((volatile struct lws *)wsi)->handling_pollout &&
 	    !_and && _or == LWS_POLLOUT) {
-		/*
+		lwsl_wsi_info(wsi, "_lws_change_pollfd !and or or == lws pollout");
+    /*
 		 * Happening alongside service thread handling POLLOUT.
 		 * The danger is when he is finished, he will disable POLLOUT,
 		 * countermanding what we changed here.
@@ -477,12 +482,16 @@ __lws_change_pollfd(struct lws *wsi, int _and, int _or)
 	int ret = 0;
 
 	if (!wsi || (!wsi->a.protocol && !wsi->event_pipe) ||
-	    wsi->position_in_fds_table == LWS_NO_FDS_POS)
+	    wsi->position_in_fds_table == LWS_NO_FDS_POS) {
+    lwsl_wsi_info(wsi, "xxxx __lws_change_pollfd no position_in_fds_table");
 		return 0;
+  }
 
 	context = lws_get_context(wsi);
-	if (!context)
+	if (!context) {
+    lwsl_wsi_info(wsi, "xxxx __lws_change_pollfd no context");
 		return 1;
+  }
 
 #if defined(LWS_WITH_EXTERNAL_POLL)
 	if (wsi->a.vhost &&
@@ -510,7 +519,7 @@ lws_change_pollfd(struct lws *wsi, int _and, int _or)
 	int ret = 0;
 
 	pt = &wsi->a.context->pt[(int)wsi->tsi];
-
+  lwsl_wsi_info(wsi, "xxxx lws_change_pollfd and %d or %d", _and, _or);
 	lws_pt_lock(pt, __func__);
 	ret = __lws_change_pollfd(wsi, _and, _or);
 	lws_pt_unlock(pt);
diff --git a/lib/core-net/service.c b/lib/core-net/service.c
index 02e4c05e..a5246872 100644
--- a/lib/core-net/service.c
+++ b/lib/core-net/service.c
@@ -536,7 +536,7 @@ lws_service_do_ripe_rxflow(struct lws_context_per_thread *pt)
 		pfd.revents = LWS_POLLIN;
 		pfd.fd = -1;
 
-		lwsl_wsi_debug(wsi, "rxflow processing: fc=%d, 0x%lx",
+		lwsl_wsi_notice(wsi, "rxflow processing: fc=%d, 0x%lx",
 				    lws_is_flowcontrolled(wsi),
 				    (unsigned long)wsi->wsistate);
 
@@ -717,8 +717,10 @@ lws_service_fd_tsi(struct lws_context *context, struct lws_pollfd *pollfd,
 	}
 
 #ifdef _WIN32
-	if (pollfd->revents & LWS_POLLOUT)
+	if (pollfd->revents & LWS_POLLOUT) {
+    lwsl_notice("xxxxxxx %s, sock_send_blocking\n", __func__);
 		wsi->sock_send_blocking = FALSE;
+  }
 #endif
 
 #if defined(LWS_WITH_TLS)
@@ -739,7 +741,8 @@ lws_service_fd_tsi(struct lws_context *context, struct lws_pollfd *pollfd,
 
 	if ((pollfd->revents & LWS_POLLOUT) == LWS_POLLOUT &&
 	    wsi->tls_read_wanted_write) {
-		/*
+		lwsl_notice("xxxxxxx %s pollfd->revents & LWS_POLLOUT) == LWS_POLLOUT && wsi->tls_read_wanted_write\n", __func__);
+    /*
 		 * If this wsi has a pending WANT_WRITE from SSL_read(), it has
 		 * asked for a callback on writeable so it can retry the read.
 		 *
@@ -760,21 +763,22 @@ lws_service_fd_tsi(struct lws_context *context, struct lws_pollfd *pollfd,
 	/* if we got here, we should have wire protocol ops set on the wsi */
 	assert(wsi->role_ops);
 
-	// lwsl_notice("%s: %s: wsistate 0x%x\n", __func__, wsi->role_ops->name,
-	//	    wsi->wsistate);
+	 lwsl_info("xxxxxxx %s: %s: wsistate 0x%x\n", __func__, wsi->role_ops->name,
+		    wsi->wsistate);
 
 	switch (lws_rops_func_fidx(wsi->role_ops, LWS_ROPS_handle_POLLIN).
 					       handle_POLLIN(pt, wsi, pollfd)) {
 	case LWS_HPI_RET_WSI_ALREADY_DIED:
 		pt->inside_lws_service = 0;
+    lwsl_info("xxxxxxx %s, LWS_HPI_RET_WSI_ALREADY_DIED\n", __func__);
 		return 1;
 	case LWS_HPI_RET_HANDLED:
 		break;
 	case LWS_HPI_RET_PLEASE_CLOSE_ME:
-		//lwsl_notice("%s: %s pollin says please close me\n", __func__,
-		//		wsi->role_ops->name);
+		lwsl_info("xxxxx %s: %s pollin says please close me\n", __func__,
+				wsi->role_ops->name);
 close_and_handled:
-		lwsl_wsi_debug(wsi, "Close and handled");
+		lwsl_wsi_info(wsi, "Close and handled");
 		lws_close_free_wsi(wsi, LWS_CLOSE_STATUS_NOSTATUS,
 				   "close_and_handled");
 #if defined(_DEBUG) && defined(LWS_WITH_LIBUV)
diff --git a/lib/plat/windows/windows-service.c b/lib/plat/windows/windows-service.c
index b56ef43d..5c8ce96e 100644
--- a/lib/plat/windows/windows-service.c
+++ b/lib/plat/windows/windows-service.c
@@ -38,7 +38,8 @@ _lws_plat_service_forced_tsi(struct lws_context *context, int tsi)
 
 	/* any socket with events to service? */
 	for (n = 0; n < (int)pt->fds_count; n++) {
-		if (!pt->fds[n].revents)
+
+    if (!pt->fds[n].revents)
 			continue;
 
                unsigned int fds_count = pt->fds_count;
@@ -97,29 +98,38 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi)
 
 	for (i = 0; i < pt->fds_count; ++i) {
 		pfd = &pt->fds[i];
-
+    lwsl_info("%s: xxxx first events checking \n", __func__);
 		if (!(pfd->events & LWS_POLLOUT))
 			continue;
-
+    lwsl_info("%s: xxxx first events checking, was pollout \n", __func__);
 		wsi = wsi_from_fd(context, pfd->fd);
-		if (!wsi || wsi->listener)
+		if (!wsi || wsi->listener) {
+      lwsl_info("%s: xxxx first events checking, was pollout, skipped 1 \n", __func__);
 			continue;
-		if (wsi->sock_send_blocking)
+    }
+		if (wsi->sock_send_blocking) {
+      lwsl_info("%s: xxxx first events checking, was pollout, skipped 2 \n", __func__);
 			continue;
+    }
 		pfd->revents = LWS_POLLOUT;
 		n = lws_service_fd(context, pfd);
-		if (n < 0)
+		if (n < 0) {
+      lwsl_info("%s: xxxx first events checking, was pollout, skipped 3 \n", __func__);
 			return -1;
+    }
 
 		/*
 		 * Force WSAWaitForMultipleEvents() to check events
 		 * and then return immediately.
 		 */
+    lwsl_info("%s: xxxx first events checking, was pollout, skipped 4, timeout 0 now \n", __func__);
 		timeout_us = 0;
 
 		/* if something closed, retry this slot */
-		if (n)
+		if (n) {
+      lwsl_info("%s: xxxx first events checking, was pollout, retriying slot %d \n", __func__, i);
 			i--;
+    }
 	}
 
 	/*
@@ -145,25 +155,29 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi)
 		lws_pt_unlock(pt);
 	}
 
-	if (_lws_plat_service_forced_tsi(context, tsi))
+	if (_lws_plat_service_forced_tsi(context, tsi)) {
+    lwsl_info("%s: xxxx _lws_plat_service_forced_tsi: adjusting timeout \n", __func__);
 		timeout_us = 0;
+  }
 
 	/*
 	 * is there anybody with pending stuff that needs service forcing?
 	 */
 
-	if (!lws_service_adjust_timeout(context, 1, tsi))
+	if (!lws_service_adjust_timeout(context, 1, tsi)) {
+    lwsl_info("%s: xxxx lws_service_adjust_timeout: adjusting timeout \n", __func__);
 		timeout_us = 0;
-
-//	lwsl_notice("%s: in %dms, count %d\n", __func__, (int)(timeout_us / 1000), pt->fds_count);
-//	for (n = 0; n < (int)pt->fds_count; n++)
-//		lwsl_notice("%s: fd %d ev 0x%x POLLIN %d, POLLOUT %d\n", __func__, (int)pt->fds[n].fd, (int)pt->fds[n].events, POLLIN, POLLOUT);
+  }
+  lwsl_info("%s: xxxxxxx in %dms, count %d\n", __func__, (int)(timeout_us / 1000), pt->fds_count);
+  lwsl_notice("%s: in %dms, count %d\n", __func__, (int)(timeout_us / 1000), pt->fds_count);
+	for (n = 0; n < (int)pt->fds_count; n++)
+		lwsl_notice("%s: fd %d ev 0x%x POLLIN %d, POLLOUT %d\n", __func__, (int)pt->fds[n].fd, (int)pt->fds[n].events, POLLIN, POLLOUT);
 	int d = WSAPoll((WSAPOLLFD *)&pt->fds[0], pt->fds_count, (int)(timeout_us / LWS_US_PER_MS));
 	if (d < 0) {
 		lwsl_err("%s: WSAPoll failed: count %d, err %d: %d\n", __func__, pt->fds_count, d, WSAGetLastError());
 		return 0;
 	}
-//	lwsl_notice("%s: out\n", __func__);
+  lwsl_notice("%s: out\n", __func__);
 
 #if defined(LWS_WITH_TLS)
 	if (pt->context->tls_ops &&
@@ -173,7 +187,7 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi)
 
 	for (n = 0; n < (int)pt->fds_count; n++)
 		if (pt->fds[n].fd != LWS_SOCK_INVALID && pt->fds[n].revents) {
-//			lwsl_notice("%s: idx %d, revents 0x%x\n", __func__, n, pt->fds[n].revents);
+      lwsl_notice("%s: idx %d, revents 0x%x\n", __func__, n, pt->fds[n].revents);
 			lws_service_fd_tsi(context, &pt->fds[n], tsi);
 		}
 
diff --git a/lib/plat/windows/windows-sockets.c b/lib/plat/windows/windows-sockets.c
index ba0de92c..982deae1 100644
--- a/lib/plat/windows/windows-sockets.c
+++ b/lib/plat/windows/windows-sockets.c
@@ -232,7 +232,7 @@ lws_plat_check_connection_error(struct lws *wsi)
 		   lwsl_debug("Connect failed SO_ERROR=%d\n", optVal);
 		   return 1;
 	}
-
+  lwsl_info("xxxxxxxxxx plat check conn succeded %d\n", optVal);
 	return 0;
 }
 
diff --git a/lib/roles/h1/ops-h1.c b/lib/roles/h1/ops-h1.c
index 769490fe..78c3280a 100644
--- a/lib/roles/h1/ops-h1.c
+++ b/lib/roles/h1/ops-h1.c
@@ -698,13 +698,17 @@ rops_handle_POLLIN_h1(struct lws_context_per_thread *pt, struct lws *wsi,
 		return LWS_HPI_RET_PLEASE_CLOSE_ME;
 	}
 
-	if (lws_http_client_socket_service(wsi, pollfd))
+	if (lws_http_client_socket_service(wsi, pollfd)) {
+    lwsl_warn("xxxx LWS_HPI_RET_WSI_ALREADY_DIED\n");
 		return LWS_HPI_RET_WSI_ALREADY_DIED;
+  }
 #endif
 
 	if (lwsi_state(wsi) == LRS_WAITING_CONNECT &&
-	    (pollfd->revents & LWS_POLLHUP))
+	    (pollfd->revents & LWS_POLLHUP)) {
+    lwsl_warn("xxxx LWS_HPI_RET_PLEASE_CLOSE_ME\n");
 		return LWS_HPI_RET_PLEASE_CLOSE_ME;
+  }
 
 	return LWS_HPI_RET_HANDLED;
 }
diff --git a/lib/roles/http/client/client-http.c b/lib/roles/http/client/client-http.c
index 16fd8b24..e8fba976 100644
--- a/lib/roles/http/client/client-http.c
+++ b/lib/roles/http/client/client-http.c
@@ -66,11 +66,16 @@ 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
 		 */
-		if (pollfd->revents & LWS_POLLOUT)
-			if (lws_client_connect_3_connect(wsi, NULL, NULL, 0, NULL) == NULL) {
+    lwsl_warn("xxxx LRS_WAITING_CONNECT %d %d %d\n", pollfd->revents, pollfd->revents & LWS_POLLOUT, LWS_POLLOUT);
+		if (pollfd->revents & LWS_POLLOUT) {
+      struct lws* wsio = lws_client_connect_3_connect(wsi, NULL, NULL, 0, NULL);
+      lwsl_warn("xxxx LRS_WAITING_CONNECT inside %p \n", wsio);
+
+      if (wsio == NULL) {
 				lwsl_client("closed\n");
 				return -1;
 			}
+    }
 		break;
 
 #if defined(LWS_WITH_SOCKS5)
-- 
2.32.0 (Apple Git-132)