[Minor] Add failure reason in the upstreams code

contrib/librdns/rdns.h

@@ -169,7 +169,7 @@ struct rdns_upstream_context {
 												   void *ups_data);
 	unsigned int (*count)(void *ups_data);
 	void (*ok)(struct rdns_upstream_elt *elt, void *ups_data);
-	void (*fail)(struct rdns_upstream_elt *elt, void *ups_data);
+	void (*fail)(struct rdns_upstream_elt *elt, void *ups_data, const char *reason);
 };
 
 /**

contrib/librdns/resolver.c

@@ -334,7 +334,7 @@ rdns_process_timer (void *arg)
 
 	if (req->resolver->ups && req->io->srv->ups_elt) {
 		req->resolver->ups->fail (req->io->srv->ups_elt,
-				req->resolver->ups->data);
+				req->resolver->ups->data, "timeout waiting reply");
 	}
 	else {
 		UPSTREAM_FAIL (req->io->srv, time (NULL));
@@ -427,7 +427,7 @@ rdns_process_timer (void *arg)
 	else if (r == -1) {
 		if (req->resolver->ups && req->io->srv->ups_elt) {
 			req->resolver->ups->fail (req->io->srv->ups_elt,
-					req->resolver->ups->data);
+					req->resolver->ups->data, "cannot send retransmit after timeout");
 		}
 		else {
 			UPSTREAM_FAIL (req->io->srv, time (NULL));
@@ -537,7 +537,7 @@ rdns_process_retransmit (int fd, void *arg)
 	else if (r == -1) {
 		if (req->resolver->ups && req->io->srv->ups_elt) {
 			req->resolver->ups->fail (req->io->srv->ups_elt,
-					req->resolver->ups->data);
+					req->resolver->ups->data, "retransmit send failed");
 		}
 		else {
 			UPSTREAM_FAIL (req->io->srv, time (NULL));
@@ -790,7 +790,8 @@ rdns_make_request_full (
 			REF_RELEASE (req);
 
 			if (resolver->ups && serv->ups_elt) {
-				resolver->ups->fail (serv->ups_elt, resolver->ups->data);
+				resolver->ups->fail (serv->ups_elt, resolver->ups->data,
+						"send IO error");
 			}
 			else {
 				UPSTREAM_FAIL (serv, time (NULL));

src/libserver/dns.c

@@ -36,7 +36,7 @@ static struct rdns_upstream_elt* rspamd_dns_select_upstream_retransmit (
 static void rspamd_dns_upstream_ok (struct rdns_upstream_elt *elt,
 		void *ups_data);
 static void rspamd_dns_upstream_fail (struct rdns_upstream_elt *elt,
-		void *ups_data);
+		void *ups_data, const gchar *reason);
 static unsigned int rspamd_dns_upstream_count (void *ups_data);
 
 static struct rdns_upstream_context rspamd_ups_ctx = {
@@ -852,11 +852,11 @@ rspamd_dns_upstream_ok (struct rdns_upstream_elt *elt,
 
 static void
 rspamd_dns_upstream_fail (struct rdns_upstream_elt *elt,
-		void *ups_data)
+		void *ups_data, const gchar *reason)
 {
 	struct upstream *up = elt->lib_data;
 
-	rspamd_upstream_fail (up, FALSE);
+	rspamd_upstream_fail (up, FALSE, reason);
 }
 
 static unsigned int

src/libserver/fuzzy_backend_redis.c

@@ -444,7 +444,7 @@ rspamd_fuzzy_redis_shingles_callback (redisAsyncContext *c, gpointer r,
 			msg_err_redis_session ("error getting shingles: %s", c->errstr);
 		}
 
-		rspamd_upstream_fail (session->up, FALSE);
+		rspamd_upstream_fail (session->up, FALSE,  strerror (errno));
 	}
 
 	rspamd_fuzzy_redis_session_dtor (session, FALSE);
@@ -582,7 +582,7 @@ rspamd_fuzzy_redis_check_callback (redisAsyncContext *c, gpointer r,
 			msg_err_redis_session ("error getting hashes: %s", c->errstr);
 		}
 
-		rspamd_upstream_fail (session->up, FALSE);
+		rspamd_upstream_fail (session->up, FALSE,  strerror (errno));
 	}
 
 	rspamd_fuzzy_redis_session_dtor (session, FALSE);
@@ -651,7 +651,7 @@ rspamd_fuzzy_backend_check_redis (struct rspamd_fuzzy_backend *bk,
 			rspamd_inet_address_get_port (addr));
 
 	if (session->ctx == NULL) {
-		rspamd_upstream_fail (up, TRUE);
+		rspamd_upstream_fail (up, TRUE, strerror (errno));
 		rspamd_fuzzy_redis_session_dtor (session, TRUE);
 
 		if (cb) {
@@ -721,7 +721,7 @@ rspamd_fuzzy_redis_count_callback (redisAsyncContext *c, gpointer r,
 			msg_err_redis_session ("error getting count: %s", c->errstr);
 		}
 
-		rspamd_upstream_fail (session->up, FALSE);
+		rspamd_upstream_fail (session->up, FALSE,  strerror (errno));
 	}
 
 	rspamd_fuzzy_redis_session_dtor (session, FALSE);
@@ -776,7 +776,7 @@ rspamd_fuzzy_backend_count_redis (struct rspamd_fuzzy_backend *bk,
 			rspamd_inet_address_get_port (addr));
 
 	if (session->ctx == NULL) {
-		rspamd_upstream_fail (up, TRUE);
+		rspamd_upstream_fail (up, TRUE,  strerror (errno));
 		rspamd_fuzzy_redis_session_dtor (session, TRUE);
 
 		if (cb) {
@@ -844,7 +844,7 @@ rspamd_fuzzy_redis_version_callback (redisAsyncContext *c, gpointer r,
 			msg_err_redis_session ("error getting version: %s", c->errstr);
 		}
 
-		rspamd_upstream_fail (session->up, FALSE);
+		rspamd_upstream_fail (session->up, FALSE,  strerror (errno));
 	}
 
 	rspamd_fuzzy_redis_session_dtor (session, FALSE);
@@ -900,7 +900,7 @@ rspamd_fuzzy_backend_version_redis (struct rspamd_fuzzy_backend *bk,
 			rspamd_inet_address_get_port (addr));
 
 	if (session->ctx == NULL) {
-		rspamd_upstream_fail (up, FALSE);
+		rspamd_upstream_fail (up, FALSE,  strerror (errno));
 		rspamd_fuzzy_redis_session_dtor (session, TRUE);
 
 		if (cb) {
@@ -1334,7 +1334,7 @@ rspamd_fuzzy_redis_update_callback (redisAsyncContext *c, gpointer r,
 			msg_err_redis_session ("error sending update to redis: %s", c->errstr);
 		}
 
-		rspamd_upstream_fail (session->up, FALSE);
+		rspamd_upstream_fail (session->up, FALSE,  strerror (errno));
 	}
 
 	rspamd_fuzzy_redis_session_dtor (session, FALSE);
@@ -1460,7 +1460,7 @@ rspamd_fuzzy_backend_update_redis (struct rspamd_fuzzy_backend *bk,
 			rspamd_inet_address_get_port (addr));
 
 	if (session->ctx == NULL) {
-		rspamd_upstream_fail (up, TRUE);
+		rspamd_upstream_fail (up, TRUE,  strerror (errno));
 		rspamd_fuzzy_redis_session_dtor (session, TRUE);
 
 		if (cb) {

src/libstat/backends/redis_backend.c

@@ -946,7 +946,7 @@ rspamd_redis_stat_keys (redisAsyncContext *c, gpointer r, gpointer priv)
 			msg_err ("cannot get keys to gather stat: unknown error");
 		}
 
-		rspamd_upstream_fail (cbdata->selected, FALSE);
+		rspamd_upstream_fail (cbdata->selected, FALSE, c->errstr);
 		rspamd_redis_async_cbdata_cleanup (cbdata);
 		redis_elt->cbdata = NULL;
 	}
@@ -1106,7 +1106,7 @@ rspamd_redis_timeout (EV_P_ ev_timer *w, int revents)
 	msg_err_task_check ("connection to redis server %s timed out",
 			rspamd_upstream_name (rt->selected));
 
-	rspamd_upstream_fail (rt->selected, FALSE);
+	rspamd_upstream_fail (rt->selected, FALSE, "timeout");
 
 	if (rt->redis) {
 		redis = rt->redis;
@@ -1207,7 +1207,7 @@ rspamd_redis_processed (redisAsyncContext *c, gpointer r, gpointer priv)
 				rspamd_upstream_name (rt->selected), c->errstr);
 
 		if (rt->redis) {
-			rspamd_upstream_fail (rt->selected, FALSE);
+			rspamd_upstream_fail (rt->selected, FALSE, c->errstr);
 		}
 
 		if (!rt->err) {
@@ -1338,7 +1338,7 @@ rspamd_redis_connected (redisAsyncContext *c, gpointer r, gpointer priv)
 	else if (rt->has_event) {
 		msg_err_task ("error getting reply from redis server %s: %s",
 				rspamd_upstream_name (rt->selected), c->errstr);
-		rspamd_upstream_fail (rt->selected, FALSE);
+		rspamd_upstream_fail (rt->selected, FALSE,  c->errstr);
 
 		if (!rt->err) {
 			g_set_error (&rt->err, rspamd_redis_stat_quark (), c->err,
@@ -1369,7 +1369,7 @@ rspamd_redis_learned (redisAsyncContext *c, gpointer r, gpointer priv)
 				rspamd_upstream_name (rt->selected), c->errstr);
 
 		if (rt->redis) {
-			rspamd_upstream_fail (rt->selected, FALSE);
+			rspamd_upstream_fail (rt->selected, FALSE, c->errstr);
 		}
 
 		if (!rt->err) {

src/libstat/learn_cache/redis_cache.c

@@ -114,7 +114,7 @@ rspamd_redis_cache_timeout (EV_P_ ev_timer *w, int revents)
 
 	msg_err_task ("connection to redis server %s timed out",
 			rspamd_upstream_name (rt->selected));
-	rspamd_upstream_fail (rt->selected, FALSE);
+	rspamd_upstream_fail (rt->selected, FALSE, "timeout");
 
 	if (rt->has_event) {
 		rspamd_session_remove_event (task->s, rspamd_redis_cache_fin, rt);
@@ -166,7 +166,7 @@ rspamd_stat_cache_redis_get (redisAsyncContext *c, gpointer r, gpointer priv)
 		rspamd_upstream_ok (rt->selected);
 	}
 	else {
-		rspamd_upstream_fail (rt->selected, FALSE);
+		rspamd_upstream_fail (rt->selected, FALSE, c->errstr);
 	}
 
 	if (rt->has_event) {
@@ -188,7 +188,7 @@ rspamd_stat_cache_redis_set (redisAsyncContext *c, gpointer r, gpointer priv)
 		rspamd_upstream_ok (rt->selected);
 	}
 	else {
-		rspamd_upstream_fail (rt->selected, FALSE);
+		rspamd_upstream_fail (rt->selected, FALSE, c->errstr);
 	}
 
 	if (rt->has_event) {

src/libutil/http_connection.c

@@ -1197,7 +1197,7 @@ rspamd_http_connection_new_client (struct rspamd_http_context *ctx,
 				msg_info ("cannot connect to http proxy %s: %s",
 						rspamd_inet_address_to_string_pretty (proxy_addr),
 						strerror (errno));
-				rspamd_upstream_fail (up, TRUE);
+				rspamd_upstream_fail (up, TRUE, strerror (errno));
 
 				return NULL;
 			}

src/libutil/upstream.c

@@ -735,13 +735,19 @@ rspamd_upstream_set_inactive (struct upstream_list *ls, struct upstream *upstrea
 }
 
 void
-rspamd_upstream_fail (struct upstream *upstream, gboolean addr_failure)
+rspamd_upstream_fail (struct upstream *upstream,
+					  gboolean addr_failure,
+					  const gchar *reason)
 {
 	gdouble error_rate = 0, max_error_rate = 0;
 	gdouble sec_last, sec_cur;
 	struct upstream_addr_elt *addr_elt;
 	struct upstream_list_watcher *w;
 
+	msg_debug_upstream ("upstream %s failed; reason: %s",
+			upstream->name,
+			reason);
+
 	if (upstream->ctx && upstream->active_idx != -1) {
 		sec_cur = rspamd_get_ticks (FALSE);
 
@@ -780,27 +786,38 @@ rspamd_upstream_fail (struct upstream *upstream, gboolean addr_failure)
 				if (error_rate > max_error_rate) {
 					/* Remove upstream from the active list */
 					if (upstream->ls->ups->len > 1) {
-						msg_debug_upstream ("mark upstream %s inactive: %.2f "
+						msg_debug_upstream ("mark upstream %s inactive; "
+											"reason: %s; %.2f "
 											"error rate (%d errors), "
 											"%.2f max error rate, "
 											"%.1f first error time, "
 											"%.1f current ts, "
 											"%d upstreams left",
-								upstream->name, error_rate, upstream->errors,
-								max_error_rate, sec_last, sec_cur,
+								upstream->name,
+								reason,
+								error_rate,
+								upstream->errors,
+								max_error_rate,
+								sec_last,
+								sec_cur,
 								upstream->ls->alive->len - 1);
 						rspamd_upstream_set_inactive (upstream->ls, upstream);
 						upstream->errors = 0;
 					}
 					else {
 						msg_debug_upstream ("cannot mark last alive upstream %s "
-											"inactive: %.2f "
+											"inactive; reason: %s; %.2f "
 											"error rate (%d errors), "
 											"%.2f max error rate, "
 											"%.1f first error time, "
 											"%.1f current ts",
-								upstream->name, error_rate, upstream->errors,
-								max_error_rate, sec_last, sec_cur);
+								upstream->name,
+								reason,
+								error_rate,
+								upstream->errors,
+								max_error_rate,
+								sec_last,
+								sec_cur);
 						/* Just re-resolve addresses */
 						if (sec_cur - sec_last > upstream->ls->limits->revive_time) {
 							upstream->errors = 0;
@@ -819,7 +836,8 @@ rspamd_upstream_fail (struct upstream *upstream, gboolean addr_failure)
 		if (addr_failure) {
 			/* Also increase count of errors for this specific address */
 			if (upstream->addrs.addr) {
-				addr_elt = g_ptr_array_index (upstream->addrs.addr, upstream->addrs.cur);
+				addr_elt = g_ptr_array_index (upstream->addrs.addr,
+						upstream->addrs.cur);
 				addr_elt->errors++;
 			}
 		}

src/libutil/upstream.h

@@ -60,7 +60,7 @@ void rspamd_upstreams_library_config (struct rspamd_config *cfg,
 /**
  * Add an error to an upstream
  */
-void rspamd_upstream_fail (struct upstream *upstream, gboolean addr_failure);
+void rspamd_upstream_fail (struct upstream *upstream, gboolean addr_failure, const gchar *reason);
 
 /**
  * Increase upstream successes count

src/lua/lua_upstream.c

@@ -129,14 +129,22 @@ lua_upstream_fail (lua_State *L)
 	LUA_TRACE_POINT;
 	struct upstream *up = lua_check_upstream (L);
 	gboolean fail_addr = FALSE;
+	const gchar *reason = "unknown";
 
 	if (up) {
 
 		if (lua_isboolean (L, 2)) {
 			fail_addr = lua_toboolean (L, 2);
+
+			if (lua_isstring (L, 3)) {
+				reason = lua_tostring (L, 3);
+			}
+		}
+		else if (lua_isstring (L, 2)) {
+			reason = lua_tostring (L, 2);
 		}
 
-		rspamd_upstream_fail (up, fail_addr);
+		rspamd_upstream_fail (up, fail_addr, reason);
 	}
 
 	return 0;

src/plugins/fuzzy_check.c

@@ -2255,7 +2255,7 @@ fuzzy_check_timer_callback (gint fd, short what, void *arg)
 				rspamd_inet_address_to_string_pretty (
 						rspamd_upstream_addr_cur (session->server)),
 				session->retransmits);
-		rspamd_upstream_fail (session->server, TRUE);
+		rspamd_upstream_fail (session->server, TRUE, "timeout");
 
 		if (session->item) {
 			rspamd_symcache_item_async_dec_check (session->task, session->item, M);
@@ -2337,7 +2337,7 @@ fuzzy_check_io_callback (gint fd, short what, void *arg)
 			session->state == 1 ? "read" : "write",
 			errno,
 			strerror (errno));
-		rspamd_upstream_fail (session->server, TRUE);
+		rspamd_upstream_fail (session->server, TRUE, strerror (errno));
 
 		if (session->item) {
 			rspamd_symcache_item_async_dec_check (session->task, session->item, M);
@@ -2378,7 +2378,7 @@ fuzzy_controller_timer_callback (gint fd, short what, void *arg)
 	task = session->task;
 
 	if (session->retransmits >= session->rule->ctx->retransmits) {
-		rspamd_upstream_fail (session->server, TRUE);
+		rspamd_upstream_fail (session->server, TRUE, "timeout");
 		msg_err_task_check ("got IO timeout with server %s(%s), "
 							"after %d retransmits",
 				rspamd_upstream_name (session->server),
@@ -2594,7 +2594,7 @@ fuzzy_controller_io_callback (gint fd, short what, void *arg)
 				rspamd_inet_address_to_string_pretty (
 						rspamd_upstream_addr_cur (session->server)),
 				errno, strerror (errno));
-		rspamd_upstream_fail (session->server, FALSE);
+		rspamd_upstream_fail (session->server, FALSE, strerror (errno));
 	}
 
 	/*
@@ -2798,7 +2798,7 @@ register_fuzzy_client_call (struct rspamd_task *task,
 						rspamd_inet_address_to_string_pretty (addr),
 						errno,
 						strerror (errno));
-				rspamd_upstream_fail (selected, TRUE);
+				rspamd_upstream_fail (selected, TRUE, strerror (errno));
 				g_ptr_array_free (commands, TRUE);
 			} else {
 				/* Create session for a socket */
@@ -2924,7 +2924,7 @@ register_fuzzy_controller_call (struct rspamd_http_connection_entry *entry,
 					rspamd_inet_address_to_string_pretty (addr),
 					rule->name,
 					strerror (errno));
-			rspamd_upstream_fail (selected, TRUE);
+			rspamd_upstream_fail (selected, TRUE, strerror (errno));
 		}
 		else {
 			s =
@@ -3287,7 +3287,7 @@ fuzzy_check_send_lua_learn (struct fuzzy_rule *rule,
 
 			if ((sock = rspamd_inet_address_connect (addr,
 					SOCK_DGRAM, TRUE)) == -1) {
-				rspamd_upstream_fail (selected, TRUE);
+				rspamd_upstream_fail (selected, TRUE, strerror (errno));
 			} else {
 				s =
 						rspamd_mempool_alloc0 (task->task_pool,

src/rspamd_proxy.c

@@ -1293,7 +1293,7 @@ proxy_backend_mirror_error_handler (struct rspamd_http_connection *conn, GError
 	msg_info_session ("abnormally closing connection from backend: %s:%s, "
 			"error: %e",
 			bk_conn->name,
-			rspamd_inet_address_to_string (
+			rspamd_inet_address_to_string_pretty (
 					rspamd_upstream_addr_cur (bk_conn->up)),
 			err);
 
@@ -1301,7 +1301,7 @@ proxy_backend_mirror_error_handler (struct rspamd_http_connection *conn, GError
 		bk_conn->err = rspamd_mempool_strdup (session->pool, err->message);
 	}
 
-	rspamd_upstream_fail (bk_conn->up, FALSE);
+	rspamd_upstream_fail (bk_conn->up, FALSE, err ? err->message : "unknown");
 
 	proxy_backend_close_connection (bk_conn);
 	REF_RELEASE (bk_conn->s);
@@ -1378,7 +1378,7 @@ proxy_open_mirror_connections (struct rspamd_proxy_session *session)
 
 		if (bk_conn->backend_sock == -1) {
 			msg_err_session ("cannot connect upstream for %s", m->name);
-			rspamd_upstream_fail (bk_conn->up, TRUE);
+			rspamd_upstream_fail (bk_conn->up, TRUE, strerror (errno));
 			continue;
 		}
 
@@ -1519,12 +1519,12 @@ proxy_backend_master_error_handler (struct rspamd_http_connection *conn, GError
 	session = bk_conn->s;
 	session->retries ++;
 	msg_info_session ("abnormally closing connection from backend: %s, error: %e,"
-			" retries left: %d",
-		rspamd_inet_address_to_string (
-				rspamd_upstream_addr_cur (session->master_conn->up)),
-		err,
-		session->ctx->max_retries - session->retries);
-	rspamd_upstream_fail (bk_conn->up, FALSE);
+					  " retries left: %d",
+			rspamd_inet_address_to_string_pretty (
+					rspamd_upstream_addr_cur (session->master_conn->up)),
+			err,
+			session->ctx->max_retries - session->retries);
+	rspamd_upstream_fail (bk_conn->up, FALSE, err ? err->message : "unknown");
 	proxy_backend_close_connection (session->master_conn);
 
 	if (session->ctx->max_retries > 0 &&
@@ -1889,10 +1889,11 @@ retry:
 		if (session->master_conn->backend_sock == -1) {
 			msg_err_session ("cannot connect upstream: %s(%s)",
 					host ? hostbuf : "default",
-							rspamd_inet_address_to_string (
+							rspamd_inet_address_to_string_pretty (
 									rspamd_upstream_addr_cur (
 											session->master_conn->up)));
-			rspamd_upstream_fail (session->master_conn->up, TRUE);
+			rspamd_upstream_fail (session->master_conn->up, TRUE,
+					strerror (errno));
 			session->retries ++;
 			goto retry;
 		}

test/rspamd_upstream_test.c

@@ -106,7 +106,7 @@ rspamd_upstream_test_func (void)
 	next_addr = rspamd_upstream_addr_next (up);
 	g_assert (rspamd_inet_address_get_af (next_addr) == AF_INET6);
 	/* Test errors with IPv6 */
-	rspamd_upstream_fail (up, TRUE);
+	rspamd_upstream_fail (up, TRUE, NULL);
 	/* Now we should have merely IPv4 addresses in rotation */
 	addr = rspamd_upstream_addr_next (up);
 	for (i = 0; i < 256; i++) {
@@ -169,7 +169,7 @@ rspamd_upstream_test_func (void)
 
 	up = rspamd_upstream_get (ls, RSPAMD_UPSTREAM_MASTER_SLAVE, NULL, 0);
 	for (i = 0; i < 100; i ++) {
-		rspamd_upstream_fail (up, TRUE);
+		rspamd_upstream_fail (up, TRUE, NULL);
 	}
 	g_assert (rspamd_upstreams_alive (ls) == 2);