From 74b182e0166abe108a374495079c2e23cdaceac6 Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Mon, 12 Aug 2019 16:50:49 +0100 Subject: [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)) { -- cgit v1.2.3