[RFC] Extending the debugging system with per-class logfiles

Ralph Böhme slow at samba.org
Mon Dec 10 15:26:27 UTC 2018


Hi folks!

I have a working WIP patchset that adds per-debug-class logfiles to our debug 
subsystem, eg

  log file = /var/log/samba/%m.log
  log level = 1 full_audit:1@/var/log/samba/audit.log

The use case that triggered the work was having vfs_full_audit log to a 
different file then "log file". This could also be achieved by changes to the 
VFS module, but we saw the general usefulness of per-class logfiles, so I took 
the stab.

I guess this could also be useful for the audit logging of AD DCs.

Fwiw, I'm extending the "log level" syntax to pass the optional per-class 
logfile, not the "log file" option, because the option requires tokenizing the 
option value which would break on any "log file" value that includes spaces (or 
an '@').

Thoughts?

WIP patch attached in case you're curious. :)

-slow

-- 
Ralph Boehme, Samba Team                https://samba.org/
Samba Developer, SerNet GmbH   https://sernet.de/en/samba/
GPG-Fingerprint   FAE2C6088A24252051C559E4AA1E9B7126399E46
-------------- next part --------------
From 0b143e99308fbd03b06f80b723c81dda8ac1e7bc Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Mon, 10 Dec 2018 14:32:13 +0100
Subject: [PATCH 1/2] lib: debug: prepare for per-class logfile

---
 lib/util/debug.c | 183 ++++++++++++++++++++++++++++++++++-------------
 1 file changed, 132 insertions(+), 51 deletions(-)

diff --git a/lib/util/debug.c b/lib/util/debug.c
index b5f120bb3a4..a892e761a57 100644
--- a/lib/util/debug.c
+++ b/lib/util/debug.c
@@ -553,23 +553,44 @@ static const char *default_classname_table[] = {
 	[DBGC_DSDB_GROUP_AUDIT_JSON] = "dsdb_group_json_audit",
 };
 
+struct debug_class {
+	/*
+	 * The debug classname.
+	 */
+	const char *class_name;
+
+	/*
+	 * An optional class specific logfile, may be NULL in which case the
+	 * "global" logfile is used.
+	 */
+	const char *logfile;
+	int fd;
+
+	/*
+	 * The debug loglevel of the class.
+	 */
+	int loglevel;
+};
+
+
 /*
  * This is to allow reading of DEBUGLEVEL_CLASS before the debug
  * system has been initialized.
  */
-static int debug_class_list_initial[ARRAY_SIZE(default_classname_table)];
+static struct debug_class
+debug_class_list_initial[ARRAY_SIZE(default_classname_table)];
 
 static size_t debug_num_classes = 0;
-static int    *DEBUGLEVEL_CLASS = debug_class_list_initial;
+static struct debug_class *DEBUGLEVEL_CLASS = debug_class_list_initial;
 
 int debuglevel_get_class(size_t idx)
 {
-	return DEBUGLEVEL_CLASS[idx];
+	return DEBUGLEVEL_CLASS[idx].loglevel;
 }
 
 void debuglevel_set_class(size_t idx, int level)
 {
-	DEBUGLEVEL_CLASS[idx] = level;
+	DEBUGLEVEL_CLASS[idx].loglevel = level;
 }
 
 
@@ -598,6 +619,7 @@ void debuglevel_set_class(size_t idx, int level)
 
 static int     debug_count    = 0;
 static int     current_msg_level   = 0;
+static int     current_msg_class   = 0;
 static char format_bufr[FORMAT_BUFR_SIZE];
 static size_t     format_pos     = 0;
 static bool    log_overflow   = false;
@@ -629,7 +651,8 @@ void gfree_debugsyms(void)
 
 	if ( DEBUGLEVEL_CLASS != debug_class_list_initial ) {
 		TALLOC_FREE( DEBUGLEVEL_CLASS );
-		DEBUGLEVEL_CLASS = discard_const_p(int, debug_class_list_initial);
+		DEBUGLEVEL_CLASS = discard_const_p(struct debug_class,
+						   debug_class_list_initial);
 	}
 
 	debug_num_classes = 0;
