From 7c7a2fa1be14964fd71eb1e22779e4e9c3b2f1e8 Mon Sep 17 00:00:00 2001
From: Ilya Markov <imarkov@tarantool.org>
Date: Tue, 27 Mar 2018 22:44:07 +0300
Subject: [PATCH] log: Fix syslog logger

* Remove rewriting format of default logger in case of syslog option.
* Add facility option parsing and use parsed results in format message
  according to RFC3164. Possible values and default value of syslog
  facility are taken from nginx (https://nginx.ru/en/docs/syslog.html)
* Move initialization of logger type and format fucntion before
  initialization of descriptor in log_XXX_init, so that we can test
  format function of syslog logger.

Closes gh-3244.
---
 src/say.c            | 89 ++++++++++++++++++++++++++++++++++----------
 src/say.h            | 31 ++++++++++++++-
 test/unit/say.c      | 37 ++++++++++++++++--
 test/unit/say.result | 37 ++++++++++++------
 4 files changed, 158 insertions(+), 36 deletions(-)

diff --git a/src/say.c b/src/say.c
index 53402bcfee..4df2116c1e 100644
--- a/src/say.c
+++ b/src/say.c
@@ -192,16 +192,17 @@ say_set_log_level(int new_level)
 void
 say_set_log_format(enum say_format format)
 {
-
+	/*
+	 * For syslog, default or boot log type the log format can
+	 * not be changed.
+	 */
+	bool allowed_to_change = log_default->type == SAY_LOGGER_STDERR ||
+				 log_default->type == SAY_LOGGER_PIPE ||
+				 log_default->type == SAY_LOGGER_FILE;
 	switch (format) {
 	case SF_JSON:
-		/*
-		 * For syslog, default or boot log type the log format can
-		 * not be changed.
-		 */
-		if (log_default->type != SAY_LOGGER_STDERR &&
-		    log_default->type != SAY_LOGGER_PIPE &&
-		    log_default->type != SAY_LOGGER_FILE) {
+
+		if (!allowed_to_change) {
 			say_error("json log format is not supported when output is '%s'",
 				  say_logger_type_strs[log_default->type]);
 			return;
@@ -209,6 +210,9 @@ say_set_log_format(enum say_format format)
 		log_set_format(log_default, say_format_json);
 		break;
 	case SF_PLAIN:
+		if (!allowed_to_change) {
+			return;
+		}
 		log_set_format(log_default, say_format_plain);
 		break;
 	default:
@@ -356,6 +360,8 @@ log_pipe_init(struct log *log, const char *init_str)
 	char cmd[] = { "/bin/sh" };
 	char args[] = { "-c" };
 	char *argv[] = { cmd, args, (char *) init_str, NULL };
+	log->type = SAY_LOGGER_PIPE;
+	log->format_func = say_format_plain;
 	sigset_t mask;
 	sigemptyset(&mask);
 	sigaddset(&mask, SIGCHLD);
@@ -416,8 +422,6 @@ log_pipe_init(struct log *log, const char *init_str)
 	sigprocmask(SIG_UNBLOCK, &mask, NULL);
 	close(pipefd[0]);
 	log->fd = pipefd[1];
-	log->type = SAY_LOGGER_PIPE;
-	log->format_func = say_format_plain;
 	return 0;
 }
 
@@ -430,6 +434,8 @@ log_file_init(struct log *log, const char *init_str)
 {
 	int fd;
 	log->path = abspath(init_str);
+	log->type = SAY_LOGGER_FILE;
+	log->format_func = say_format_plain;
 	if (log->path == NULL) {
 		diag_set(OutOfMemory, strlen(init_str), "malloc", "abspath");
 		return -1;
@@ -441,8 +447,6 @@ log_file_init(struct log *log, const char *init_str)
 		return -1;
 	}
 	log->fd = fd;
-	log->type = SAY_LOGGER_FILE;
-	log->format_func = say_format_plain;
 	return 0;
 }
 
@@ -487,6 +491,9 @@ static int
 log_syslog_init(struct log *log, const char *init_str)
 {
 	struct say_syslog_opts opts;
+	log->type = SAY_LOGGER_SYSLOG;
+	/* syslog supports only one formatting function */
+	log->format_func = say_format_syslog;
 
 	if (say_parse_syslog_opts(init_str, &opts) < 0)
 		return -1;
@@ -495,6 +502,11 @@ log_syslog_init(struct log *log, const char *init_str)
 		log->syslog_ident = strdup("tarantool");
 	else
 		log->syslog_ident = strdup(opts.identity);
+
+	if (opts.facility == syslog_facility_MAX)
+		log->syslog_facility = SYSLOG_LOCAL7;
+	else
+		log->syslog_facility = opts.facility;
 	say_free_syslog_opts(&opts);
 	log->fd = log_syslog_connect(log);
 	if (log->fd < 0) {
@@ -502,9 +514,6 @@ log_syslog_init(struct log *log, const char *init_str)
 		diag_set(SystemError, "syslog logger: %s", strerror(errno));
 		return -1;
 	}
-	log->type = SAY_LOGGER_SYSLOG;
-	/* syslog supports only one formatting function */
-	log->format_func = say_format_syslog;
 	return 0;
 }
 
@@ -835,14 +844,14 @@ say_format_syslog(struct log *log, char *buf, int len, int level, const char *fi
 
 	/* Format syslog header according to RFC */
 	int prio = level_to_syslog_priority(level);
-	SNPRINT(total, snprintf, buf, len, "<%d>", LOG_MAKEPRI(1, prio));
+	SNPRINT(total, snprintf, buf, len, "<%d>",
+		LOG_MAKEPRI(8 * log->syslog_facility, prio));
 	SNPRINT(total, strftime, buf, len, "%h %e %T ", &tm);
 	SNPRINT(total, snprintf, buf, len, "%s[%d]:", log->syslog_ident, getpid());
 
 	/* Format message */
 	SNPRINT(total, say_format_plain_tail, buf, len, level, filename, line,
 		error, format, ap);
-
 	return total;
 }
 
@@ -996,11 +1005,45 @@ say_parse_logger_type(const char **str, enum say_logger_type *type)
 	return 0;
 }
 
+static const char *syslog_facility_strs[] = {
+	[SYSLOG_KERN] = "kern",
+	[SYSLOG_USER] = "user",
+	[SYSLOG_MAIL] = "mail",
+	[SYSLOG_DAEMON] = "daemon",
+	[SYSLOG_AUTH] = "auth",
+	[SYSLOG_INTERN] = "intern",
+	[SYSLOG_LPR] = "lpr",
+	[SYSLOG_NEWS] = "news",
+	[SYSLOG_UUCP] = "uucp",
+	[SYSLOG_CLOCK] = "clock",
+	[SYSLOG_AUTHPRIV] = "authpriv",
+	[SYSLOG_FTP] = "ftp",
+	[SYSLOG_NTP] = "ntp",
+	[SYSLOG_AUDIT] = "audit",
+	[SYSLOG_ALERT] = "alert",
+	[SYSLOG_CRON] = "cron",
+	[SYSLOG_LOCAL0] = "local0",
+	[SYSLOG_LOCAL1] = "local1",
+	[SYSLOG_LOCAL2] = "local2",
+	[SYSLOG_LOCAL3] = "local3",
+	[SYSLOG_LOCAL4] = "local4",
+	[SYSLOG_LOCAL5] = "local5",
+	[SYSLOG_LOCAL6] = "local6",
+	[SYSLOG_LOCAL7] = "local7",
+	[syslog_facility_MAX] = "unknown",
+};
+
+enum syslog_facility
+say_syslog_facility_by_name(const char *facility)
+{
+	return STR2ENUM(syslog_facility, facility);
+}
+
 int
 say_parse_syslog_opts(const char *init_str, struct say_syslog_opts *opts)
 {
 	opts->identity = NULL;
-	opts->facility = NULL;
+	opts->facility = syslog_facility_MAX;
 	opts->copy = strdup(init_str);
 	if (opts->copy == NULL) {
 		diag_set(OutOfMemory, strlen(init_str), "malloc", "opts->copy");
@@ -1020,9 +1063,14 @@ say_parse_syslog_opts(const char *init_str, struct say_syslog_opts *opts)
 				goto duplicate;
 			opts->identity = value;
 		} else if (say_parse_prefix(&value, "facility=")) {
-			if (opts->facility != NULL)
+			if (opts->facility != syslog_facility_MAX)
 				goto duplicate;
-			opts->facility = value;
+			opts->facility = say_syslog_facility_by_name(value);
+			if (opts->facility == syslog_facility_MAX) {
+				diag_set(IllegalParams, "bad syslog facility option '%s'",
+					 value);
+				goto error;
+			}
 		} else {
 			diag_set(IllegalParams, "bad option '%s'", option);
 			goto error;
@@ -1056,6 +1104,7 @@ log_destroy(struct log *log)
 	if (log->fd != -1)
 		close(log->fd);
 	free(log->syslog_ident);
+	free(log->path);
 	rlist_del_entry(log, in_log_list);
 	ev_async_stop(loop(), &log->log_async);
 	fiber_cond_destroy(&log->rotate_cond);
diff --git a/src/say.h b/src/say.h
index c05ec7419d..f324c279ef 100644
--- a/src/say.h
+++ b/src/say.h
@@ -99,6 +99,34 @@ enum say_logger_type {
 	SAY_LOGGER_SYSLOG
 };
 
+enum syslog_facility {
+	SYSLOG_KERN = 0,
+	SYSLOG_USER,
+	SYSLOG_MAIL,
+	SYSLOG_DAEMON,
+	SYSLOG_AUTH,
+	SYSLOG_INTERN,
+	SYSLOG_LPR,
+	SYSLOG_NEWS,
+	SYSLOG_UUCP,
+	SYSLOG_CLOCK,
+	SYSLOG_AUTHPRIV,
+	SYSLOG_FTP,
+	SYSLOG_NTP,
+	SYSLOG_AUDIT,
+	SYSLOG_ALERT,
+	SYSLOG_CRON,
+	SYSLOG_LOCAL0,
+	SYSLOG_LOCAL1,
+	SYSLOG_LOCAL2,
+	SYSLOG_LOCAL3,
+	SYSLOG_LOCAL4,
+	SYSLOG_LOCAL5,
+	SYSLOG_LOCAL6,
+	SYSLOG_LOCAL7,
+	syslog_facility_MAX,
+};
+
 struct log;
 
 typedef int (*log_format_func_t)(struct log *log, char *buf, int len, int level,
@@ -132,6 +160,7 @@ struct log {
 	struct fiber_cond rotate_cond;
 	/** Counter identifying number of threads executing log_rotate. */
 	int rotating_threads;
+	enum syslog_facility syslog_facility;
 	struct rlist in_log_list;
 };
 
@@ -362,7 +391,7 @@ say_parse_logger_type(const char **str, enum say_logger_type *type);
 /** Syslog logger initialization params */
 struct say_syslog_opts {
 	const char *identity;
-	const char *facility;
+	enum syslog_facility facility;
 	/* Input copy (content unspecified). */
 	char *copy;
 };
diff --git a/test/unit/say.c b/test/unit/say.c
index 0ffd2679b7..511783fe57 100644
--- a/test/unit/say.c
+++ b/test/unit/say.c
@@ -6,6 +6,8 @@
 #include <pthread.h>
 #include <errinj.h>
 #include <coio_task.h>
+#include <sys/socket.h>
+#include <sys/un.h>
 
 int
 parse_logger_type(const char *input)
@@ -41,7 +43,7 @@ parse_syslog_opts(const char *input)
 	if (opts.identity)
 		note("identity: %s", opts.identity);
 	if (opts.facility)
-		note("facility: %s", opts.facility);
+		note("facility: %i", opts.facility);
 	say_free_syslog_opts(&opts);
 	return 0;
 }
@@ -160,7 +162,7 @@ int main()
 	fiber_init(fiber_c_invoke);
 	say_logger_init("/dev/null", S_INFO, 0, "plain", 0);
 
-	plan(23);
+	plan(33);
 
 #define PARSE_LOGGER_TYPE(input, rc) \
 	ok(parse_logger_type(input) == rc, "%s", input)
@@ -185,7 +187,10 @@ int main()
 	PARSE_SYSLOG_OPTS("identity=tarantool", 0);
 	PARSE_SYSLOG_OPTS("facility=user", 0);
 	PARSE_SYSLOG_OPTS("identity=xtarantoolx,facility=local1", 0);
-	PARSE_SYSLOG_OPTS("facility=foo,identity=bar", 0);
+	PARSE_SYSLOG_OPTS("identity=xtarantoolx,facility=kern", 0);
+	PARSE_SYSLOG_OPTS("identity=xtarantoolx,facility=uucp", 0);
+	PARSE_SYSLOG_OPTS("identity=xtarantoolx,facility=foo", -1);
+	PARSE_SYSLOG_OPTS("facility=authpriv,identity=bar", 0);
 	PARSE_SYSLOG_OPTS("invalid=", -1);
 	PARSE_SYSLOG_OPTS("facility=local1,facility=local2", -1);
 	PARSE_SYSLOG_OPTS("identity=foo,identity=bar", -1);
@@ -206,7 +211,7 @@ int main()
 	log_set_format(&test_log, format_func_custom);
 	log_say(&test_log, 0, NULL, 0, NULL, "hello %s", "user");
 
-	FILE* fd = fopen(tmp_filename, "r");
+	FILE* fd = fopen(tmp_filename, "r+");
 	const size_t len = 4096;
 	char line[len];
 
@@ -234,6 +239,30 @@ int main()
 	fiber_wakeup(test);
 	ev_run(loop(), 0);
 
+	/*
+	 * Ignore possible failure of log_create(). It may fail
+	 * connecting to /dev/log or its analogs. We need only
+	 * the format function here, as we change log.fd to file
+	 * descriptor.
+	 */
+	log_create(&test_log, "syslog:identity=tarantool,facility=local0", false);
+	test_log.fd = fileno(fd);
+	/*
+	 * redirect stderr to /dev/null in order to filter
+	 * it out from result file.
+	 */
+	ok(freopen("/dev/null", "w", stderr) != NULL, "freopen");
+	ok(strncmp(test_log.syslog_ident, "tarantool", 9) == 0, "parsed identity");
+	ok(test_log.syslog_facility == SYSLOG_LOCAL0, "parsed facility");
+	long before = ftell(fd);
+	ok(before >= 0, "ftell");
+	ok(log_say(&test_log, 0, NULL, 0, NULL, "hello %s", "user") > 0, "log_say");
+	ok(fseek(fd, before, SEEK_SET) >= 0, "fseek");
+
+	if (fgets(line, len, fd) != NULL) {
+		ok(strstr(line, "<131>") != NULL, "syslog line");
+	}
+	log_destroy(&test_log);
 	fiber_free();
 	memory_free();
 	return check_plan();
diff --git a/test/unit/say.result b/test/unit/say.result
index dfd3fc0efd..8dfed7b610 100644
--- a/test/unit/say.result
+++ b/test/unit/say.result
@@ -1,4 +1,4 @@
-1..23
+1..33
 # type: file
 # next: 
 ok 1 - 
@@ -33,20 +33,35 @@ ok 10 - syslog:identity=
 ok 11 - unknown:
 # next: unknown:example.org
 ok 12 - unknown:example.org
+# facility: 24
 ok 13 - 
 # identity: tarantool
+# facility: 24
 ok 14 - identity=tarantool
-# facility: user
+# facility: 1
 ok 15 - facility=user
 # identity: xtarantoolx
-# facility: local1
+# facility: 17
 ok 16 - identity=xtarantoolx,facility=local1
+# identity: xtarantoolx
+ok 17 - identity=xtarantoolx,facility=kern
+# identity: xtarantoolx
+# facility: 8
+ok 18 - identity=xtarantoolx,facility=uucp
+ok 19 - identity=xtarantoolx,facility=foo
 # identity: bar
-# facility: foo
-ok 17 - facility=foo,identity=bar
-ok 18 - invalid=
-ok 19 - facility=local1,facility=local2
-ok 20 - identity=foo,identity=bar
-ok 21 - plain
-ok 22 - json
-ok 23 - custom
+# facility: 10
+ok 20 - facility=authpriv,identity=bar
+ok 21 - invalid=
+ok 22 - facility=local1,facility=local2
+ok 23 - identity=foo,identity=bar
+ok 24 - plain
+ok 25 - json
+ok 26 - custom
+ok 27 - freopen
+ok 28 - parsed identity
+ok 29 - parsed facility
+ok 30 - ftell
+ok 31 - log_say
+ok 32 - fseek
+ok 33 - syslog line
-- 
GitLab