lib-http: Add ioloop and lock wait information to timeout messages.

It'll now log for example:
9007 Request timed out (Request sent 7.087 secs ago, 0.076 in other ioloops, 7.012 in locks, connected 7.087 secs ago)

Which points out that the problem wasn't really with the HTTP, but with
locking. This likely should be fixed in some way also in lib-http so that
it gives a bit of extra time for reading the request, but that's a separate
fix.

diff --git a/src/lib-http/http-client-connection.c b/src/lib-http/http-client-connection.c
index 5aeb28456a954c11261f24dab449922b7e39cb38..5f8b769cba30d7e1bc71c7ba12d563641eabbf3d 100644 (file)
--- a/src/lib-http/http-client-connection.c
+++ b/src/lib-http/http-client-connection.c
@@ -11,6 +11,7 @@
 #include "istream-timeout.h"
 #include "ostream.h"
 #include "time-util.h"
+#include "file-lock.h"
 #include "iostream-rawlog.h"
 #include "iostream-ssl.h"
 #include "http-response-parser.h"
@@ -199,6 +200,24 @@ http_client_connection_get_timing_info(struct http_client_connection *conn)
                                    (*requestp)->attempts + 1,
                                    total_msecs/1000, total_msecs%1000);
                }
+               int other_ioloop_msecs = (ioloop_global_wait_usecs -
+                       (*requestp)->sent_global_ioloop_usecs + 999) / 1000;
+               if (conn->client->ioloop != NULL) {
+                       int http_ioloop_msecs =
+                               (io_loop_get_wait_usecs(conn->client->ioloop) + 999) / 1000;
+                       other_ioloop_msecs -= http_ioloop_msecs;
+                       str_printfa(str, ", %d.%03d in http ioloop",
+                                   http_ioloop_msecs/1000, http_ioloop_msecs%1000);
+               }
+               str_printfa(str, ", %d.%03d in other ioloops",
+                           other_ioloop_msecs/1000, other_ioloop_msecs%1000);
+
+               int lock_msecs = (file_lock_wait_get_total_usecs() -
+                                 (*requestp)->sent_lock_usecs + 999) / 1000;
+               if (lock_msecs > 0) {
+                       str_printfa(str, ", %d.%03d in locks",
+                                   lock_msecs/1000, lock_msecs%1000);
+               }
        } else {
                str_append(str, "No requests");
                if (conn->conn.last_input != 0) {

diff --git a/src/lib-http/http-client-private.h b/src/lib-http/http-client-private.h
index 51e01168ef802a765a50452e0299bd1c7aa22cbb..0090e4112765f36ec7b8a64523f7f3a0937349fb 100644 (file)
--- a/src/lib-http/http-client-private.h
+++ b/src/lib-http/http-client-private.h
@@ -95,6 +95,8 @@ struct http_client_request {
 
        unsigned int attempts;
        unsigned int redirects;
+       uint64_t sent_global_ioloop_usecs;
+       uint64_t sent_lock_usecs;
 
        unsigned int delayed_error_status;
        const char *delayed_error;

diff --git a/src/lib-http/http-client-request.c b/src/lib-http/http-client-request.c
index fcc53c5c4487b190f16e8fd4296b78db5b2d05a5..eaac523fe83da5dc3dea105211f995ad3f0d7d99 100644 (file)
--- a/src/lib-http/http-client-request.c
+++ b/src/lib-http/http-client-request.c
@@ -9,6 +9,7 @@
 #include "time-util.h"
 #include "istream.h"
 #include "ostream.h"
+#include "file-lock.h"
 #include "dns-lookup.h"
 #include "http-url.h"
 #include "http-date.h"
@@ -1006,6 +1007,8 @@ static int http_client_request_send_real(struct http_client_request *req,
 
        req->state = HTTP_REQUEST_STATE_PAYLOAD_OUT;
        req->sent_time = ioloop_timeval;
+       req->sent_lock_usecs = file_lock_wait_get_total_usecs();
+       req->sent_global_ioloop_usecs = ioloop_global_wait_usecs;
        o_stream_cork(output);
        if (o_stream_sendv(output, iov, N_ELEMENTS(iov)) < 0) {
                *error_r = t_strdup_printf("write(%s) failed: %s",