@@ -654,7 +677,7 @@ char *debug_list_class_names_and_levels(void)
 		buf = talloc_asprintf_append(buf,
 					     "%s:%d%s",
 					     classname_table[i],
-					     DEBUGLEVEL_CLASS[i],
+					     DEBUGLEVEL_CLASS[i].loglevel,
 					     i == (debug_num_classes - 1) ? "\n" : " ");
 		if (buf == NULL) {
 			return NULL;
@@ -687,19 +710,21 @@ static int debug_lookup_classname_int(const char* classname)
 int debug_add_class(const char *classname)
 {
 	int ndx;
-	int *new_class_list;
+	struct debug_class *new_class_list = NULL;
 	char **new_name_list;
 	int default_level;
 
-	if (!classname)
+	if (classname == NULL) {
 		return -1;
+	}
 
 	/* check the init has yet been called */
 	debug_init();
 
 	ndx = debug_lookup_classname_int(classname);
-	if (ndx >= 0)
+	if (ndx >= 0) {
 		return ndx;
+	}
 	ndx = debug_num_classes;
 
 	if (DEBUGLEVEL_CLASS == debug_class_list_initial) {
@@ -709,23 +734,32 @@ int debug_add_class(const char *classname)
 		new_class_list = DEBUGLEVEL_CLASS;
 	}
 
-	default_level = DEBUGLEVEL_CLASS[DBGC_ALL];
+	default_level = DEBUGLEVEL_CLASS[DBGC_ALL].loglevel;
 
-	new_class_list = talloc_realloc(NULL, new_class_list, int, ndx + 1);
-	if (!new_class_list)
+	new_class_list = talloc_realloc(NULL,
+					new_class_list,
+					struct debug_class,
+					ndx + 1);
+	if (new_class_list == NULL) {
 		return -1;
+	}
+
 	DEBUGLEVEL_CLASS = new_class_list;
 
-	DEBUGLEVEL_CLASS[ndx] = default_level;
+	ZERO_STRUCT(DEBUGLEVEL_CLASS[ndx]);
+	DEBUGLEVEL_CLASS[ndx].loglevel = default_level;
+	DEBUGLEVEL_CLASS[ndx].fd = -1;
 
 	new_name_list = talloc_realloc(NULL, classname_table, char *, ndx + 1);
-	if (!new_name_list)
+	if (new_name_list == NULL) {
 		return -1;
+	}
 	classname_table = new_name_list;
 
 	classname_table[ndx] = talloc_strdup(classname_table, classname);
-	if (! classname_table[ndx])
+	if (classname_table[ndx] == NULL) {
 		return -1;
+	}
 
 	debug_num_classes = ndx + 1;
 
@@ -766,7 +800,7 @@ static void debug_dump_status(int level)
 		const char *classname = classname_table[q];
 		DEBUGADD(level, ("  %s: %d\n",
 				 classname,
-				 DEBUGLEVEL_CLASS[q]));
+				 DEBUGLEVEL_CLASS[q].loglevel));
 	}
 }
 
@@ -792,7 +826,7 @@ static bool debug_parse_param(char *param)
 		return false;
 	}
 
-	DEBUGLEVEL_CLASS[ndx] = atoi(class_level);
+	DEBUGLEVEL_CLASS[ndx].loglevel = atoi(class_level);
 
 	return true;
 }
