[Fix] Add debug to ssl, fixed write hangs

5 files changed, 106 insertions, 50 deletions

diff --git a/src/libutil/http_connection.c b/src/libutil/http_connection.c
index d653758cf..094438ee6 100644
--- a/src/libutil/http_connection.c
+++ b/src/libutil/http_connection.c
@@ -2222,7 +2222,8 @@ rspamd_http_connection_write_message_common (struct rspamd_http_connection *conn
 			}
 
 			priv->ssl = rspamd_ssl_connection_new (ssl_ctx, priv->ctx->event_loop,
-					!(msg->flags & RSPAMD_HTTP_FLAG_SSL_NOVERIFY));
+					!(msg->flags & RSPAMD_HTTP_FLAG_SSL_NOVERIFY),
+					conn->log_tag);
 			g_assert (priv->ssl != NULL);
 
 			if (!rspamd_ssl_connect_fd (priv->ssl, conn->fd, host, &priv->ev,
diff --git a/src/libutil/http_connection.h b/src/libutil/http_connection.h
index 1923e5953..b90d0125a 100644
--- a/src/libutil/http_connection.h
+++ b/src/libutil/http_connection.h
@@ -111,6 +111,7 @@ struct rspamd_http_connection {
 	rspamd_http_error_handler_t error_handler;
 	rspamd_http_finish_handler_t finish_handler;
 	gpointer ud;
+	const gchar *log_tag;
 	/* Used for keepalive */
 	struct rspamd_keepalive_hash_key *keepalive_hash_key;
 	gsize max_size;
diff --git a/src/libutil/ssl_util.c b/src/libutil/ssl_util.c
index 62e22a3c6..32778f265 100644
--- a/src/libutil/ssl_util.c
+++ b/src/libutil/ssl_util.c
@@ -47,6 +47,7 @@ struct rspamd_ssl_connection {
 	gboolean verify_peer;
 	SSL *ssl;
 	gchar *hostname;
+	const gchar *log_tag;
 	struct rspamd_io_ev *ev;
 	struct ev_loop *event_loop;
 	rspamd_ssl_handler_t handler;
@@ -54,6 +55,13 @@ struct rspamd_ssl_connection {
 	gpointer handler_data;
 };
 
+#define msg_debug_ssl(...)  rspamd_conditional_debug_fast (NULL, NULL, \
+        rspamd_ssl_log_id, "ssl", conn->log_tag, \
+        G_STRFUNC, \
+        __VA_ARGS__)
+
+INIT_LOG_MODULE(ssl)
+
 static GQuark
 rspamd_ssl_quark (void)
 {
@@ -421,6 +429,7 @@ rspamd_ssl_shutdown (struct rspamd_ssl_connection *conn)
 
 	if ((ret = SSL_shutdown (conn->ssl)) == 1) {
 		/* All done */
+		msg_debug_ssl ("ssl shutdown: all done");
 		rspamd_ssl_connection_dtor (conn);
 	}
 	else {
@@ -430,13 +439,16 @@ rspamd_ssl_shutdown (struct rspamd_ssl_connection *conn)
 		conn->state = ssl_next_shutdown;
 
 		if (ret == SSL_ERROR_WANT_READ) {
+			msg_debug_ssl ("ssl shutdown: need read");
 			what = EV_READ;
 		}
 		else if (ret == SSL_ERROR_WANT_WRITE) {
+			msg_debug_ssl ("ssl shutdown: need read");
 			what = EV_WRITE;
 		}
 		else {
 			/* Cannot do anything else, fatal error */
+			msg_debug_ssl ("ssl shutdown: fatal error");
 			rspamd_ssl_connection_dtor (conn);
 
 			return;
@@ -451,89 +463,93 @@ rspamd_ssl_shutdown (struct rspamd_ssl_connection *conn)
 static void
 rspamd_ssl_event_handler (gint fd, short what, gpointer ud)
 {
-	struct rspamd_ssl_connection *c = ud;
+	struct rspamd_ssl_connection *conn = ud;
 	gint ret;
 	GError *err = NULL;
 
 	if (what == EV_TIMER) {
-		if (c->state == ssl_next_shutdown) {
+		if (conn->state == ssl_next_shutdown) {
 			/* No way to restore, just terminate */
-			rspamd_ssl_connection_dtor (c);
+			rspamd_ssl_connection_dtor (conn);
 		}
 		else {
-			c->shut = ssl_shut_unclean;
-			rspamd_ev_watcher_stop (c->event_loop, c->ev);
+			conn->shut = ssl_shut_unclean;
+			rspamd_ev_watcher_stop (conn->event_loop, conn->ev);
 			g_set_error (&err, rspamd_ssl_quark (), ETIMEDOUT,
 					"ssl connection timed out");
-			c->err_handler (c->handler_data, err);
+			conn->err_handler (conn->handler_data, err);
 			g_error_free (err);
 		}
 
 		return;
 	}
 
-	msg_debug ("ssl event; what=%d; c->state=%d", (int)what, (int)c->state);
+	msg_debug_ssl ("ssl event; what=%d; c->state=%d", (int)what,
+			(int)conn->state);
 
-	switch (c->state) {
+	switch (conn->state) {
 	case ssl_conn_init:
 		/* Continue connection */
-		ret = SSL_connect (c->ssl);
+		ret = SSL_connect (conn->ssl);
 
 		if (ret == 1) {
-			rspamd_ev_watcher_stop (c->event_loop, c->ev);
+			rspamd_ev_watcher_stop (conn->event_loop, conn->ev);
 			/* Verify certificate */
-			if ((!c->verify_peer) || rspamd_ssl_peer_verify (c)) {
-				c->state = ssl_conn_connected;
-				c->handler (fd, EV_WRITE, c->handler_data);
+			if ((!conn->verify_peer) || rspamd_ssl_peer_verify (conn)) {
+				msg_debug_ssl ("ssl connect: connected");
+				conn->state = ssl_conn_connected;
+				conn->handler (fd, EV_WRITE, conn->handler_data);
 			}
 			else {
 				return;
 			}
 		}
 		else {
-			ret = SSL_get_error (c->ssl, ret);
+			ret = SSL_get_error (conn->ssl, ret);
 
 			if (ret == SSL_ERROR_WANT_READ) {
+				msg_debug_ssl ("ssl connect: need read");
 				what = EV_READ;
 			}
 			else if (ret == SSL_ERROR_WANT_WRITE) {
+				msg_debug_ssl ("ssl connect: need write");
 				what = EV_WRITE;
 			}
 			else {
-				rspamd_ev_watcher_stop (c->event_loop, c->ev);
+				rspamd_ev_watcher_stop (conn->event_loop, conn->ev);
 				rspamd_tls_set_error (ret, "connect", &err);
-				c->err_handler (c->handler_data, err);
+				conn->err_handler (conn->handler_data, err);
 				g_error_free (err);
 				return;
 			}
 
-			rspamd_ev_watcher_reschedule (c->event_loop, c->ev, what);
+			rspamd_ev_watcher_reschedule (conn->event_loop, conn->ev, what);
 
 		}
 		break;
 	case ssl_next_read:
-		rspamd_ev_watcher_reschedule (c->event_loop, c->ev, EV_READ);
-		c->state = ssl_conn_connected;
-		c->handler (fd, EV_READ, c->handler_data);
+		rspamd_ev_watcher_reschedule (conn->event_loop, conn->ev, EV_READ);
+		conn->state = ssl_conn_connected;
+		conn->handler (fd, EV_READ, conn->handler_data);
 		break;
 	case ssl_next_write:
-		rspamd_ev_watcher_reschedule (c->event_loop, c->ev, EV_WRITE);
-		c->state = ssl_conn_connected;
-		c->handler (fd, EV_WRITE, c->handler_data);
+		rspamd_ev_watcher_reschedule (conn->event_loop, conn->ev, EV_WRITE);
+		conn->state = ssl_conn_connected;
+		conn->handler (fd, EV_WRITE, conn->handler_data);
 		break;
 	case ssl_conn_connected:
-		rspamd_ev_watcher_reschedule (c->event_loop, c->ev, what);
-		c->state = ssl_conn_connected;
-		c->handler (fd, what, c->handler_data);
+		rspamd_ev_watcher_reschedule (conn->event_loop, conn->ev, what);
+		conn->state = ssl_conn_connected;
+		conn->handler (fd, what, conn->handler_data);
 		break;
 	case ssl_next_shutdown:
-		rspamd_ssl_shutdown (c);
+		rspamd_ssl_shutdown (conn);
 		break;
 	default:
-		rspamd_ev_watcher_stop (c->event_loop, c->ev);
+		rspamd_ev_watcher_stop (conn->event_loop, conn->ev);
 		g_set_error (&err, rspamd_ssl_quark (), EINVAL,
-				"ssl bad state error: %d", c->state);
-		c->err_handler (c->handler_data, err);
+				"ssl bad state error: %d", conn->state);
+		conn->err_handler (conn->handler_data, err);
 		g_error_free (err);
 		break;
 	}
@@ -541,7 +557,7 @@ rspamd_ssl_event_handler (gint fd, short what, gpointer ud)
 
 struct rspamd_ssl_connection *
 rspamd_ssl_connection_new (gpointer ssl_ctx, struct ev_loop *ev_base,
-		gboolean verify_peer)
+		gboolean verify_peer, const gchar *log_tag)
 {
 	struct rspamd_ssl_connection *c;
 
@@ -550,6 +566,7 @@ rspamd_ssl_connection_new (gpointer ssl_ctx, struct ev_loop *ev_base,
 	c->ssl = SSL_new (ssl_ctx);
 	c->event_loop = ev_base;
 	c->verify_peer = verify_peer;
+	c->log_tag = log_tag;
 
 	return c;
 }
@@ -603,6 +620,7 @@ rspamd_ssl_connect_fd (struct rspamd_ssl_connection *conn, gint fd,
 	if (ret == 1) {
 		conn->state = ssl_conn_connected;
 
+		msg_debug_ssl ("connected, start write event");
 		rspamd_ev_watcher_stop (conn->event_loop, ev);
 		rspamd_ev_watcher_init (ev, fd, EV_WRITE, rspamd_ssl_event_handler, conn);
 		rspamd_ev_watcher_start (conn->event_loop, ev, timeout);
@@ -611,13 +629,16 @@ rspamd_ssl_connect_fd (struct rspamd_ssl_connection *conn, gint fd,
 		ret = SSL_get_error (conn->ssl, ret);
 
 		if (ret == SSL_ERROR_WANT_READ) {
+			msg_debug_ssl ("not connected, want read");
 			what = EV_READ;
 		}
 		else if (ret == SSL_ERROR_WANT_WRITE) {
+			msg_debug_ssl ("not connected, want write");
 			what = EV_WRITE;
 		}
 		else {
 			conn->shut = ssl_shut_unclean;
+			msg_debug_ssl ("not connected, fatal error %d", ret);
 
 			return FALSE;
 		}
@@ -653,6 +674,7 @@ rspamd_ssl_read (struct rspamd_ssl_connection *conn, gpointer buf,
 	}
 
 	ret = SSL_read (conn->ssl, buf, buflen);
+	msg_debug_ssl ("ssl read: %d", ret);
 
 	if (ret > 0) {
 		conn->state = ssl_conn_connected;
@@ -681,9 +703,11 @@ rspamd_ssl_read (struct rspamd_ssl_connection *conn, gpointer buf,
 		what = 0;
 
 		if (ret == SSL_ERROR_WANT_READ) {
+			msg_debug_ssl ("ssl read: need read");
 			what |= EV_READ;
 		}
 		else if (ret == SSL_ERROR_WANT_WRITE) {
+			msg_debug_ssl ("ssl read: need write");
 			what |= EV_WRITE;
 		}
 		else {
@@ -719,6 +743,7 @@ rspamd_ssl_write (struct rspamd_ssl_connection *conn, gconstpointer buf,
 	}
 
 	ret = SSL_write (conn->ssl, buf, buflen);
+	msg_debug_ssl ("ssl write: ret=%d, buflen=%z", ret, buflen);
 
 	if (ret > 0) {
 		conn->state = ssl_conn_connected;
@@ -751,9 +776,11 @@ rspamd_ssl_write (struct rspamd_ssl_connection *conn, gconstpointer buf,
 		conn->state = ssl_next_write;
 
 		if (ret == SSL_ERROR_WANT_READ) {
+			msg_debug_ssl ("ssl write: need read");
 			what = EV_READ;
 		}
 		else if (ret == SSL_ERROR_WANT_WRITE) {
+			msg_debug_ssl ("ssl write: need write");
 			what = EV_WRITE;
 		}
 		else {
@@ -777,10 +804,14 @@ gssize
 rspamd_ssl_writev (struct rspamd_ssl_connection *conn, struct iovec *iov,
 		gsize iovlen)
 {
-	guchar ssl_buf[16000];
+	/*
+	 * Static is needed to avoid issue:
+	 * https://github.com/openssl/openssl/issues/6865
+	 */
+	static guchar ssl_buf[16384];
 	guchar *p;
 	struct iovec *cur;
-	guint i, remain;
+	gsize i, remain;
 
 	remain = sizeof (ssl_buf);
 	p = ssl_buf;
@@ -816,10 +847,12 @@ rspamd_ssl_connection_free (struct rspamd_ssl_connection *conn)
 	if (conn) {
 		if (conn->shut == ssl_shut_unclean) {
 			/* Ignore return result and close socket */
+			msg_debug_ssl ("unclean shutdown");
 			(void)SSL_shutdown (conn->ssl);
 			rspamd_ssl_connection_dtor (conn);
 		}
 		else {
+			msg_debug_ssl ("normal shutdown");
 			rspamd_ssl_shutdown (conn);
 		}
 	}
diff --git a/src/libutil/ssl_util.h b/src/libutil/ssl_util.h
index 75436f2cc..c934bebaa 100644
--- a/src/libutil/ssl_util.h
+++ b/src/libutil/ssl_util.h
@@ -36,7 +36,9 @@ typedef void (*rspamd_ssl_error_handler_t) (gpointer d, GError *err);
  * @return opaque connection data
  */
 struct rspamd_ssl_connection *rspamd_ssl_connection_new (gpointer ssl_ctx,
-														 struct ev_loop *ev_base, gboolean verify_peer);
+														 struct ev_loop *ev_base,
+														 gboolean verify_peer,
+														 const gchar *log_tag);
 
 /**
  * Connects SSL session using the specified (connected) FD
diff --git a/src/lua/lua_tcp.c b/src/lua/lua_tcp.c
index 226f48cc5..e9dab0196 100644
--- a/src/lua/lua_tcp.c
+++ b/src/lua/lua_tcp.c
@@ -840,12 +840,15 @@ lua_tcp_write_helper (struct lua_tcp_cbdata *cbd)
 	}
 
 	if (r == -1) {
-		lua_tcp_push_error (cbd, FALSE, "IO write error while trying to write %d "
-				"bytes: %s", (gint)remain, strerror (errno));
-		if (!IS_SYNC (cbd)) {
-			/* sync connection methods perform this inside */
-			lua_tcp_shift_handler (cbd);
-			lua_tcp_plan_handler_event (cbd, TRUE, FALSE);
+		if (!(cbd->ssl_conn)) {
+			lua_tcp_push_error (cbd, FALSE,
+					"IO write error while trying to write %d bytes: %s",
+					(gint) remain, strerror (errno));
+			if (!IS_SYNC (cbd)) {
+				/* sync connection methods perform this inside */
+				lua_tcp_shift_handler (cbd);
+				lua_tcp_plan_handler_event (cbd, TRUE, FALSE);
+			}
 		}
 
 		return;
@@ -862,7 +865,7 @@ lua_tcp_write_helper (struct lua_tcp_cbdata *cbd)
 	}
 	else {
 		/* Want to write more */
-		if (niov > IOV_MAX && r > 0) {
+		if (r > 0) {
 			/* XXX: special case: we know that we want to write more data
 			 * than it is available in iov function.
 			 *
@@ -1285,8 +1288,10 @@ lua_tcp_make_connection (struct lua_tcp_cbdata *cbd)
 			verify_peer = TRUE;
 		}
 
-		cbd->ssl_conn =
-				rspamd_ssl_connection_new (ssl_ctx, cbd->event_loop, verify_peer);
+		cbd->ssl_conn = rspamd_ssl_connection_new (ssl_ctx,
+				cbd->event_loop,
+				verify_peer,
+				cbd->tag);
 
 		if (!rspamd_ssl_connect_fd (cbd->ssl_conn, fd, cbd->hostname, &cbd->ev,
 				cbd->ev.timeout, lua_tcp_handler, lua_tcp_ssl_on_error, cbd)) {
@@ -1823,6 +1828,8 @@ lua_tcp_connect_sync (lua_State *L)
 	struct rspamd_dns_resolver *resolver = NULL;
 	struct rspamd_config *cfg = NULL;
 	struct ev_loop *ev_base = NULL;
+	struct lua_tcp_cbdata *cbd;
+
 
 	int arguments_validated = rspamd_lua_parse_table_arguments (L, 1, &err,
 			RSPAMD_LUA_PARSE_ARGUMENTS_DEFAULT,
@@ -1855,11 +1862,24 @@ lua_tcp_connect_sync (lua_State *L)
 		timeout = default_tcp_timeout;
 	}
 
+	cbd = g_new0 (struct lua_tcp_cbdata, 1);
+
 	if (task) {
+		static const gchar hexdigests[16] = "0123456789abcdef";
+
 		cfg = task->cfg;
 		ev_base = task->event_loop;
 		session = task->s;
+		/* Make a readable tag */
+		memcpy (cbd->tag, task->task_pool->tag.uid, sizeof (cbd->tag) - 2);
+		cbd->tag[sizeof (cbd->tag) - 2] = hexdigests[GPOINTER_TO_INT (cbd) & 0xf];
+		cbd->tag[sizeof (cbd->tag) - 1] = 0;
 	}
+	else {
+		h = rspamd_random_uint64_fast ();
+		rspamd_snprintf (cbd->tag, sizeof (cbd->tag), "%uxL", h);
+	}
+
 	if (resolver == NULL) {
 		if (task) {
 			resolver = task->resolver;
@@ -1869,14 +1889,11 @@ lua_tcp_connect_sync (lua_State *L)
 		}
 	}
 
-	struct lua_tcp_cbdata *cbd = g_new0 (struct lua_tcp_cbdata, 1);
-
 	cbd->task = task;
 	cbd->cfg = cfg;
 	cbd->thread = lua_thread_pool_get_running_entry (cfg->lua_thread_pool);
 
-	h = rspamd_random_uint64_fast ();
-	rspamd_snprintf (cbd->tag, sizeof (cbd->tag), "%uxL", h);
+
 	cbd->handlers = g_queue_new ();
 
 	cbd->event_loop = ev_base;
@@ -2322,8 +2339,10 @@ lua_tcp_starttls (lua_State * L)
 		verify_peer = TRUE;
 	}
 
-	cbd->ssl_conn =
-			rspamd_ssl_connection_new (ssl_ctx, cbd->event_loop, verify_peer);
+	cbd->ssl_conn = rspamd_ssl_connection_new (ssl_ctx,
+			cbd->event_loop,
+			verify_peer,
+			cbd->tag);
 
 	if (!rspamd_ssl_connect_fd (cbd->ssl_conn, cbd->fd, cbd->hostname, &cbd->ev,
 			cbd->ev.timeout, lua_tcp_handler, lua_tcp_ssl_on_error, cbd)) {