http_async_client: add http_time pseudovariable

src/modules/http_async_client/async_http.c

@@ -57,6 +57,7 @@ extern struct tm_binds tmb;
 
 struct sip_msg *ah_reply = NULL;
 str ah_error = {NULL, 0};
+http_m_time_t ah_time = {0};
 
 async_http_worker_t *workers = NULL;
 int num_workers = 1;
@@ -142,6 +143,8 @@ void async_http_cb(struct http_m_reply *reply, void *param)
 	/* clean process-local result variables */
 	ah_error.s = NULL;
 	ah_error.len = 0;
+
+	memset(&ah_time, 0, sizeof(struct http_m_time));
 	memset(ah_reply, 0, sizeof(struct sip_msg));
 
 	keng = sr_kemi_eng_get();
@@ -163,6 +166,8 @@ void async_http_cb(struct http_m_reply *reply, void *param)
 	}
 
 	/* set process-local result variables */
+	ah_time = reply->time;
+
 	if (reply->result == NULL) {
 		/* error */
 		ah_error.s = reply->error;

src/modules/http_async_client/async_http.h

@@ -56,6 +56,7 @@ extern int tcp_ka_interval;
 
 extern struct sip_msg *ah_reply;
 extern str ah_error;
+extern http_m_time_t ah_time;
 
 extern int tls_verify_host;
 extern int tls_verify_peer;

src/modules/http_async_client/doc/http_async_client_admin.xml

@@ -501,6 +501,21 @@ http_async_query("https://example.com/test.php", "HTTP_REPLY");
 		<listitem><para>
 			<emphasis>$http_rb</emphasis> and <emphasis>$http_bs</emphasis>: HTTP response body and body length
 		</para></listitem>
+		<listitem><para>
+			<emphasis>$http_time</emphasis>: provides access to broken-down transfer time in microseconds calculated by cURL (https://curl.se/libcurl/c/curl_easy_getinfo.html). 
+				<para>
+					<emphasis>'name'</emphasis> can be:
+					<itemizedlist>
+						<listitem><para>total - total time for the transfer</para></listitem>
+						<listitem><para>lookup - name lookup time</para></listitem>
+						<listitem><para>connect - time from the start until the connection to the remote host (or proxy) was completed.</para></listitem>
+						<listitem><para>appconnect - time from start until SSL/SSH handshake completed</para></listitem>
+						<listitem><para>pretransfer - time from start until just before the transfer begins</para></listitem>
+						<listitem><para>starttransfer - time from start until just when the first byte is received</para></listitem>
+						<listitem><para>redirect - time taken for all redirect steps before the final transfer.</para></listitem>
+					</itemizedlist>
+				</para>	
+		</para></listitem>
 	</itemizedlist>
 </section>
 <section>

src/modules/http_async_client/hm_hash.h

@@ -31,6 +31,7 @@
 #ifndef _HM_HASH_
 #define _HM_HASH_
 
+#include <stdint.h>
 #include <curl/curl.h>
 #include "../../core/dprint.h"
 #include "../../core/mem/mem.h"
@@ -39,11 +40,23 @@
 
 extern struct http_m_table *hm_table;
 
+typedef struct http_m_time
+{
+	uint32_t total;
+	uint32_t lookup;
+	uint32_t connect;
+	uint32_t appconnect;
+	uint32_t pretransfer;
+	uint32_t starttransfer;
+	uint32_t redirect;
+} http_m_time_t;
+
 typedef struct http_m_reply
 {
 	long retcode;
 	str *result;
 	char error[CURL_ERROR_SIZE];
+	http_m_time_t time;
 } http_m_reply_t;
 
 typedef void (*http_multi_cbe_t)(struct http_m_reply *reply, void *param);

src/modules/http_async_client/http_async_client_mod.c

@@ -98,6 +98,7 @@ static int ah_get_body_size(struct sip_msg *msg, pv_param_t *param, pv_value_t *
 static int ah_get_msg_buf(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
 static int ah_get_msg_len(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
 static int ah_parse_req_name(pv_spec_p sp, str *in);
+static int ah_parse_time_name(pv_spec_p sp, str *in);
 static int ah_set_req(struct sip_msg* msg, pv_param_t *param, int op, pv_value_t *val);
 static int ah_get_id(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
 
@@ -107,6 +108,7 @@ static str pv_str_0 = {"0", 1};
 
 static int ah_get_ok(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
 static int ah_get_err(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
+static int ah_get_time(struct sip_msg *msg, pv_param_t *param, pv_value_t *res);
 
 /* tm */
 struct tm_binds tmb;
@@ -128,6 +130,12 @@ enum http_req_name_t {
 	E_HRN_TCP_KA_INTERVAL
 };
 
+enum http_time_name_t {
+	E_HT_TOTAL = 0,
+	E_HT_LOOKUP, E_HT_CONNECT, E_HT_REDIRECT,
+	E_HT_APPCONNECT, E_HT_PRETRANSFER, E_HT_STARTTRANSFER
+};
+
 static cmd_export_t cmds[]={
 	{"http_async_query",  (cmd_function)w_http_async_query, 2, fixup_spve_spve,
 		0, ANY_ROUTE},
@@ -190,6 +198,9 @@ static pv_export_t pvs[] = {
 	{STR_STATIC_INIT("http_err"),
 		PVT_OTHER, ah_get_err, 0,
 		0, 0, 0, 0},
+	{STR_STATIC_INIT("http_time"),
+		PVT_OTHER, ah_get_time, 0,
+		ah_parse_time_name, 0, 0, 0},
 	{STR_STATIC_INIT("http_req"),
 		PVT_OTHER, pv_get_null, ah_set_req,
 		ah_parse_req_name, 0, 0, 0},
@@ -544,6 +555,31 @@ static int ah_get_err(struct sip_msg *msg, pv_param_t *param, pv_value_t *res) {
 	}
 }
 
+static int ah_get_time(struct sip_msg *msg, pv_param_t *param,
+		pv_value_t *res)
+{
+	if(msg==NULL || param==NULL)
+		return -1;
+
+	switch(param->pvn.u.isname.name.n)
+	{
+		case E_HT_LOOKUP:
+			return pv_get_uintval(msg, param, res, ah_time.lookup);
+		case E_HT_CONNECT:
+			return pv_get_uintval(msg, param, res, ah_time.connect);
+		case E_HT_REDIRECT:
+			return pv_get_uintval(msg, param, res, ah_time.redirect);
+		case E_HT_APPCONNECT:
+			return pv_get_uintval(msg, param, res, ah_time.appconnect);
+		case E_HT_PRETRANSFER:
+			return pv_get_uintval(msg, param, res, ah_time.pretransfer);
+		case E_HT_STARTTRANSFER:
+			return pv_get_uintval(msg, param, res, ah_time.starttransfer);
+		default:
+			return pv_get_uintval(msg, param, res, ah_time.total);
+	}
+}
+
 static int ah_parse_req_name(pv_spec_p sp, str *in) {
 	if(sp==NULL || in==NULL || in->len<=0)
 		return -1;
@@ -623,6 +659,60 @@ error:
 	return -1;
 }
 
+static int ah_parse_time_name(pv_spec_p sp, str *in) {
+	if(sp==NULL || in==NULL || in->len<0)
+		return -1;
+
+	switch(in->len)
+	{
+		case 5:
+			if(strncmp(in->s, "total", 5)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_TOTAL;
+			else goto error;
+			break;
+		case 6:
+			if(strncmp(in->s, "lookup", 6)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_LOOKUP;
+			else goto error;
+			break;
+		case 7:
+			if(strncmp(in->s, "connect", 7)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_CONNECT;
+			else goto error;
+			break;
+		case 8:
+			if(strncmp(in->s, "redirect", 8)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_REDIRECT;
+			else goto error;
+			break;
+		case 10:
+			if(strncmp(in->s, "appconnect", 10)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_APPCONNECT;
+			else goto error;
+			break;
+		case 11:
+			if(strncmp(in->s, "pretransfer", 11)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_PRETRANSFER;
+			else goto error;
+			break;
+		case 13:
+			if(strncmp(in->s, "starttransfer", 13)==0)
+				sp->pvp.pvn.u.isname.name.n = E_HT_STARTTRANSFER;
+			else goto error;
+			break;
+		default:
+			goto error;
+	}
+	sp->pvp.pvn.type = PV_NAME_INTSTR;
+	sp->pvp.pvn.u.isname.type = 0;
+
+	return 0;
+
+error:
+	LM_ERR("unknown http_time name %.*s\n", in->len, in->s);
+	return -1;
+}
+
 static int ah_set_req(struct sip_msg* msg, pv_param_t *param,
 		int op, pv_value_t *val)
 {

src/modules/http_async_client/http_multi.c

@@ -66,8 +66,8 @@ void timer_cb(int fd, short kind, void *userp)
 
 	LM_DBG("timeout on socket %d\n", fd);
 
-	rc = curl_multi_socket_action(g->multi,
-                                  CURL_SOCKET_TIMEOUT, 0, &g->still_running);
+	rc = curl_multi_socket_action(g->multi, CURL_SOCKET_TIMEOUT, 0, &g->still_running);
+
 	if (check_mcode(rc, error) < 0) {
 		LM_ERR("curl_multi_socket_action error: %s", error);
 	}
@@ -122,8 +122,7 @@ void event_cb(int fd, short kind, void *userp)
 		LM_DBG("removing handle %p\n", easy);
 		curl_multi_remove_handle(g->multi, easy);
 		curl_easy_cleanup(easy);
-		rc = curl_multi_socket_action(g->multi,
-                                  CURL_SOCKET_TIMEOUT, 0, &g->still_running);
+		rc = curl_multi_socket_action(g->multi, CURL_SOCKET_TIMEOUT, 0, &g->still_running);
 
 	} else {
 		LM_DBG("performing action %d on socket %d\n", action, fd);
@@ -568,6 +567,7 @@ void check_multi_info(struct http_m_global *g)
 	CURLcode res;
 
 	struct http_m_cell *cell;
+	double tmp_time;
 
 	LM_DBG("REMAINING: %d\n", g->still_running);
 	while ((msg = curl_multi_info_read(g->multi, &msgs_left))) {
@@ -576,6 +576,8 @@ void check_multi_info(struct http_m_global *g)
 			res = msg->data.result;
 			curl_easy_getinfo(easy, CURLINFO_PRIVATE, &cell);
 			curl_easy_getinfo(easy, CURLINFO_EFFECTIVE_URL, &eff_url);
+
+
 			LM_DBG("DONE: %s => (%d) %s\n", eff_url, res, cell->error);
 
 			cell = http_m_cell_lookup(easy);
@@ -584,6 +586,22 @@ void check_multi_info(struct http_m_global *g)
 				update_stat(errors, 1);
 				reply_error(cell);
 			} else {
+				
+				if (curl_easy_getinfo(cell->easy, CURLINFO_TOTAL_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.total=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_NAMELOOKUP_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.lookup=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_CONNECT_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.connect=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_REDIRECT_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.redirect=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_APPCONNECT_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.appconnect=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_PRETRANSFER_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.pretransfer=(uint32_t)(tmp_time*1000000);
+				if (curl_easy_getinfo(cell->easy, CURLINFO_STARTTRANSFER_TIME, &tmp_time) == CURLE_OK)
+					cell->reply->time.starttransfer=(uint32_t)(tmp_time*1000000);
+				
 				cell->reply->error[0] = '\0';
 				cell->cb(cell->reply, cell->param);