Merge pull request #17155 from opensourcerouting/memstats-zlog

lib: `debug memstats-at-exit` improvements

Author: donaldsharp

lib/libfrr.c

@@ -1239,10 +1239,6 @@ void frr_early_fini(void)
 
 void frr_fini(void)
 {
-	FILE *fp;
-	char filename[128];
-	int have_leftovers = 0;
-
 	hook_call(frr_fini);
 
 	vty_terminate();
@@ -1263,32 +1259,27 @@ void frr_fini(void)
 	event_master_free(master);
 	master = NULL;
 	zlog_tls_buffer_fini();
-	zlog_fini();
+
+	if (0) {
+		/* this is intentionally disabled.  zlog remains running until
+		 * exit(), so even the very last item done during shutdown can
+		 * have its zlog() messages written out.
+		 *
+		 * Yes this causes memory leaks.  They are explicitly marked
+		 * with DEFINE_MGROUP_ACTIVEATEXIT, which is only used for
+		 * log target memory allocations, and excluded from leak
+		 * reporting at shutdown.  This is strongly preferable over
+		 * just discarding error messages at shutdown.
+		 */
+		zlog_fini();
+	}
+
 	/* frrmod_init -> nothing needed / hooks */
 	rcu_shutdown();
 
 	frrmod_terminate();
 
-	/* also log memstats to stderr when stderr goes to a file*/
-	if (debug_memstats_at_exit || !isatty(STDERR_FILENO))
-		have_leftovers = log_memstats(stderr, di->name);
-
-	/* in case we decide at runtime that we want exit-memstats for
-	 * a daemon
-	 * (only do this if we actually have something to print though)
-	 */
-	if (!debug_memstats_at_exit || !have_leftovers)
-		return;
-
-	snprintf(filename, sizeof(filename), "/tmp/frr-memstats-%s-%llu-%llu",
-		 di->name, (unsigned long long)getpid(),
-		 (unsigned long long)time(NULL));
-
-	fp = fopen(filename, "w");
-	if (fp) {
-		log_memstats(fp, di->name);
-		fclose(fp);
-	}
+	log_memstats(di->name, debug_memstats_at_exit);
 }
 
 struct json_object *frr_daemon_state_load(void)

lib/log.c

@@ -306,7 +306,7 @@ void memory_oom(size_t size, const char *name)
 	     "out of memory: failed to allocate %zu bytes for %s object",
 	     size, name);
 	zlog_backtrace(LOG_CRIT);
-	log_memstats(stderr, "log");
+	log_memstats(zlog_progname, true);
 	abort();
 }
 

lib/memory.c

@@ -148,35 +148,108 @@ int qmem_walk(qmem_walk_fn *func, void *arg)
 }
 
 struct exit_dump_args {
-	FILE *fp;
-	const char *prefix;
+	const char *daemon_name;
+	bool do_log;
+	bool do_file;
+	bool do_stderr;
 	int error;
+	FILE *fp;
+	struct memgroup *last_mg;
 };
 
