[Rework] Logger: Fix issues found so far

14 files changed, 89 insertions, 98 deletions

diff --git a/src/controller.c b/src/controller.c
index adbc2b848..23ff7237b 100644
--- a/src/controller.c
+++ b/src/controller.c
@@ -3685,7 +3685,7 @@ start_controller_worker (struct rspamd_worker *worker)
 	g_hash_table_unref (ctx->custom_commands);
 
 	REF_RELEASE (ctx->cfg);
-	rspamd_log_close (worker->srv->logger, TRUE);
+	rspamd_log_close (worker->srv->logger);
 
 	exit (EXIT_SUCCESS);
 }
diff --git a/src/fuzzy_storage.c b/src/fuzzy_storage.c
index bc13b7049..a57f07797 100644
--- a/src/fuzzy_storage.c
+++ b/src/fuzzy_storage.c
@@ -2100,7 +2100,7 @@ start_fuzzy (struct rspamd_worker *worker)
 	}
 
 	REF_RELEASE (ctx->cfg);
-	rspamd_log_close (worker->srv->logger, TRUE);
+	rspamd_log_close (worker->srv->logger);
 
 	exit (EXIT_SUCCESS);
 }
diff --git a/src/hs_helper.c b/src/hs_helper.c
index f6292be68..873dc7f88 100644
--- a/src/hs_helper.c
+++ b/src/hs_helper.c
@@ -344,7 +344,7 @@ start_hs_helper (struct rspamd_worker *worker)
 	ev_loop (ctx->event_loop, 0);
 	rspamd_worker_block_signals ();
 
-	rspamd_log_close (worker->srv->logger, TRUE);
+	rspamd_log_close (worker->srv->logger);
 	REF_RELEASE (ctx->cfg);
 
 	exit (EXIT_SUCCESS);