@@ -824,15 +858,15 @@ bool debug_parse_levels(const char *params_str)
 	 * v.s. "all:10", this is the traditional way to set DEBUGLEVEL
 	 */
 	if (isdigit(tok[0])) {
-		DEBUGLEVEL_CLASS[DBGC_ALL] = atoi(tok);
+		DEBUGLEVEL_CLASS[DBGC_ALL].loglevel = atoi(tok);
 		tok = strtok_r(NULL, LIST_SEP, &saveptr);
 	} else {
-		DEBUGLEVEL_CLASS[DBGC_ALL] = 0;
+		DEBUGLEVEL_CLASS[DBGC_ALL].loglevel = 0;
 	}
 
 	/* Array is debug_num_classes long */
 	for (i = DBGC_ALL+1; i < debug_num_classes; i++) {
-		DEBUGLEVEL_CLASS[i] = DEBUGLEVEL_CLASS[DBGC_ALL];
+		DEBUGLEVEL_CLASS[i].loglevel = DEBUGLEVEL_CLASS[DBGC_ALL].loglevel;
 	}
 
 	while (tok != NULL) {
@@ -1022,6 +1056,28 @@ static void debug_callback_log(const char *msg, int msg_level)
  Fix from dgibson at linuxcare.com.
 **************************************************************************/
 
+static int reopen_one_log(int *fd, const char *logfile)
+{
+	int new_fd;
+	int old_fd = -1;
+
+	new_fd = open(logfile, O_WRONLY|O_APPEND|O_CREAT, 0644);
+	if (new_fd == -1) {
+		log_overflow = true;
+		DBG_ERR("Unable to open new log file '%s': %s\n",
+			logfile, strerror(errno));
+		log_overflow = false;
+		return -1;
+	}
+
+	smb_set_close_on_exec(new_fd);
+	old_fd = *fd;
+	*fd = new_fd;
+	debug_close_fd(old_fd);
+
+	return new_fd;
+}
+
 /**
   reopen the log file (usually called because the log file name might have changed)
 */
@@ -1029,7 +1085,6 @@ bool reopen_logs_internal(void)
 {
 	mode_t oldumask;
 	int new_fd = 0;
-	int old_fd = 0;
 	bool ret = true;
 
 	if (state.reopening_logs) {
@@ -1066,18 +1121,9 @@ bool reopen_logs_internal(void)
 
 	state.reopening_logs = true;
 
-	new_fd = open( state.debugf, O_WRONLY|O_APPEND|O_CREAT, 0644);
-
+	new_fd = reopen_one_log(&state.fd, state.debugf);
 	if (new_fd == -1) {
-		log_overflow = true;
-		DEBUG(0, ("Unable to open new log file '%s': %s\n", state.debugf, strerror(errno)));
-		log_overflow = false;
 		ret = false;
-	} else {
-		smb_set_close_on_exec(new_fd);
-		old_fd = state.fd;
-		state.fd = new_fd;
-		debug_close_fd(old_fd);
 	}
 
 	/* Fix from klausr at ITAP.Physik.Uni-Stuttgart.De
@@ -1144,10 +1190,58 @@ bool need_to_check_log_size( void )
  Check to see if the log has grown to be too big.
  **************************************************************************/
 
-void check_log_size( void )
+static void do_one_check_log_size(off_t maxlog, int fd, const char *logfile)
 {
-	int         maxlog;
+	char name[strlen(logfile) + 5];
 	struct stat st;
+	int ret;
+	bool ok;
+
+	if (maxlog == 0) {
+		return;
+	}
+
+	ret = fstat(fd, &st);
+	if (ret != 0) {
+		return;
+	}
+	if (st.st_size < maxlog ) {
+		return;
+	}
+
+	(void)reopen_logs_internal();
+
+	if (fd <= 2) {
+		return;
+	}
+	ret = fstat(fd, &st);
+	if (ret != 0) {
+		return;
+	}
+	if (st.st_size < maxlog) {
+		return;
+	}
+
+	snprintf(name, sizeof(name), "%s.old", logfile);
+
+	(void)rename(logfile, name);
+
+	ok = reopen_logs_internal();
+	if (ok) {
+		return;
+	}
+	/* We failed to reopen a log - continue using the old name. */
+	(void)rename(name, logfile);
+}
+
+static void do_check_log_size(off_t maxlog)
+{
+	do_one_check_log_size(maxlog, state.fd, state.debugf);
+}
+
+void check_log_size( void )
+{
+	off_t maxlog;
 
 	/*
 	 *  We need to be root to check/change log-file, skip this and let the main
@@ -1177,23 +1271,7 @@ void check_log_size( void )
 	    (void)reopen_logs_internal();
 	}
 
-	if (maxlog && (fstat(state.fd, &st) == 0
-	    && st.st_size > maxlog )) {
-		(void)reopen_logs_internal();
-		if (state.fd > 2 && (fstat(state.fd, &st) == 0
-				     && st.st_size > maxlog)) {
-			char name[strlen(state.debugf) + 5];
-
-			snprintf(name, sizeof(name), "%s.old", state.debugf);
-
-			(void)rename(state.debugf, name);
-
-			if (!reopen_logs_internal()) {
-				/* We failed to reopen a log - continue using the old name. */
-				(void)rename(name, state.debugf);
-			}
-		}
-	}
+	do_check_log_size(maxlog);
 
 	/*
 	 * Here's where we need to panic if state.fd == 0 or -1 (invalid values)
@@ -1380,6 +1458,9 @@ bool dbghdrclass(int level, int cls, const char *location, const char *func)
 	/* Set current_msg_level. */
 	current_msg_level = level;
 
+	/* Set current message class */
+	current_msg_class = cls;
+
 	/* Don't print a header if we're logging to stdout. */
 	if ( state.logtype != DEBUG_FILE ) {
 		return( true );
@@ -1403,7 +1484,7 @@ bool dbghdrclass(int level, int cls, const char *location, const char *func)
 		goto full;
 	}
 
-	if (unlikely(DEBUGLEVEL_CLASS[ cls ] >= 10)) {
+	if (unlikely(DEBUGLEVEL_CLASS[cls].loglevel >= 10)) {
 		verbose = true;
 	}
 
-- 
2.17.2


From 55e228f7c838ef681444660be23ac3002e2c735f Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Mon, 10 Dec 2018 15:59:56 +0100
Subject: [PATCH 2/2] lib: debug: add per class logfile support

This allows configs like

    log file = /var/log/samba/%m.log
    log level = 1 full_audit:1@/var/log/samba/audit.log
---
 lib/util/debug.c | 183 ++++++++++++++++++++++++++++-------------------
 1 file changed, 108 insertions(+), 75 deletions(-)

diff --git a/lib/util/debug.c b/lib/util/debug.c
index a892e761a57..583d98ceb34 100644
--- a/lib/util/debug.c
+++ b/lib/util/debug.c
@@ -103,6 +103,79 @@ static struct {
 	.fd = 2 /* stderr by default */
 };
 
+struct debug_class {
+	/*
+	 * The debug classname.
+	 */
+	const char *class_name;
+
+	/*
+	 * An optional class specific logfile, may be NULL in which case the
+	 * "global" logfile is used.
+	 */
+	const char *logfile;
+	int fd;
+
+	/*
+	 * The debug loglevel of the class.
+	 */
+	int loglevel;
+};
+
+static const char *default_classname_table[] = {
+	[DBGC_ALL] =		"all",
+	[DBGC_TDB] =		"tdb",
+	[DBGC_PRINTDRIVERS] =	"printdrivers",
+	[DBGC_LANMAN] =		"lanman",
+	[DBGC_SMB] =		"smb",
+	[DBGC_RPC_PARSE] =	"rpc_parse",
+	[DBGC_RPC_SRV] =	"rpc_srv",
+	[DBGC_RPC_CLI] =	"rpc_cli",
+	[DBGC_PASSDB] =		"passdb",
+	[DBGC_SAM] =		"sam",
+	[DBGC_AUTH] =		"auth",
+	[DBGC_WINBIND] =	"winbind",
+	[DBGC_VFS] =		"vfs",
+	[DBGC_IDMAP] =		"idmap",
+	[DBGC_QUOTA] =		"quota",
+	[DBGC_ACLS] =		"acls",
+	[DBGC_LOCKING] =	"locking",
+	[DBGC_MSDFS] =		"msdfs",
+	[DBGC_DMAPI] =		"dmapi",
+	[DBGC_REGISTRY] =	"registry",
+	[DBGC_SCAVENGER] =	"scavenger",
+	[DBGC_DNS] =		"dns",
+	[DBGC_LDB] =		"ldb",
+	[DBGC_TEVENT] =		"tevent",
+	[DBGC_AUTH_AUDIT] =	"auth_audit",
+	[DBGC_AUTH_AUDIT_JSON] = "auth_json_audit",
+	[DBGC_KERBEROS] =       "kerberos",
+	[DBGC_DRS_REPL] =       "drs_repl",
+	[DBGC_SMB2] =           "smb2",
+	[DBGC_SMB2_CREDITS] =   "smb2_credits",
+	[DBGC_DSDB_AUDIT]  =	"dsdb_audit",
+	[DBGC_DSDB_AUDIT_JSON] = "dsdb_json_audit",
+	[DBGC_DSDB_PWD_AUDIT]  =	"dsdb_password_audit",
+	[DBGC_DSDB_PWD_AUDIT_JSON] = "dsdb_password_json_audit",
+	[DBGC_DSDB_TXN_AUDIT]  =	"dsdb_transaction_audit",
+	[DBGC_DSDB_TXN_AUDIT_JSON] = "dsdb_transaction_json_audit",
+	[DBGC_DSDB_GROUP_AUDIT] =	"dsdb_group_audit",
+	[DBGC_DSDB_GROUP_AUDIT_JSON] = "dsdb_group_json_audit",
+};
+
+/*
+ * This is to allow reading of DEBUGLEVEL_CLASS before the debug
+ * system has been initialized.
+ */
+static struct debug_class
+debug_class_list_initial[ARRAY_SIZE(default_classname_table)];
+
+static size_t debug_num_classes = 0;
+static struct debug_class *DEBUGLEVEL_CLASS = debug_class_list_initial;
+
+static int     current_msg_level   = 0;
+static int     current_msg_class   = 0;
+
 #if defined(WITH_SYSLOG) || defined(HAVE_LIBSYSTEMD_JOURNAL) || defined(HAVE_LIBSYSTEMD)
 static int debug_level_to_priority(int level)
 {
@@ -141,10 +214,15 @@ static void debug_file_log(int msg_level,
 			   const char *msg, const char *msg_no_nl)
 {
 	ssize_t ret;
+	int fd = state.fd;
+
+	if (DEBUGLEVEL_CLASS[current_msg_class].fd != -1) {
+		fd = DEBUGLEVEL_CLASS[current_msg_class].fd;
+	}
 
 	check_log_size();
 	do {
-		ret = write(state.fd, msg, strlen(msg));
+		ret = write(fd, msg, strlen(msg));
 	} while (ret == -1 && errno == EINTR);
 }
 
@@ -512,77 +590,6 @@ static void debug_backends_log(const char *msg, int msg_level)
 */
 bool    override_logfile;
 
-static const char *default_classname_table[] = {
-	[DBGC_ALL] =		"all",
-	[DBGC_TDB] =		"tdb",
-	[DBGC_PRINTDRIVERS] =	"printdrivers",
-	[DBGC_LANMAN] =		"lanman",
-	[DBGC_SMB] =		"smb",
-	[DBGC_RPC_PARSE] =	"rpc_parse",
-	[DBGC_RPC_SRV] =	"rpc_srv",
-	[DBGC_RPC_CLI] =	"rpc_cli",
-	[DBGC_PASSDB] =		"passdb",
-	[DBGC_SAM] =		"sam",
-	[DBGC_AUTH] =		"auth",
-	[DBGC_WINBIND] =	"winbind",
-	[DBGC_VFS] =		"vfs",
-	[DBGC_IDMAP] =		"idmap",
-	[DBGC_QUOTA] =		"quota",
-	[DBGC_ACLS] =		"acls",
-	[DBGC_LOCKING] =	"locking",
-	[DBGC_MSDFS] =		"msdfs",
-	[DBGC_DMAPI] =		"dmapi",
-	[DBGC_REGISTRY] =	"registry",
-	[DBGC_SCAVENGER] =	"scavenger",
-	[DBGC_DNS] =		"dns",
-	[DBGC_LDB] =		"ldb",
-	[DBGC_TEVENT] =		"tevent",
-	[DBGC_AUTH_AUDIT] =	"auth_audit",
-	[DBGC_AUTH_AUDIT_JSON] = "auth_json_audit",
-	[DBGC_KERBEROS] =       "kerberos",
-	[DBGC_DRS_REPL] =       "drs_repl",
-	[DBGC_SMB2] =           "smb2",
-	[DBGC_SMB2_CREDITS] =   "smb2_credits",
-	[DBGC_DSDB_AUDIT]  =	"dsdb_audit",
-	[DBGC_DSDB_AUDIT_JSON] = "dsdb_json_audit",
-	[DBGC_DSDB_PWD_AUDIT]  =	"dsdb_password_audit",
-	[DBGC_DSDB_PWD_AUDIT_JSON] = "dsdb_password_json_audit",
-	[DBGC_DSDB_TXN_AUDIT]  =	"dsdb_transaction_audit",
-	[DBGC_DSDB_TXN_AUDIT_JSON] = "dsdb_transaction_json_audit",
-	[DBGC_DSDB_GROUP_AUDIT] =	"dsdb_group_audit",
-	[DBGC_DSDB_GROUP_AUDIT_JSON] = "dsdb_group_json_audit",
-};
-
-struct debug_class {
-	/*
-	 * The debug classname.
-	 */
-	const char *class_name;
-
-	/*
-	 * An optional class specific logfile, may be NULL in which case the
-	 * "global" logfile is used.
-	 */
-	const char *logfile;
-	int fd;
-
-	/*
-	 * The debug loglevel of the class.
-	 */
-	int loglevel;
-};
-
-
-/*
- * This is to allow reading of DEBUGLEVEL_CLASS before the debug
- * system has been initialized.
- */
-static struct debug_class
-debug_class_list_initial[ARRAY_SIZE(default_classname_table)];
-
-static size_t debug_num_classes = 0;
-static struct debug_class *DEBUGLEVEL_CLASS = debug_class_list_initial;
-
 int debuglevel_get_class(size_t idx)
 {
 	return DEBUGLEVEL_CLASS[idx].loglevel;
@@ -618,8 +625,6 @@ void debuglevel_set_class(size_t idx, int level)
  */
 
 static int     debug_count    = 0;
-static int     current_msg_level   = 0;
-static int     current_msg_class   = 0;
 static char format_bufr[FORMAT_BUFR_SIZE];
 static size_t     format_pos     = 0;
 static bool    log_overflow   = false;
@@ -807,6 +812,7 @@ static void debug_dump_status(int level)
 static bool debug_parse_param(char *param)
 {
 	char *class_name;
+	char *class_file = NULL;
 	char *class_level;
 	char *saveptr = NULL;
 	int ndx;
@@ -816,11 +822,13 @@ static bool debug_parse_param(char *param)
 		return false;
 	}
 
-	class_level = strtok_r(NULL, "\0", &saveptr);
+	class_level = strtok_r(NULL, "@\0", &saveptr);
 	if (class_level == NULL) {
 		return false;
 	}
 
+	class_file = strtok_r(NULL, "\0", &saveptr);
+
 	ndx = debug_lookup_classname(class_name);
 	if (ndx == -1) {
 		return false;
@@ -828,6 +836,12 @@ static bool debug_parse_param(char *param)
 
 	DEBUGLEVEL_CLASS[ndx].loglevel = atoi(class_level);
 
+	if (class_file != NULL) {
+		DEBUGLEVEL_CLASS[ndx].logfile = talloc_strdup(NULL, class_file);
+		if (DEBUGLEVEL_CLASS[ndx].logfile == NULL) {
+			return false;
+		}
+	}
 	return true;
 }
 
@@ -1086,6 +1100,7 @@ bool reopen_logs_internal(void)
 	mode_t oldumask;
 	int new_fd = 0;
 	bool ret = true;
+	int i;
 
 	if (state.reopening_logs) {
 		return true;
@@ -1126,6 +1141,24 @@ bool reopen_logs_internal(void)
 		ret = false;
 	}
 
+	for (i = 0; i < debug_num_classes; i++) {
+		int fd;
+
+		if (DEBUGLEVEL_CLASS[i].logfile == NULL) {
+			debug_close_fd(DEBUGLEVEL_CLASS[i].fd);
+			DEBUGLEVEL_CLASS[i].fd = -1;
+			continue;
+		}
+
+		fd = reopen_one_log(&DEBUGLEVEL_CLASS[i].fd,
+				    DEBUGLEVEL_CLASS[i].logfile);
+		if (fd == -1) {
+			DBG_ERR("Reopen log [%s] class [%s] failed\n",
+				DEBUGLEVEL_CLASS[i].logfile,
+				DEBUGLEVEL_CLASS[i].class_name);
+		}
+	}
+
 	/* Fix from klausr at ITAP.Physik.Uni-Stuttgart.De
 	 * to fix problem where smbd's that generate less
 	 * than 100 messages keep growing the log.
-- 
2.17.2



More information about the samba-technical mailing list