+static void qmem_exit_fopen(struct exit_dump_args *eda)
+{
+	char filename[128];
+
+	if (eda->fp || !eda->do_file || !eda->daemon_name)
+		return;
+
+	snprintf(filename, sizeof(filename), "/tmp/frr-memstats-%s-%llu-%llu", eda->daemon_name,
+		 (unsigned long long)getpid(), (unsigned long long)time(NULL));
+	eda->fp = fopen(filename, "w");
+
+	if (!eda->fp) {
+		zlog_err("failed to open memstats dump file %pSQq: %m", filename);
+		/* don't try opening file over and over again */
+		eda->do_file = false;
+	}
+}
+
 static int qmem_exit_walker(void *arg, struct memgroup *mg, struct memtype *mt)
 {
 	struct exit_dump_args *eda = arg;
+	const char *prefix = eda->daemon_name ?: "NONE";
+	char size[32];
+
+	if (!mt)
+		/* iterator calls mg=X, mt=NULL first */
+		return 0;
 
-	if (!mt) {
-		fprintf(eda->fp,
-			"%s: showing active allocations in memory group %s\n",
-			eda->prefix, mg->name);
+	if (!mt->n_alloc)
+		return 0;
 
-	} else if (mt->n_alloc) {
-		char size[32];
-		if (!mg->active_at_exit)
-			eda->error++;
+	if (mt->size != SIZE_VAR)
 		snprintf(size, sizeof(size), "%10zu", mt->size);
-		fprintf(eda->fp, "%s: memstats:  %-30s: %6zu * %s\n",
-			eda->prefix, mt->name, mt->n_alloc,
-			mt->size == SIZE_VAR ? "(variably sized)" : size);
+	else
+		snprintf(size, sizeof(size), "(variably sized)");
+
+	if (mg->active_at_exit) {
+		/* not an error - this memgroup has allocations remain active
+		 * at exit.  Only printed to zlog_debug.
+		 */
+		if (!eda->do_log)
+			return 0;
+
+		if (eda->last_mg != mg) {
+			zlog_debug("showing active allocations in memory group %s (not an error)",
+				   mg->name);
+			eda->last_mg = mg;
+		}
+		zlog_debug("memstats:  %-30s: %6zu * %s", mt->name, mt->n_alloc, size);
+		return 0;
 	}
+
+	eda->error++;
+	if (eda->do_file)
+		qmem_exit_fopen(eda);
+
+	if (eda->last_mg != mg) {
+		if (eda->do_log)
+			zlog_warn("showing active allocations in memory group %s", mg->name);
+		if (eda->do_stderr)
+			fprintf(stderr, "%s: showing active allocations in memory group %s\n",
+				prefix, mg->name);
+		if (eda->fp)
+			fprintf(eda->fp, "%s: showing active allocations in memory group %s\n",
+				prefix, mg->name);
+		eda->last_mg = mg;
+	}
+
+	if (eda->do_log)
+		zlog_warn("memstats:  %-30s: %6zu * %s", mt->name, mt->n_alloc, size);
+	if (eda->do_stderr)
+		fprintf(stderr, "%s: memstats:  %-30s: %6zu * %s\n", prefix, mt->name, mt->n_alloc,
+			size);
+	if (eda->fp)
+		fprintf(eda->fp, "%s: memstats:  %-30s: %6zu * %s\n", prefix, mt->name, mt->n_alloc,
+			size);
 	return 0;
 }
 
-int log_memstats(FILE *fp, const char *prefix)
+int log_memstats(const char *daemon_name, bool enabled)
 {
-	struct exit_dump_args eda = {.fp = fp, .prefix = prefix, .error = 0};
+	struct exit_dump_args eda = {
+		.daemon_name = daemon_name,
+		.do_log = enabled,
+		.do_file = enabled,
+		.do_stderr = enabled || !isatty(STDERR_FILENO),
+		.error = 0,
+	};
+
 	qmem_walk(qmem_exit_walker, &eda);
+	if (eda.fp)
+		fclose(eda.fp);
+	if (eda.error && eda.do_log)
+		zlog_warn("exiting with %d leaked MTYPEs", eda.error);
 	return eda.error;
 }

lib/memory.h

@@ -67,6 +67,8 @@ struct memgroup {
  *         but MGROUP_* aren't.
  */
 
+/* clang-format off */
+
 #define DECLARE_MGROUP(name) extern struct memgroup _mg_##name
 #define _DEFINE_MGROUP(mname, desc, ...)                                       \
 	struct memgroup _mg_##mname _DATA_SECTION("mgroups") = {               \
@@ -75,6 +77,7 @@ struct memgroup {
 		.next = NULL,                                                  \
 		.insert = NULL,                                                \
 		.ref = NULL,                                                   \
+		__VA_ARGS__                                                    \
 	};                                                                     \
 	static void _mginit_##mname(void) __attribute__((_CONSTRUCTOR(1000))); \
 	static void _mginit_##mname(void)                                      \
@@ -136,6 +139,8 @@ struct memgroup {
 	DEFINE_MTYPE_ATTR(group, name, static, desc)                           \
 	/* end */
 
+/* clang-format on */
+
 DECLARE_MGROUP(LIB);
 DECLARE_MTYPE(TMP);
 DECLARE_MTYPE(TMP_TTABLE);
@@ -176,8 +181,7 @@ static inline size_t mtype_stats_alloc(struct memtype *mt)
  * last value from qmem_walk_fn. */
 typedef int qmem_walk_fn(void *arg, struct memgroup *mg, struct memtype *mt);
 extern int qmem_walk(qmem_walk_fn *func, void *arg);
-extern int log_memstats(FILE *fp, const char *);
-#define log_memstats_stderr(prefix) log_memstats(stderr, prefix)
+extern int log_memstats(const char *daemon_name, bool enabled);
 
 extern __attribute__((__noreturn__)) void memory_oom(size_t size,
 						     const char *name);

lib/sigevent.c

@@ -237,8 +237,18 @@ core_handler(int signo, siginfo_t *siginfo, void *context)
 
 	zlog_signal(signo, "aborting...", siginfo, pc);
 
-	/* dump memory stats on core */
-	log_memstats(stderr, "core_handler");
+	/* there used to be a log_memstats() call here, to dump MTYPE counters
+	 * on a coredump.  This is not possible since log_memstats is not
+	 * AS-Safe, as it calls fopen(), fprintf(), and cousins.  This can
+	 * lead to a deadlock depending on where we crashed - very much not a
+	 * good thing if the process just hangs there after a crash.
+	 *
+	 * The alarm(1) above tries to alleviate this, but that's really a
+	 * last resort recovery.  Stick with AS-safe calls here.
+	 *
+	 * If the fprintf() calls are removed from log_memstats(), this can be
+	 * added back in, since writing to log with zlog_sigsafe() is AS-safe.
+	 */
 
 	/*
 	 * This is a buffer flush because FRR is going down

tests/isisd/test_fuzz_isis_tlv.c

@@ -22,7 +22,7 @@ static bool atexit_registered;
 
 static void show_meminfo_at_exit(void)
 {
-	log_memstats(stderr, "isis fuzztest");
+	log_memstats(NULL, true);
 }
 
 static int comp_line(const void *p1, const void *p2)

tests/isisd/test_isis_spf.c

@@ -475,7 +475,7 @@ static void vty_do_exit(int isexit)
 	yang_terminate();
 	event_master_free(master);
 
-	log_memstats(stderr, "test-isis-spf");
+	log_memstats(NULL, true);
 	if (!isexit)
 		exit(0);
 }

tests/lib/cli/common_cli.c

@@ -43,7 +43,7 @@ static void vty_do_exit(int isexit)
 	yang_terminate();
 	event_master_free(master);
 
-	log_memstats(stderr, "testcli");
+	log_memstats(NULL, true);
 	if (!isexit)
 		exit(0);
 }

tests/lib/northbound/test_oper_data.c

@@ -427,7 +427,7 @@ static void vty_do_exit(int isexit)
 	yang_terminate();
 	event_master_free(master);
 
-	log_memstats(stderr, "test-nb-oper-data");
+	log_memstats(NULL, true);
 	if (!isexit)
 		exit(0);
 }

tests/lib/test_typelist.c

@@ -156,6 +156,6 @@ int main(int argc, char **argv)
 	test_ATOMSORT_UNIQ();
 	test_ATOMSORT_NONUNIQ();
 
-	log_memstats_stderr("test: ");
+	log_memstats(NULL, true);
 	return 0;
 }

tests/lib/test_zmq.c

@@ -285,7 +285,7 @@ static void run_server(int syncfd)
 	zmq_close(zmqsock);
 	frrzmq_finish();
 	event_master_free(master);
-	log_memstats_stderr("test");
+	log_memstats(NULL, true);
 }
 
 int main(void)