Mercurial > dovecot > core-2.2
changeset 22253:9676f01a11df
director: Log more connection state information on handshaking errors
author | Timo Sirainen <timo.sirainen@dovecot.fi> |
---|---|
date | Wed, 31 May 2017 13:42:31 +0300 |
parents | 8882a5cbe76d |
children | 58ffaff6f714 |
files | src/director/director-connection.c |
diffstat | 1 files changed, 48 insertions(+), 27 deletions(-) [+] |
line wrap: on
line diff
--- a/src/director/director-connection.c Wed May 31 13:17:37 2017 +0300 +++ b/src/director/director-connection.c Wed May 31 13:42:31 2017 +0300 @@ -159,27 +159,52 @@ } static void +director_connection_append_stats(struct director_connection *conn, string_t *str) +{ + int input_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->last_input); + int output_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->last_output); + int connected_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->connected_time); + + str_printfa(str, "bytes in=%"PRIuUOFF_T", bytes out=%"PRIuUOFF_T", " + "last input %u.%03u s ago, last output %u.%03u s ago", + conn->input->v_offset, conn->output->offset, + input_msecs/1000, input_msecs%1000, + output_msecs/1000, output_msecs%1000); + if (conn->connected) { + str_printfa(str, ", connected %u.%03u s ago", + connected_msecs/1000, connected_msecs%1000); + } + if (o_stream_get_buffer_used_size(conn->output) > 0) { + str_printfa(str, ", %"PRIuSIZE_T" bytes in output buffer", + o_stream_get_buffer_used_size(conn->output)); + } +} + +static void director_connection_init_timeout(struct director_connection *conn) { - unsigned int secs; + struct timeval start_time; + string_t *reason = t_str_new(128); if (!conn->connected) { - secs = ioloop_time - conn->created.tv_sec; - i_error("director(%s): Connect timed out (%u secs)", - conn->name, secs); + start_time = conn->created; + str_append(reason, "Connect timed out"); } else if (!conn->me_received) { - secs = ioloop_time - conn->connected_time.tv_sec; - i_error("director(%s): Handshaking ME timed out (%u secs)", - conn->name, secs); + start_time = conn->connected_time; + str_append(reason, "Handshaking ME timed out"); } else if (!conn->in) { - secs = ioloop_time - conn->me_received_time.tv_sec; - i_error("director(%s): Sending handshake timed out (%u secs)", - conn->name, secs); + start_time = conn->me_received_time; + str_append(reason, "Sending handshake timed out"); } else { - secs = ioloop_time - conn->me_received_time.tv_sec; - i_error("director(%s): Handshaking DONE timed out (%u secs)", - conn->name, secs); + start_time = conn->me_received_time; + str_append(reason, "Handshaking DONE timed out"); } + int msecs = timeval_diff_msecs(&ioloop_timeval, &start_time); + str_printfa(reason, " (%u.%03u secs, ", msecs/1000, msecs%1000); + director_connection_append_stats(conn, reason); + str_append_c(reason, ')'); + + i_error("director(%s): %s", conn->name, str_c(reason)); director_connection_disconnected(&conn, "Handshake timeout"); } @@ -1254,10 +1279,10 @@ } str = t_str_new(128); - str_printfa(str, "director(%s): Handshake finished in %u.%03u secs " - "(bytes in=%"PRIuUOFF_T" out=%"PRIuUOFF_T")", - conn->name, handshake_msecs/1000, handshake_msecs%1000, - conn->input->v_offset, conn->output->offset); + str_printfa(str, "director(%s): Handshake finished in %u.%03u secs (", + conn->name, handshake_msecs/1000, handshake_msecs%1000); + director_connection_append_stats(conn, str); + str_append_c(str, ')'); if (handshake_msecs >= DIRECTOR_HANDSHAKE_WARN_SECS*1000) i_warning("%s", str_c(str)); else @@ -1727,7 +1752,6 @@ director_connection_log_disconnect(struct director_connection *conn, int err, const char *errstr) { - unsigned int secs = ioloop_time - conn->connected_time.tv_sec; string_t *str = t_str_new(128); i_assert(conn->connected); @@ -1749,14 +1773,14 @@ str_printfa(str, ": %s", errstr); } - str_printfa(str, " (connected %u secs, " - "in=%"PRIuUOFF_T" out=%"PRIuUOFF_T, - secs, conn->input->v_offset, conn->output->offset); + str_append(str, "( "); + director_connection_append_stats(conn, str); if (!conn->me_received) str_append(str, ", handshake ME not received"); else if (!conn->handshake_received) str_append(str, ", handshake DONE not received"); + str_append_c(str, ')'); i_error("%s", str_c(str)); } @@ -2192,14 +2216,11 @@ static void director_connection_ping_idle_timeout(struct director_connection *conn) { - int input_diff = timeval_diff_msecs(&ioloop_timeval, &conn->last_input); - int output_diff = timeval_diff_msecs(&ioloop_timeval, &conn->last_output); string_t *str = t_str_new(128); - str_printfa(str, "Ping timed out, disconnecting " - "(last input %u.%03u s ago, last output %u.%03u s ago", - input_diff/1000, input_diff%1000, - output_diff/1000, output_diff%1000); + str_printfa(str, "Ping timed out in %u secs, disconnecting (", + DIRECTOR_CONNECTION_PING_IDLE_TIMEOUT_MSECS/1000); + director_connection_append_stats(conn, str); if (conn->handshake_received) str_append(str, ", handshaked"); if (conn->synced)