commit 74b182e: [Fix] Add debug to ssl, fixed write hangs
Vsevolod Stakhov
vsevolod at highsecure.ru
Mon Aug 12 15:56:06 UTC 2019
Author: Vsevolod Stakhov
Date: 2019-08-12 16:50:49 +0100
URL: https://github.com/rspamd/rspamd/commit/74b182e0166abe108a374495079c2e23cdaceac6 (HEAD -> master)
[Fix] Add debug to ssl, fixed write hangs
---
src/libutil/http_connection.c | 3 +-
src/libutil/http_connection.h | 1 +
src/libutil/ssl_util.c | 99 ++++++++++++++++++++++++++++---------------
src/libutil/ssl_util.h | 4 +-
src/lua/lua_tcp.c | 49 ++++++++++++++-------
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)) {
More information about the Commits
mailing list