From e3a552c64ba7639f294edf24da0b062f7ca896ea Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Sun, 27 Oct 2019 12:19:50 +0000 Subject: [PATCH] [Fix] Lot's of fixes in maps check logic --- src/libutil/map.c | 118 +++++++++++++++++++++++++++++--------- src/libutil/map_private.h | 1 + src/rspamd_proxy.c | 4 +- 3 files changed, 94 insertions(+), 29 deletions(-) diff --git a/src/libutil/map.c b/src/libutil/map.c index f93eafb90..808b2a69a 100644 --- a/src/libutil/map.c +++ b/src/libutil/map.c @@ -43,13 +43,19 @@ #define MAP_RELEASE(x, t) REF_RELEASE(x) #endif +enum rspamd_map_periodic_opts { + RSPAMD_MAP_SCHEDULE_NORMAL = 0, + RSPAMD_MAP_SCHEDULE_ERROR = (1u << 0u), + RSPAMD_MAP_SCHEDULE_LOCKED = (1u << 1u), + RSPAMD_MAP_SCHEDULE_INIT = (1u << 2u), +}; + static void free_http_cbdata_common (struct http_callback_data *cbd, gboolean plan_new); static void free_http_cbdata_dtor (gpointer p); static void free_http_cbdata (struct http_callback_data *cbd); static void rspamd_map_process_periodic (struct map_periodic_cbdata *cbd); -static void rspamd_map_schedule_periodic (struct rspamd_map *map, gboolean locked, - gboolean initial, gboolean errored); +static void rspamd_map_schedule_periodic (struct rspamd_map *map, int how); static gboolean read_map_file_chunks (struct rspamd_map *map, struct map_cb_data *cbdata, const gchar *fname, @@ -214,11 +220,7 @@ http_map_error (struct rspamd_http_connection *conn, cbd->addr ? rspamd_inet_address_to_string_pretty (cbd->addr) : "", err); - MAP_RETAIN (cbd->periodic, "periodic"); rspamd_map_process_periodic (cbd->periodic); - MAP_RELEASE (cbd->periodic, "periodic"); - /* Detach periodic as rspamd_map_process_periodic will destroy it */ - cbd->periodic = NULL; } MAP_RELEASE (cbd, "http_callback_data"); @@ -965,11 +967,13 @@ rspamd_map_periodic_dtor (struct map_periodic_cbdata *periodic) } if (periodic->locked) { + g_atomic_int_set (periodic->map->locked, 0); + msg_debug_map ("unlocked map %s", periodic->map->name); + if (!periodic->map->wrk->wanna_die) { - rspamd_map_schedule_periodic (periodic->map, FALSE, FALSE, FALSE); + rspamd_map_schedule_periodic (periodic->map, + RSPAMD_SYMBOL_RESULT_NORMAL); } - g_atomic_int_set (periodic->map->locked, 0); - msg_debug_map ("unlocked map"); } g_free (periodic); @@ -988,10 +992,11 @@ rspamd_map_periodic_callback (struct ev_loop *loop, ev_timer *w, int revents) } static void -rspamd_map_schedule_periodic (struct rspamd_map *map, - gboolean locked, gboolean initial, gboolean errored) +rspamd_map_schedule_periodic (struct rspamd_map *map, int how) { const gdouble error_mult = 20.0, lock_mult = 0.1; + static const gdouble min_timer_interval = 2.0; + const gchar *reason = "unknown reason"; gdouble jittered_sec; gdouble timeout; struct map_periodic_cbdata *cbd; @@ -1001,49 +1006,83 @@ rspamd_map_schedule_periodic (struct rspamd_map *map, return; } - if (map->next_check != 0) { + if (map->non_trivial && map->next_check != 0) { timeout = map->next_check - rspamd_get_calendar_ticks (); if (timeout > 0 && timeout < map->poll_timeout) { /* Early check case, jitter */ gdouble poll_timeout = map->poll_timeout; - if (errored) { + if (how & RSPAMD_MAP_SCHEDULE_ERROR) { poll_timeout = map->poll_timeout * error_mult; + reason = "early active non-trivial check (after error)"; } - else if (locked) { + else if (how & RSPAMD_MAP_SCHEDULE_LOCKED) { poll_timeout = map->poll_timeout * lock_mult; + reason = "early active non-trivial check (after being locked)"; + } + else { + reason = "early active non-trivial check"; } jittered_sec = MIN (timeout, poll_timeout); + } else if (timeout <= 0) { /* Data is already expired, need to check */ jittered_sec = 0.0; + reason = "expired non-trivial data"; } else { /* No need to check now, wait till next_check */ jittered_sec = timeout; + reason = "valid non-trivial data"; } } else { timeout = map->poll_timeout; - if (initial) { + if (how & RSPAMD_MAP_SCHEDULE_INIT) { timeout = 0.0; + reason = "init scheduled check"; } else { - if (errored) { + if (how & RSPAMD_MAP_SCHEDULE_ERROR) { timeout = map->poll_timeout * error_mult; + reason = "errored scheduled check"; } - else if (locked) { + else if (how & RSPAMD_MAP_SCHEDULE_LOCKED) { timeout = map->poll_timeout * lock_mult; + reason = "locked scheduled check"; + } + else { + reason = "normal scheduled check"; } } jittered_sec = rspamd_time_jitter (timeout, 0); } + /* Now, we do some sanity checks for jittered seconds */ + if (!(how & RSPAMD_MAP_SCHEDULE_INIT)) { + /* Never allow too low interval between timer checks, it is epxensive */ + if (jittered_sec < min_timer_interval) { + jittered_sec = rspamd_time_jitter (min_timer_interval, 0); + } + + if (map->non_trivial) { + /* + * Even if we are reported that we need to reload cache often, we + * still want to be sane in terms of events... + */ + if (jittered_sec < min_timer_interval * 2.0) { + if (map->nelts > 0) { + jittered_sec = min_timer_interval * 3.0; + } + } + } + } + cbd = g_malloc0 (sizeof (*cbd)); cbd->cbdata.state = 0; cbd->cbdata.prev_data = *map->user_data; @@ -1057,8 +1096,8 @@ rspamd_map_schedule_periodic (struct rspamd_map *map, ev_timer_init (&cbd->ev, rspamd_map_periodic_callback, jittered_sec, 0.0); ev_timer_start (map->event_loop, &cbd->ev); - msg_debug_map ("schedule new periodic event %p in %.2f seconds", - cbd, jittered_sec); + msg_debug_map ("schedule new periodic event %p in %.3f seconds for %s; reason: %s", + cbd, jittered_sec, map->name, reason); } static void @@ -1071,6 +1110,9 @@ rspamd_map_dns_callback (struct rdns_reply *reply, void *arg) map = cbd->map; + msg_debug_map ("got dns reply with code %s on stage %d", + rdns_strerror (reply->code), cbd->stage); + if (cbd->stage == http_map_terminated) { MAP_RELEASE (cbd, "http_callback_data"); return; @@ -1112,6 +1154,10 @@ rspamd_map_dns_callback (struct rdns_reply *reply, void *arg) cbd->periodic->errored = 1; rspamd_map_process_periodic (cbd->periodic); } + else { + /* We have at least one address, so we can continue... */ + cbd->stage = http_map_http_conn; + } } if (cbd->stage == http_map_http_conn && cbd->addrs->len > 0) { @@ -1121,6 +1167,8 @@ rspamd_map_dns_callback (struct rdns_reply *reply, void *arg) cbd->addr = (rspamd_inet_addr_t *)g_ptr_array_index (cbd->addrs, selected_addr_idx); + msg_debug_map ("open http connection to %s", + rspamd_inet_address_to_string_pretty (cbd->addr)); cbd->conn = rspamd_http_connection_new_client (NULL, NULL, http_map_error, @@ -1131,6 +1179,16 @@ rspamd_map_dns_callback (struct rdns_reply *reply, void *arg) if (cbd->conn != NULL) { write_http_request (cbd); } + else { + cbd->periodic->errored = TRUE; + msg_err_map ("error reading %s(%s): " + "connection with http server terminated incorrectly: %s", + cbd->bk->uri, + cbd->addr ? rspamd_inet_address_to_string_pretty (cbd->addr) : "", + strerror (errno)); + + rspamd_map_process_periodic (cbd->periodic); + } } MAP_RELEASE (cbd, "http_callback_data"); @@ -1795,28 +1853,30 @@ rspamd_map_process_periodic (struct map_periodic_cbdata *cbd) if (!cbd->locked) { if (!g_atomic_int_compare_and_exchange (cbd->map->locked, 0, 1)) { msg_debug_map ( - "don't try to reread map as it is locked by other process, " - "will reread it later"); - rspamd_map_schedule_periodic (map, TRUE, FALSE, FALSE); + "don't try to reread map %s as it is locked by other process, " + "will reread it later", cbd->map->name); + rspamd_map_schedule_periodic (map, RSPAMD_MAP_SCHEDULE_LOCKED); MAP_RELEASE (cbd, "periodic"); return; } else { - msg_debug_map ("locked map"); + msg_debug_map ("locked map %s", cbd->map->name); cbd->locked = TRUE; } } if (cbd->errored) { /* We should not check other backends if some backend has failed */ - rspamd_map_schedule_periodic (cbd->map, FALSE, FALSE, TRUE); + rspamd_map_schedule_periodic (cbd->map, RSPAMD_MAP_SCHEDULE_ERROR); if (cbd->locked) { g_atomic_int_set (cbd->map->locked, 0); + cbd->locked = FALSE; } - msg_debug_map ("unlocked map"); + msg_debug_map ("unlocked map %s, refcount=%d", cbd->map->name, + cbd->ref.refcount); MAP_RELEASE (cbd, "periodic"); return; @@ -1897,7 +1957,7 @@ rspamd_map_on_stat (struct ev_loop *loop, ev_stat *w, int revents) map->scheduled_check = NULL; } - rspamd_map_schedule_periodic (map, FALSE, TRUE, FALSE); + rspamd_map_schedule_periodic (map, RSPAMD_MAP_SCHEDULE_INIT); } } } @@ -1949,9 +2009,13 @@ rspamd_map_watch (struct rspamd_config *cfg, data->st_ev.data = map; ev_stat_start (event_loop, &data->st_ev); } + else if ((bk->protocol == MAP_PROTO_HTTP || + bk->protocol == MAP_PROTO_HTTPS) && map->active_http) { + map->non_trivial = TRUE; + } } - rspamd_map_schedule_periodic (map, FALSE, TRUE, FALSE); + rspamd_map_schedule_periodic (map, RSPAMD_MAP_SCHEDULE_INIT); cur = g_list_next (cur); } diff --git a/src/libutil/map_private.h b/src/libutil/map_private.h index adcdd9d98..c45f55f4b 100644 --- a/src/libutil/map_private.h +++ b/src/libutil/map_private.h @@ -156,6 +156,7 @@ struct rspamd_map { gdouble poll_timeout; time_t next_check; gboolean active_http; + gboolean non_trivial; /* E.g. has http backends in active mode */ /* Shared lock for temporary disabling of map reading (e.g. when this map is written by UI) */ gint *locked; gchar tag[MEMPOOL_UID_LEN]; diff --git a/src/rspamd_proxy.c b/src/rspamd_proxy.c index 66ab623f8..a01a37612 100644 --- a/src/rspamd_proxy.c +++ b/src/rspamd_proxy.c @@ -2086,8 +2086,8 @@ proxy_milter_error_handler (gint fd, struct rspamd_proxy_session *session = ud; msg_info_session ("abnormally closing milter connection from: %s, " - "error: %s", rspamd_inet_address_to_string (session->client_addr), - err->message); + "error: %e", rspamd_inet_address_to_string (session->client_addr), + err); /* Terminate session immediately */ proxy_backend_close_connection (session->master_conn); REF_RELEASE (session); -- 2.39.5