diff --git a/src/libserver/worker_util.c b/src/libserver/worker_util.c
index c835a4dbd..ebc6a1980 100644
--- a/src/libserver/worker_util.c
+++ b/src/libserver/worker_util.c
@@ -305,7 +305,7 @@ rspamd_worker_usr1_handler (struct rspamd_worker_signal_handler *sigh, void *arg
 {
 	struct rspamd_main *rspamd_main = sigh->worker->srv;
 
-	rspamd_log_reopen (sigh->worker->srv->logger);
+	rspamd_log_reopen (sigh->worker->srv->logger, rspamd_main->cfg, -1, -1);
 	msg_info_main ("logging reinitialised");
 
 	/* Get more signals */
@@ -996,9 +996,7 @@ rspamd_fork_worker (struct rspamd_main *rspamd_main,
 	switch (wrk->pid) {
 	case 0:
 		/* Update pid for logging */
-		rspamd_log_update_pid (cf->type, rspamd_main->logger);
-		/* To avoid atomic writes issue */
-		rspamd_log_reopen (rspamd_main->logger);
+		rspamd_log_on_fork (cf->type, rspamd_main->cfg, rspamd_main->logger);
 		wrk->pid = getpid ();
 
 		/* Init PRNG after fork */
@@ -1047,17 +1045,10 @@ rspamd_fork_worker (struct rspamd_main *rspamd_main,
 			rspamd_pidfile_close (rspamd_main->pfh);
 		}
 
-		/* Do silent log reopen to avoid collisions */
-		rspamd_log_close (rspamd_main->logger, FALSE);
-
-
 		if (rspamd_main->cfg->log_silent_workers) {
-			rspamd_main->cfg->log_level = G_LOG_LEVEL_MESSAGE;
-			rspamd_set_logger (rspamd_main->cfg, cf->type,
-					&rspamd_main->logger, rspamd_main->server_pool);
+			rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_MESSAGE);
 		}
 
-		rspamd_log_open (rspamd_main->logger);
 		wrk->start_time = rspamd_get_calendar_ticks ();
 
 		if (cf->bind_conf) {
@@ -1075,8 +1066,9 @@ rspamd_fork_worker (struct rspamd_main *rspamd_main,
 		rspamd_socket_nonblocking (wrk->control_pipe[1]);
 		rspamd_socket_nonblocking (wrk->srv_pipe[1]);
 		rspamd_main->cfg->cur_worker = wrk;
-		/* Execute worker */
+		/* Execute worker (this function should not return normally!) */
 		cf->worker->worker_start_func (wrk);
+		/* To distinguish from normal termination */
 		exit (EXIT_FAILURE);
 		break;
 	case -1:
@@ -1167,7 +1159,7 @@ rspamd_hard_terminate (struct rspamd_main *rspamd_main)
 
 	msg_err_main ("shutting down Rspamd due to fatal error");
 
-	rspamd_log_close (rspamd_main->logger, TRUE);
+	rspamd_log_close (rspamd_main->logger);
 	exit (EXIT_FAILURE);
 }
 
diff --git a/src/libutil/logger.c b/src/libutil/logger.c
index af71665fd..4fed80d3e 100644
--- a/src/libutil/logger.c
+++ b/src/libutil/logger.c
@@ -66,6 +66,12 @@ rspamd_log_close (rspamd_logger_t *logger)
 {
 	g_assert (logger != NULL);
 
+	if (logger->closed) {
+		return;
+	}
+
+	logger->closed = TRUE;
+
 	if (logger->debug_ip) {
 		rspamd_map_helper_destroy_radix (logger->debug_ip);
 	}
@@ -105,6 +111,15 @@ rspamd_log_reopen (rspamd_logger_t *rspamd_log,  struct rspamd_config *cfg,
 
 	nspec = rspamd_log->ops.reload (rspamd_log, cfg, rspamd_log->ops.specific,
 			uid, gid, &err);
+
+	if (nspec != NULL) {
+		rspamd_log->ops.specific = nspec;
+	}
+	else {
+
+	}
+
+	return nspec != NULL;
 }
 
 static void
@@ -116,7 +131,7 @@ rspamd_emergency_logger_dtor (gpointer d)
 }
 
 rspamd_logger_t *
-rspamd_log_init (rspamd_mempool_t *pool)
+rspamd_log_open_emergency (rspamd_mempool_t *pool)
 {
 	rspamd_logger_t *logger;
 	GError *err = NULL;
@@ -167,8 +182,7 @@ rspamd_log_open_specific (rspamd_mempool_t *pool,
 	rspamd_logger_t *logger;
 	GError *err = NULL;
 
-	g_assert (default_logger == NULL);
-	g_assert (emergency_logger == NULL);
+	g_assert (emergency_logger != NULL);
 
 	if (pool) {
 		logger = rspamd_mempool_alloc0 (pool, sizeof (rspamd_logger_t));
@@ -208,6 +222,17 @@ rspamd_log_open_specific (rspamd_mempool_t *pool,
 	g_assert (funcs != NULL);
 	memcpy (&logger->ops, funcs, sizeof (*funcs));
 
+	logger->ops.specific = logger->ops.init (logger, cfg, uid, gid, &err);
+
+	if (logger->ops.specific == NULL) {
+		rspamd_common_log_function (emergency_logger, G_LOG_LEVEL_CRITICAL,
+				"logger", NULL, G_STRFUNC,
+				"cannot open specific logger: %e", err);
+		g_error_free (err);
+
+		return NULL;
+	}
+
 	logger->pid = getpid ();
 	logger->process_type = ptype;
 
@@ -241,6 +266,8 @@ rspamd_log_open_specific (rspamd_mempool_t *pool,
 	}
 
 	default_logger = logger;
+
+	return logger;
 }
 
 
@@ -358,7 +385,7 @@ rspamd_log_write_ringbuffer (rspamd_logger_t *rspamd_log,
 	}
 
 	elt->pid = rspamd_log->pid;
-	elt->ptype = rspamd_log->process_type;
+	elt->ptype = g_quark_from_string (rspamd_log->process_type);
 	elt->ts = rspamd_get_calendar_ticks ();
 
 	if (id) {
@@ -846,4 +873,7 @@ struct rspamd_logger_funcs*
 rspamd_logger_set_log_function (rspamd_logger_t *logger,
 								struct rspamd_logger_funcs *nfuncs)
 {
+	/* TODO: write this */
+
+	return NULL;
 }
\ No newline at end of file
diff --git a/src/libutil/logger_console.c b/src/libutil/logger_console.c
index fae12ea11..05bb67f21 100644
--- a/src/libutil/logger_console.c
+++ b/src/libutil/logger_console.c
@@ -76,7 +76,7 @@ rspamd_log_console_init (rspamd_logger_t *logger, struct rspamd_config *cfg,
 
 	if (priv->fd == -1) {
 		g_set_error (err, CONSOLE_LOG_QUARK, errno,
-				"open_log: cannot dup console fd: %s, %s\n",
+				"open_log: cannot dup console fd: %s\n",
 				strerror (errno));
 		rspamd_log_console_dtor (logger, priv);
 
@@ -85,6 +85,10 @@ rspamd_log_console_init (rspamd_logger_t *logger, struct rspamd_config *cfg,
 
 	if (isatty (priv->fd)) {
 		priv->log_tty = true;
+
+		if (priv->log_color) {
+			priv->log_color = false;
+		}
 	}
 
 	return priv;
diff --git a/src/libutil/logger_private.h b/src/libutil/logger_private.h
index f4b6fe8d6..23361e38d 100644
--- a/src/libutil/logger_private.h
+++ b/src/libutil/logger_private.h
@@ -67,6 +67,7 @@ struct rspamd_logger_s {
 	struct rspamd_cryptobox_keypair *keypair;
 
 	guint flags;
+	gboolean closed;
 	gboolean enabled;
 	gboolean is_debug;
 	gboolean no_lock;
diff --git a/src/lua/lua_worker.c b/src/lua/lua_worker.c
index 17266ae96..4364a1b86 100644
--- a/src/lua/lua_worker.c
+++ b/src/lua/lua_worker.c
@@ -817,7 +817,7 @@ lua_worker_spawn_process (lua_State *L)
 		gint rc;
 		gchar inbuf[4];
 
-		rspamd_log_update_pid (w->cf->type, w->srv->logger);
+		rspamd_log_on_fork (w->cf->type, w->srv->cfg, w->srv->logger);
 		rc = ottery_init (w->srv->cfg->libs_ctx->ottery_cfg);
 
 		if (rc != OTTERY_ERR_NONE) {
diff --git a/src/rspamadm/configdump.c b/src/rspamadm/configdump.c
index 32e8ab3f1..de45d1cee 100644
--- a/src/rspamadm/configdump.c
+++ b/src/rspamadm/configdump.c
@@ -89,18 +89,6 @@ rspamadm_configdump_help (gboolean full_help, const struct rspamadm_command *cmd
 static void
 config_logger (rspamd_mempool_t *pool, gpointer ud)
 {
-	struct rspamd_main *rm = ud;
-
-	rm->cfg->log_type = RSPAMD_LOG_CONSOLE;
-	rm->cfg->log_level = G_LOG_LEVEL_CRITICAL;
-
-	rspamd_set_logger (rm->cfg, g_quark_try_string ("main"), &rm->logger,
-			rm->server_pool);
-	if (rspamd_log_open_priv (rm->logger, rm->workers_uid, rm->workers_gid) ==
-			-1) {
-		fprintf (stderr, "Fatal error, cannot open logfile, exiting\n");
-		exit (EXIT_FAILURE);
-	}
 }
 
 static void
diff --git a/src/rspamadm/configtest.c b/src/rspamadm/configtest.c
index 1ebabe48b..bc7afd9d8 100644
--- a/src/rspamadm/configtest.c
+++ b/src/rspamadm/configtest.c
@@ -77,25 +77,6 @@ rspamadm_configtest_help (gboolean full_help, const struct rspamadm_command *cmd
 static void
 config_logger (rspamd_mempool_t *pool, gpointer ud)
 {
-	struct rspamd_main *rm = ud;
-	GQuark configtest_quark = g_quark_from_static_string ("configtest");
-
-	rm->cfg->log_type = RSPAMD_LOG_CONSOLE;
-
-	if (quiet) {
-		rm->cfg->log_level = G_LOG_LEVEL_CRITICAL;
-	}
-	else {
-		rm->cfg->log_level = G_LOG_LEVEL_WARNING;
-	}
-
-	rspamd_set_logger (rm->cfg, configtest_quark, &rm->logger,
-			rm->server_pool);
-	if (rspamd_log_open_priv (rm->logger, rm->workers_uid, rm->workers_gid) ==
-			-1) {
-		fprintf (stderr, "Fatal error, cannot open logfile, exiting\n");
-		exit (EXIT_FAILURE);
-	}
 }
 
 static void
diff --git a/src/rspamadm/rspamadm.c b/src/rspamadm/rspamadm.c
index 775b505ee..1c1d6f52c 100644
--- a/src/rspamadm/rspamadm.c
+++ b/src/rspamadm/rspamadm.c
@@ -439,21 +439,19 @@ main (gint argc, gchar **argv, gchar **env)
 	}
 
 	/* Setup logger */
+	rspamd_main->logger = rspamd_log_open_emergency (rspamd_main->server_pool);
+
+	/* Setup logger */
 	if (verbose) {
-		cfg->log_level = G_LOG_LEVEL_DEBUG;
-		cfg->log_flags |= RSPAMD_LOG_FLAG_USEC|RSPAMD_LOG_FLAG_ENFORCED;
+		rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_DEBUG);
+		rspamd_log_set_log_flags (rspamd_main->logger,
+				RSPAMD_LOG_FLAG_USEC|RSPAMD_LOG_FLAG_ENFORCED|RSPAMD_LOG_FLAG_RSPAMADM);
 	}
 	else {
-		cfg->log_level = G_LOG_LEVEL_MESSAGE;
+		rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_MESSAGE);
+		rspamd_log_set_log_flags (rspamd_main->logger,RSPAMD_LOG_FLAG_RSPAMADM);
 	}
 
-	cfg->log_type = RSPAMD_LOG_CONSOLE;
-	/* Avoid timestamps printing */
-	cfg->log_flags |= RSPAMD_LOG_FLAG_RSPAMADM;
-	rspamd_set_logger (cfg, process_quark, &rspamd_main->logger,
-			rspamd_main->server_pool);
-	(void) rspamd_log_open (rspamd_main->logger);
-
 	rspamd_main->event_loop = ev_default_loop (EVFLAG_SIGNALFD|EVBACKEND_ALL);
 
 	resolver = rspamd_dns_resolver_init (rspamd_main->logger,
@@ -616,7 +614,7 @@ end:
 	rspamd_dns_resolver_deinit (resolver);
 	REF_RELEASE (rspamd_main->cfg);
 	rspamd_http_context_free (rspamd_main->http_ctx);
-	rspamd_log_close (rspamd_main->logger, TRUE);
+	rspamd_log_close (rspamd_main->logger);
 	rspamd_url_deinit ();
 	g_ptr_array_free (all_commands, TRUE);
 	ev_loop_destroy (rspamd_main->event_loop);
diff --git a/src/rspamd.c b/src/rspamd.c
index 108b22996..9a95c416a 100644
--- a/src/rspamd.c
+++ b/src/rspamd.c
@@ -257,12 +257,18 @@ config_logger (rspamd_mempool_t *pool, gpointer ud)
 {
 	struct rspamd_main *rspamd_main = ud;
 
-	rspamd_set_logger (rspamd_main->cfg, g_quark_try_string ("main"),
-			&rspamd_main->logger, rspamd_main->server_pool);
+	rspamd_main->logger = rspamd_log_open_specific (rspamd_main->server_pool,
+			rspamd_main->cfg,
+			"main",
+			rspamd_main->workers_uid,
+			rspamd_main->workers_gid);
 
-	if (rspamd_log_open_priv (rspamd_main->logger,
-			rspamd_main->workers_uid, rspamd_main->workers_gid) == -1) {
-		fprintf (stderr, "Fatal error, cannot open logfile, exiting\n");
+	if (rspamd_main->logger == NULL) {
+		/*
+		 * XXX:
+		 * Error has been already logged (in fact,
+		 * we might fall back to console logger here)
+		 */
 		exit (EXIT_FAILURE);
 	}
 
@@ -287,24 +293,18 @@ reread_config (struct rspamd_main *rspamd_main)
 	tmp_cfg->cfg_name = cfg_file;
 	old_cfg = rspamd_main->cfg;
 	rspamd_main->cfg = tmp_cfg;
+	rspamd_logger_t *old_logger = rspamd_main->logger;
 
 	if (!load_rspamd_config (rspamd_main, tmp_cfg, TRUE, load_opts, TRUE)) {
 		rspamd_main->cfg = old_cfg;
-		rspamd_log_close_priv (rspamd_main->logger,
-					FALSE,
-					rspamd_main->workers_uid,
-					rspamd_main->workers_gid);
-		rspamd_set_logger (rspamd_main->cfg, g_quark_try_string ("main"),
-				&rspamd_main->logger, rspamd_main->server_pool);
-		rspamd_log_open_priv (rspamd_main->logger,
-					rspamd_main->workers_uid,
-					rspamd_main->workers_gid);
+		rspamd_main->logger = old_logger;
 		msg_err_main ("cannot parse new config file, revert to old one");
 		REF_RELEASE (tmp_cfg);
 
 		return FALSE;
 	}
 	else {
+		rspamd_log_close (old_logger);
 		msg_info_main ("replacing config");
 		REF_RELEASE (old_cfg);
 		rspamd_main->cfg->rspamd_user = rspamd_user;
@@ -975,7 +975,8 @@ rspamd_usr1_handler (struct ev_loop *loop, ev_signal *w, int revents)
 	struct rspamd_main *rspamd_main = (struct rspamd_main *)w->data;
 
 	if (!rspamd_main->wanna_die) {
-		rspamd_log_reopen_priv (rspamd_main->logger,
+		rspamd_log_reopen (rspamd_main->logger,
+				rspamd_main->cfg,
 				rspamd_main->workers_uid,
 				rspamd_main->workers_gid);
 		msg_info_main ("logging reinitialised");
@@ -1029,12 +1030,6 @@ rspamd_hup_handler (struct ev_loop *loop, ev_signal *w, int revents)
 		/* Detach existing workers and stop their heartbeats */
 		g_hash_table_foreach (rspamd_main->workers, stop_srv_ev, rspamd_main);
 
-		/* Close log to avoid FDs leak, as reread_config will re-init logging */
-		rspamd_log_close_priv (rspamd_main->logger,
-				FALSE,
-				rspamd_main->workers_uid,
-				rspamd_main->workers_gid);
-
 		if (reread_config (rspamd_main)) {
 			msg_info_main ("kill old workers");
 			g_hash_table_foreach (rspamd_main->workers, kill_old_workers, NULL);
@@ -1237,10 +1232,16 @@ main (gint argc, gchar **argv, gchar **env)
 	type = g_quark_from_static_string ("main");
 
 	/* First set logger to console logger */
-	rspamd_main->logger = rspamd_log_init (rspamd_main->server_pool);
-	rspamd_set_logger (rspamd_main->cfg, type,
-			&rspamd_main->logger, rspamd_main->server_pool);
-	(void) rspamd_log_open (rspamd_main->logger);
+	rspamd_main->logger = rspamd_log_open_emergency (rspamd_main->server_pool);
+	g_assert (rspamd_main->logger != NULL);
+
+	if (is_debug) {
+		rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_DEBUG);
+	}
+	else {
+		rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_MESSAGE);
+	}
+
 	g_log_set_default_handler (rspamd_glib_log_function, rspamd_main->logger);
 	g_set_printerr_handler (rspamd_glib_printerr_function);
 
@@ -1255,10 +1256,6 @@ main (gint argc, gchar **argv, gchar **env)
 
 	/* Init listen sockets hash */
 	listen_sockets = g_hash_table_new (g_direct_hash, g_direct_equal);
-
-	rspamd_log_close_priv (rspamd_main->logger, FALSE,
-			rspamd_main->workers_uid, rspamd_main->workers_gid);
-
 	sqlite3_initialize ();
 
 	/* Load config */
@@ -1274,7 +1271,7 @@ main (gint argc, gchar **argv, gchar **env)
 
 	/* Force debug log */
 	if (is_debug) {
-		rspamd_main->cfg->log_level = G_LOG_LEVEL_DEBUG;
+		rspamd_log_set_log_level (rspamd_main->logger, G_LOG_LEVEL_DEBUG);
 	}
 
 	/* Create rolling history */
@@ -1452,7 +1449,7 @@ main (gint argc, gchar **argv, gchar **env)
 	msg_info_main ("terminating...");
 
 	REF_RELEASE (rspamd_main->cfg);
-	rspamd_log_close (rspamd_main->logger, TRUE);
+	rspamd_log_close (rspamd_main->logger);
 	g_hash_table_unref (rspamd_main->spairs);
 	g_hash_table_unref (rspamd_main->workers);
 	rspamd_mempool_delete (rspamd_main->server_pool);
diff --git a/src/rspamd_proxy.c b/src/rspamd_proxy.c
index 7e460c040..5050a3f65 100644
--- a/src/rspamd_proxy.c
+++ b/src/rspamd_proxy.c
@@ -2369,7 +2369,7 @@ start_rspamd_proxy (struct rspamd_worker *worker)
 	}
 
 	REF_RELEASE (ctx->cfg);
-	rspamd_log_close (worker->srv->logger, TRUE);
+	rspamd_log_close (worker->srv->logger);
 
 	exit (EXIT_SUCCESS);
 }
diff --git a/src/worker.c b/src/worker.c
index 7d9550249..b75cb0317 100644
--- a/src/worker.c
+++ b/src/worker.c
@@ -561,7 +561,7 @@ start_worker (struct rspamd_worker *worker)
 
 	rspamd_stat_close ();
 	REF_RELEASE (ctx->cfg);
-	rspamd_log_close (worker->srv->logger, TRUE);
+	rspamd_log_close (worker->srv->logger);
 
 	exit (EXIT_SUCCESS);
 }