he-debug

Author: lws-team

lib/core-net/client/connect3.c

@@ -69,7 +69,7 @@ lws_client_happy_eyeballs_cb(lws_sorted_usec_list_t *sul)
 	struct lws *wsi = lws_container_of(sul, struct lws,
 					   sul_happy_eyeballs);
 
-	lwsl_wsi_info(wsi, "happy eyeballs timer fired, initiating parallel connect");
+	lwsl_wsi_notice(wsi, "happy eyeballs timer fired, initiating parallel connect");
 	lws_client_connect_3_connect(wsi, NULL, NULL, 0, NULL);
 }
 
@@ -578,6 +578,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 				}
 				lws_sul_cancel(&wsi->sul_happy_eyeballs);
 				if (pidx != -1) {
+					lwsl_wsi_notice(wsi, "racing connect %d won, promoting", pidx);
 					/*
 					 * A racing connect won.  The primary
 					 * socket is still open and still in the
@@ -640,7 +641,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 				lws_snprintf(dcce, sizeof(dcce), "conn fail: %s",
 					     lws_errno_describe(real_errno, t16, sizeof(t16)));
 				cce = dcce;
-				lwsl_wsi_debug(wsi, "%s", dcce);
+				lwsl_wsi_notice(wsi, "%s", dcce);
 				lws_metrics_caliper_report(wsi->cal_conn, METRES_NOGO);
 
 				if (pidx != -1) {
@@ -674,6 +675,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 							 * kernel recycles the fd
 							 * numbers.
 							 */
+							lwsl_wsi_notice(wsi, "primary failed, promoting parallel racer %d", m);
 							if (wsi->a.context->event_loop_ops->promote_parallel)
 								wsi->a.context->event_loop_ops->promote_parallel(wsi, m);
 							promote_parallel_fd(wsi, m);
@@ -1081,7 +1083,8 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 		char buf[64];
 
 		lws_sa46_write_numeric_address((lws_sockaddr46 *)psa, buf, sizeof(buf));
-		lwsl_wsi_info(wsi, "trying %s", buf);
+		lwsl_wsi_notice(wsi, "trying %s%s", buf,
+				 is_parallel ? " (parallel racer)" : "");
 	}
 
 #if defined(LWS_WITH_SYS_FAULT_INJECTION)
@@ -1180,6 +1183,8 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 			}
 #endif
 #endif
+			if (is_parallel)
+				lwsl_wsi_notice(wsi, "parallel racer failed connect() synchronously");
 			goto try_next_dns_result_fds;
 		}
 
@@ -1311,6 +1316,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 
 	if (is_parallel) {
 		/* promote parallel to primary right away */
+		lwsl_wsi_notice(wsi, "parallel racer %d connected synchronously, promoting", pidx);
 		wsi->parallel_conns[pidx].position_in_fds_table = wsi->position_in_fds_table;
 		wsi->position_in_fds_table = saved_pos;
 		wsi->desc = saved_fd;
@@ -1412,7 +1418,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 		wsi->a.protocol->callback(wsi, LWS_CALLBACK_WSI_CREATE,
 					  wsi->user_space, NULL, 0);
 
-	lwsl_wsi_debug(wsi, "going into connect_4");
+	lwsl_wsi_notice(wsi, "going into connect_4");
 
 	return lws_client_connect_4_established(wsi, NULL, plen);
 
@@ -1518,6 +1524,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads,
 		}
 		if (any_valid) {
 			/* some connection is still running */
+			lwsl_wsi_notice(wsi, "attempt failed, others still running");
 			return wsi;
 		}
 	}

lib/core-net/close.c

@@ -818,8 +818,11 @@ __lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason,
 	     !wsi->close_is_redirect) {
 		static const char _reason[] = "closed before established";
 
-		lwsl_wsi_debug(wsi, "closing in unestablished state 0x%x",
-				lwsi_state(wsi));
+		lwsl_wsi_notice(wsi, "closing in unestablished state 0x%x "
+				"(fd %d, parallels %d, redirect %d)",
+				lwsi_state(wsi),
+				(int)wsi->desc.sockfd, wsi->parallel_count,
+				wsi->close_is_redirect);
 		wsi->socket_is_permanently_unusable = 1;
 
 		lws_inform_client_conn_fail(wsi,

lib/roles/h1/ops-h1.c

@@ -789,8 +789,23 @@ rops_handle_POLLIN_h1(struct lws_context_per_thread *pt, struct lws *wsi,
 #endif
 
 	if (lwsi_state(wsi) == LRS_WAITING_CONNECT &&
-	    (pollfd->revents & LWS_POLLHUP))
-		return LWS_HPI_RET_PLEASE_CLOSE_ME;
+	    (pollfd->revents & LWS_POLLHUP)) {
+		/*
+		 * This fd's connect attempt failed.  But if we are racing
+		 * parallel connect attempts, the failing fd may only be the
+		 * primary while a racer is still live and able to win.
+		 *
+		 * Let connect_3 disposition the failed attempt (promoting a
+		 * live racer, or trying the next dns result, or informing
+		 * the connect failure if nothing is left) rather than
+		 * killing the whole wsi here.
+		 */
+		if (!lws_client_connect_3_connect(wsi, NULL, NULL, 0, pollfd))
+			/* the wsi was synchronously closed and freed */
+			return LWS_HPI_RET_WSI_ALREADY_DIED;
+
+		return LWS_HPI_RET_HANDLED;
+	}
 
 	return LWS_HPI_RET_HANDLED;
 }

lib/roles/http/client/client-http.c

@@ -71,7 +71,13 @@ 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)
+		/*
+		 * A hangup or error here means this fd's attempt failed;
+		 * disposition it via connect_3 so any parallel racing
+		 * attempt on the same wsi can still be promoted instead of
+		 * being lost when the wsi is killed
+		 */
+		if (pollfd->revents & (LWS_POLLOUT | LWS_POLLHUP))
 			if (lws_client_connect_3_connect(wsi, NULL, NULL, 0, pollfd) == NULL) {
 				lwsl_client("closed\\n");
 				return LWS_HPI_RET_WSI_ALREADY_DIED;