feat: add detailed timeout error (#170)

When a timeout occurs, now the error message is like:

```
Timeout of 1000 ms reached. Total time: 1000.527000 ms (DNS time: 0.084000 ms, TCP/SSL handshake time: 0.314000 ms, HTTP Request/Response time: 1000.014000 ms)
```

Before it used to be:

```
Timeout was reached
```

Closes #169.

Also move error reporting macros from utils.h to a more proper errors.h module.

Makefile

@@ -9,7 +9,8 @@ REGRESS = $(patsubst test/sql/%.sql,%,$(TESTS))
 REGRESS_OPTS = --use-existing --inputdir=test
 
 MODULE_big = $(EXTENSION)
-OBJS = src/worker.o src/util.o src/core.o src/event.o
+SRC = $(wildcard src/*.c)
+OBJS = $(patsubst src/%.c, src/%.o, $(SRC))
 
 all: sql/$(EXTENSION)--$(EXTVERSION).sql $(EXTENSION).control
 

src/core.c

@@ -28,14 +28,15 @@
 #include <string.h>
 #include <inttypes.h>
 
-#include "util.h"
 #include "core.h"
 #include "event.h"
+#include "errors.h"
 
 typedef struct {
   int64 id;
   StringInfo body;
   struct curl_slist* request_headers;
+  int32 timeout_milliseconds;
 } CurlData;
 
 static size_t
@@ -47,6 +48,29 @@ body_cb(void *contents, size_t size, size_t nmemb, void *userp)
   return realsize;
 }
 
+static struct curl_slist *pg_text_array_to_slist(ArrayType *array,
+                                          struct curl_slist *headers) {
+    ArrayIterator iterator;
+    Datum value;
+    bool isnull;
+    char *hdr;
+
+    iterator = array_create_iterator(array, 0, NULL);
+
+    while (array_iterate(iterator, &value, &isnull)) {
+        if (isnull) {
+            continue;
+        }
+
+        hdr = TextDatumGetCString(value);
+        EREPORT_CURL_SLIST_APPEND(headers, hdr);
+        pfree(hdr);
+    }
+    array_free_iterator(iterator);
+
+    return headers;
+}
+
 // We need a different memory context here, as the parent function will have an SPI memory context, which has a shorter lifetime.
 static void init_curl_handle(CURLM *curl_mhandle, MemoryContext curl_memctx, int64 id, Datum urlBin, NullableDatum bodyBin, NullableDatum headersBin, Datum methodBin, int32 timeout_milliseconds){
   MemoryContext old_ctx = MemoryContextSwitchTo(curl_memctx);
@@ -55,13 +79,15 @@ static void init_curl_handle(CURLM *curl_mhandle, MemoryContext curl_memctx, int
   cdata->id   = id;
   cdata->body = makeStringInfo();
 
+  cdata->timeout_milliseconds = timeout_milliseconds;
+
   if (!headersBin.isnull) {
     ArrayType *pgHeaders = DatumGetArrayTypeP(headersBin.value);
     struct curl_slist *request_headers = NULL;
 
     request_headers = pg_text_array_to_slist(pgHeaders, request_headers);
 
-    CURL_SLIST_APPEND(request_headers, "User-Agent: pg_net/" EXTVERSION);
+    EREPORT_CURL_SLIST_APPEND(request_headers, "User-Agent: pg_net/" EXTVERSION);
 
     cdata->request_headers = request_headers;
   }
@@ -81,39 +107,39 @@ static void init_curl_handle(CURLM *curl_mhandle, MemoryContext curl_memctx, int
 
   if (strcasecmp(method, "GET") == 0) {
     if (reqBody) {
-      CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDS, reqBody);
-      CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_CUSTOMREQUEST, "GET");
+      EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDS, reqBody);
+      EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_CUSTOMREQUEST, "GET");
     }
   }
 
   if (strcasecmp(method, "POST") == 0) {
     if (reqBody) {
-      CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDS, reqBody);
+      EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDS, reqBody);
     }
     else {
-      CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_POST, 1);
-      CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDSIZE, 0);
+      EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_POST, 1);
+      EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_POSTFIELDSIZE, 0);
     }
   }
 
   if (strcasecmp(method, "DELETE") == 0) {
-    CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_CUSTOMREQUEST, "DELETE");
+    EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_CUSTOMREQUEST, "DELETE");
   }
 
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_WRITEFUNCTION, body_cb);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_WRITEDATA, cdata);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_HEADER, 0L);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_URL, url);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_HTTPHEADER, cdata->request_headers);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_TIMEOUT_MS, timeout_milliseconds);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_PRIVATE, cdata);
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_FOLLOWLOCATION, true);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_WRITEFUNCTION, body_cb);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_WRITEDATA, cdata);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_HEADER, 0L);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_URL, url);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_HTTPHEADER, cdata->request_headers);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_TIMEOUT_MS, cdata->timeout_milliseconds);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_PRIVATE, cdata);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_FOLLOWLOCATION, true);
   if (log_min_messages <= DEBUG2)
-    CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_VERBOSE, 1L);
+    EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_VERBOSE, 1L);
 #if LIBCURL_VERSION_NUM >= 0x075500 /* libcurl 7.85.0 */
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_PROTOCOLS_STR, "http,https");
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_PROTOCOLS_STR, "http,https");
 #else
-  CURL_EZ_SETOPT(curl_ez_handle, CURLOPT_PROTOCOLS, CURLPROTO_HTTP | CURLPROTO_HTTPS);
+  EREPORT_CURL_SETOPT(curl_ez_handle, CURLOPT_PROTOCOLS, CURLPROTO_HTTP | CURLPROTO_HTTPS);
 #endif
 
   EREPORT_MULTI(
@@ -124,10 +150,10 @@ static void init_curl_handle(CURLM *curl_mhandle, MemoryContext curl_memctx, int
 }
 
 void set_curl_mhandle(CURLM *curl_mhandle, LoopState *lstate){
-  CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_SOCKETFUNCTION, multi_socket_cb);
-  CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_SOCKETDATA, lstate);
-  CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_TIMERFUNCTION, multi_timer_cb);
-  CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_TIMERDATA, lstate);
+  EREPORT_CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_SOCKETFUNCTION, multi_socket_cb);
+  EREPORT_CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_SOCKETDATA, lstate);
+  EREPORT_CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_TIMERFUNCTION, multi_timer_cb);
+  EREPORT_CURL_MULTI_SETOPT(curl_mhandle, CURLMOPT_TIMERDATA, lstate);
 }
 
 void delete_expired_responses(char *ttl, int batch_size){
@@ -164,16 +190,23 @@ void delete_expired_responses(char *ttl, int batch_size){
   CommitTransactionCommand();
 }
 
-static void insert_failure_response(CURLcode return_code, int64 id){
+static void insert_failure_response(CURL *ez_handle, CURLcode return_code, int64 id, int32 timeout_milliseconds){
   StartTransactionCommand();
   PushActiveSnapshot(GetTransactionSnapshot());
   SPI_connect();
 
+  const char* error_msg;
+  if (return_code == CURLE_OPERATION_TIMEDOUT){
+    error_msg = detailed_timeout_strerror(ez_handle, timeout_milliseconds).msg;
+  } else {
+    error_msg = curl_easy_strerror(return_code);
+  }
+
   int ret_code = SPI_execute_with_args("\
       insert into net._http_response(id, error_msg) values ($1, $2)",
       2,
       (Oid[]){INT8OID, CSTRINGOID},
-      (Datum[]){Int64GetDatum(id), CStringGetDatum(curl_easy_strerror(return_code))},
+      (Datum[]){Int64GetDatum(id), CStringGetDatum(error_msg)},
       NULL, false, 1);
 
   if (ret_code != SPI_OK_INSERT)
@@ -316,16 +349,16 @@ void insert_curl_responses(LoopState *lstate, MemoryContext curl_memctx){
       CURLcode return_code = msg->data.result;
       CURL *ez_handle= msg->easy_handle;
       CurlData *cdata = NULL;
-      CURL_EZ_GETINFO(ez_handle, CURLINFO_PRIVATE, &cdata);
+      EREPORT_CURL_GETINFO(ez_handle, CURLINFO_PRIVATE, &cdata);
 
       if (return_code != CURLE_OK) {
-        insert_failure_response(return_code, cdata->id);
+        insert_failure_response(ez_handle, return_code, cdata->id, cdata->timeout_milliseconds);
       } else {
         char *contentType;
-        CURL_EZ_GETINFO(ez_handle, CURLINFO_CONTENT_TYPE, &contentType);
+        EREPORT_CURL_GETINFO(ez_handle, CURLINFO_CONTENT_TYPE, &contentType);
 
         long http_status_code;
-        CURL_EZ_GETINFO(ez_handle, CURLINFO_RESPONSE_CODE, &http_status_code);
+        EREPORT_CURL_GETINFO(ez_handle, CURLINFO_RESPONSE_CODE, &http_status_code);
 
         Jsonb *jsonb_headers = jsonb_headers_from_curl_handle(ez_handle);
 

src/errors.c

@@ -0,0 +1,81 @@
+#include <postgres.h>
+#include <curl/curl.h>
+
+#include "errors.h"
+
+/*
+ * Show a more detailed error message when a timeout happens, which includes the DNS, TCP/SSL handshake and HTTP request/response time. An example message is like:
+ *
+ * "Timeout of 800 ms reached. Total time: 801.159000 ms (DNS time: 73.407000 ms, TCP/SSL handshake time: 677.256000 ms, HTTP Request/Respose time: 50.103000 ms)"
+ *
+ * Curl allows to calculate the above by applying substractions on some internal timings. Refer to https://blog.cloudflare.com/a-question-of-timing/ for an explanation of these timings.
+ *
+ * There are extra considerations:
+ *
+ * - If a step (e.g. TCP handshake [CURLINFO_CONNECT_TIME]) surpasses the request timeout, its given timing is 0.
+ *   However the step duration can still be determined by using the total time (CURLINFO_TOTAL_TIME).
+ *   We want to show at which step the timeout occurred.
+ *
+ * - If a step is omitted its given timing is 0. This can happen on non-HTTPS requests with the SSL handshake time (CURLINFO_APPCONNECT_TIME).
+ *
+ * - The pretransfer time (CURLINFO_PRETRANSFER_TIME) is greater than 0 when the HTTP request step starts.
+ */
+curl_timeout_msg detailed_timeout_strerror(CURL *ez_handle, int32 timeout_milliseconds){
+  double namelookup;    EREPORT_CURL_GETINFO(ez_handle, CURLINFO_NAMELOOKUP_TIME,    &namelookup);
+  double appconnect;    EREPORT_CURL_GETINFO(ez_handle, CURLINFO_APPCONNECT_TIME,    &appconnect);
+  double connect;       EREPORT_CURL_GETINFO(ez_handle, CURLINFO_CONNECT_TIME,       &connect);
+  double pretransfer;   EREPORT_CURL_GETINFO(ez_handle, CURLINFO_PRETRANSFER_TIME,   &pretransfer);
+  double starttransfer; EREPORT_CURL_GETINFO(ez_handle, CURLINFO_STARTTRANSFER_TIME, &starttransfer);
+  double total;         EREPORT_CURL_GETINFO(ez_handle, CURLINFO_TOTAL_TIME,         &total);
+
+  elog(DEBUG2, "The curl timings are time_namelookup: %f, time_connect: %f, time_appconnect: %f, time_pretransfer: %f, time_starttransfer: %f, time_total: %f",
+      namelookup, connect, appconnect, pretransfer, starttransfer, total);
+
+  // Steps at which the request timed out
+  bool timedout_at_dns       = namelookup == 0 && connect == 0; // if DNS time is 0 and no TCP occurred, it timed out at the DNS step
+  bool timedout_at_handshake = pretransfer == 0; // pretransfer determines if the HTTP step started, if 0 no HTTP ocurred and thus the timeout occurred at TCP or SSL handshake step
+  bool timedout_at_http      = pretransfer > 0; // The HTTP step did start and the timeout occurred here
+
+  // Calculate the steps times
+  double _dns_time =
+    timedout_at_dns ?
+      total: // get the total since namelookup will be 0 because of the timeout
+    timedout_at_handshake ?
+      namelookup:
+    timedout_at_http ?
+      namelookup:
+    0;
+
+  double _handshake_time =
+    timedout_at_dns ?
+      0:
+    timedout_at_handshake ?
+      total - namelookup: // connect or appconnect will be 0 because of the timeout, get the total - DNS step time
+    timedout_at_http ?
+      (connect - namelookup) +                    // TCP handshake time
+      (appconnect > 0 ? (appconnect - connect): 0): // SSL handshake time. Prevent a negative here which can happen when no SSL is involved (plain HTTP request) and appconnect is 0
+    0;
+
+  double _http_time =
+    timedout_at_dns ?
+      0:
+    timedout_at_handshake ?
+      0:
+    timedout_at_http ?
+      total - pretransfer:
+    0;
+
+  // convert seconds to milliseconds
+  double dns_time_ms       = _dns_time       * 1000;
+  double handshake_time_ms = _handshake_time * 1000;
+  double http_time_ms      = _http_time      * 1000;
+  double total_time_ms     = total           * 1000;
+
+  // build the error message
+  curl_timeout_msg result = {.msg = {}};
+  snprintf(result.msg, CURL_TIMEOUT_MSG_SIZE,
+    "Timeout of %d ms reached. Total time: %f ms (DNS time: %f ms, TCP/SSL handshake time: %f ms, HTTP Request/Response time: %f ms)",
+    timeout_milliseconds, total_time_ms, dns_time_ms, handshake_time_ms, http_time_ms
+  );
+  return result;
+}

src/errors.h

@@ -0,0 +1,51 @@
+#ifndef ERRORS_H
+#define ERRORS_H
+
+#define EREPORT_CURL_SETOPT(hdl, opt, prm) \
+  do { \
+      if (curl_easy_setopt(hdl, opt, prm) != CURLE_OK) \
+        ereport(ERROR, errmsg("Could not curl_easy_setopt(%s)", #opt)); \
+  } while (0)
+
+#define EREPORT_CURL_GETINFO(hdl, opt, prm) \
+  do { \
+      if (curl_easy_getinfo(hdl, opt, prm) != CURLE_OK) \
+        ereport(ERROR, errmsg("Could not curl_easy_getinfo(%s)", #opt)); \
+  } while (0)
+
+#define EREPORT_CURL_MULTI_SETOPT(hdl, opt, prm) \
+  do { \
+      if (curl_multi_setopt(hdl, opt, prm) != CURLM_OK) \
+        ereport(ERROR, errmsg("Could not curl_multi_setopt(%s)", #opt)); \
+  } while (0)
+
+#define EREPORT_CURL_SLIST_APPEND(list, str) \
+  do { \
+    struct curl_slist *new_list = curl_slist_append(list, str); \
+    if (new_list == NULL) \
+      ereport(ERROR, errmsg("curl_slist_append returned NULL")); \
+    list = new_list; \
+  } while (0)
+
+#define EREPORT_NULL_ATTR(tupIsNull, attr) \
+  do { \
+    if (tupIsNull) \
+      ereport(ERROR, errmsg("%s cannot be null", #attr)); \
+  } while (0)
+
+#define EREPORT_MULTI(multi_call) \
+  do { \
+    CURLMcode code = multi_call; \
+    if (code != CURLM_OK) \
+      ereport(ERROR, errmsg("%s failed with %s", #multi_call, curl_multi_strerror(code))); \
+  } while (0)
+
+#define CURL_TIMEOUT_MSG_SIZE 256
+
+typedef struct {
+  char msg[CURL_TIMEOUT_MSG_SIZE];
+} curl_timeout_msg;
+
+curl_timeout_msg detailed_timeout_strerror(CURL *ez_handle, int32 timeout_milliseconds);
+
+#endif

src/event.h

@@ -10,7 +10,7 @@
 #elif defined(__APPLE__) || defined(__FreeBSD__) || defined(__NetBSD__) || defined(__OpenBSD__)
 #define WAIT_USE_KQUEUE
 #else
-#error "no event wait implementation available"
+#error "no event loop implementation available"
 #endif
 
 #ifdef WAIT_USE_EPOLL

src/util.c

@@ -66,25 +66,3 @@ Datum _encode_url_with_params_array(PG_FUNCTION_ARGS) {
     PG_RETURN_TEXT_P(cstring_to_text(full_url));
 }
 
-struct curl_slist *pg_text_array_to_slist(ArrayType *array,
-                                          struct curl_slist *headers) {
-    ArrayIterator iterator;
-    Datum value;
-    bool isnull;
-    char *hdr;
-
-    iterator = array_create_iterator(array, 0, NULL);
-
-    while (array_iterate(iterator, &value, &isnull)) {
-        if (isnull) {
-            continue;
-        }
-
-        hdr = TextDatumGetCString(value);
-        CURL_SLIST_APPEND(headers, hdr);
-        pfree(hdr);
-    }
-    array_free_iterator(iterator);
-
-    return headers;
-}