test-process-util: add more debug logging but hide most of it by default

It makes little sense to always print the stuff that is fully deterministic
and verified by asserts. It can be opted-in with $SYSTEMD_LOG_LEVEL when
developing the tests or debugging a failure.

diff --git a/src/test/test-process-util.c b/src/test/test-process-util.c
index 5f148c1522e7308095f1204c1c0faaede65e3c92..383e9ae3c5e48bdee359eda21ef085eea70f5b4b 100644 (file)
--- a/src/test/test-process-util.c
+++ b/src/test/test-process-util.c
@@ -43,6 +43,8 @@ static void test_get_process_comm(pid_t pid) {
         dev_t h;
         int r;
 
+        log_info("/* %s */", __func__);
+
         xsprintf(path, "/proc/"PID_FMT"/comm", pid);
 
         if (stat(path, &st) == 0) {
@@ -91,12 +93,12 @@ static void test_get_process_comm(pid_t pid) {
 static void test_get_process_comm_escape_one(const char *input, const char *output) {
         _cleanup_free_ char *n = NULL;
 
-        log_info("input: <%s> — output: <%s>", input, output);
+        log_debug("input: <%s> — output: <%s>", input, output);
 
         assert_se(prctl(PR_SET_NAME, input) >= 0);
         assert_se(get_process_comm(0, &n) >= 0);
 
-        log_info("got: <%s>", n);
+        log_debug("got: <%s>", n);
 
         assert_se(streq_ptr(n, output));
 }
@@ -104,6 +106,8 @@ static void test_get_process_comm_escape_one(const char *input, const char *outp
 static void test_get_process_comm_escape(void) {
         _cleanup_free_ char *saved = NULL;
 
+        log_info("/* %s */", __func__);
+
         assert_se(get_process_comm(0, &saved) >= 0);
 
         test_get_process_comm_escape_one("", "");
@@ -140,6 +144,8 @@ static void test_pid_is_unwaited(void) {
 static void test_pid_is_alive(void) {
         pid_t pid;
 
+        log_info("/* %s */", __func__);
+
         pid = fork();
         assert_se(pid >= 0);
         if (pid == 0) {
@@ -155,6 +161,7 @@ static void test_pid_is_alive(void) {
 }
 
 static void test_personality(void) {
+        log_info("/* %s */", __func__);
 
         assert_se(personality_to_string(PER_LINUX));
         assert_se(!personality_to_string(PERSONALITY_INVALID));
@@ -183,6 +190,8 @@ static void test_get_process_cmdline_harder(void) {
         _cleanup_free_ char *line = NULL;
         pid_t pid;
 
+        log_info("/* %s */", __func__);
+
         if (geteuid() != 0) {
                 log_info("Skipping %s: not root", __func__);
                 return;
@@ -248,17 +257,17 @@ static void test_get_process_cmdline_harder(void) {
         assert_se(get_process_cmdline(0, SIZE_MAX, 0, &line) == -ENOENT);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
-        log_info("'%s'", line);
+        log_debug("'%s'", line);
         assert_se(streq(line, "[testa]"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_COMM_FALLBACK | PROCESS_CMDLINE_QUOTE, &line) >= 0);
-        log_info("'%s'", line);
+        log_debug("'%s'", line);
         assert_se(streq(line, "\"[testa]\"")); /* quoting is enabled here */
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 0, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
-        log_info("'%s'", line);
+        log_debug("'%s'", line);
         assert_se(streq(line, ""));
         line = mfree(line);
 
@@ -299,7 +308,7 @@ static void test_get_process_cmdline_harder(void) {
         assert_se(write(fd, "foo\0bar", 8) == 8);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, 0, &line) >= 0);
-        log_info("'%s'", line);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar"));
         line = mfree(line);
 
@@ -309,71 +318,87 @@ static void test_get_process_cmdline_harder(void) {
 
         assert_se(write(fd, "quux", 4) == 4);
         assert_se(get_process_cmdline(0, SIZE_MAX, 0, &line) >= 0);
-        log_info("'%s'", line);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 1, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 2, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "f…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 3, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "fo…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 4, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 5, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo …"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 6, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo b…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 7, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo ba…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 8, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 9, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar …"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 10, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar q…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 11, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar qu…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 12, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 13, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 14, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 1000, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "foo bar quux"));
         line = mfree(line);
 
@@ -383,18 +408,22 @@ static void test_get_process_cmdline_harder(void) {
         assert_se(get_process_cmdline(0, SIZE_MAX, 0, &line) == -ENOENT);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "[aaaa bbbb cccc]"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 10, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "[aaaa bbb…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 11, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "[aaaa bbbb…"));
         line = mfree(line);
 
         assert_se(get_process_cmdline(0, 12, PROCESS_CMDLINE_COMM_FALLBACK, &line) >= 0);
+        log_debug("'%s'", line);
         assert_se(streq(line, "[aaaa bbbb …"));
         line = mfree(line);
 
@@ -407,8 +436,8 @@ static void test_get_process_cmdline_harder(void) {
         assert_se(ftruncate(fd, sizeof CMDLINE1) == 0);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_QUOTE, &line) >= 0);
-        log_info("got: ==%s==", line);
-        log_info("exp: ==%s==", EXPECT1);
+        log_debug("got: ==%s==", line);
+        log_debug("exp: ==%s==", EXPECT1);
         assert_se(streq(line, EXPECT1));
         line = mfree(line);
 
@@ -419,8 +448,8 @@ static void test_get_process_cmdline_harder(void) {
         assert_se(ftruncate(fd, sizeof CMDLINE2) == 0);
 
         assert_se(get_process_cmdline(0, SIZE_MAX, PROCESS_CMDLINE_QUOTE, &line) >= 0);
-        log_info("got: ==%s==", line);
-        log_info("exp: ==%s==", EXPECT2);
+        log_debug("got: ==%s==", line);
+        log_debug("exp: ==%s==", EXPECT2);
         assert_se(streq(line, EXPECT2));
         line = mfree(line);
 
@@ -432,12 +461,14 @@ static void test_rename_process_now(const char *p, int ret) {
         _cleanup_free_ char *comm = NULL, *cmdline = NULL;
         int r;
 
+        log_info("/* %s */", __func__);
+
         r = rename_process(p);
         assert_se(r == ret ||
                   (ret == 0 && r >= 0) ||
                   (ret > 0 && r > 0));
 
-        log_info_errno(r, "rename_process(%s): %m", p);
+        log_debug_errno(r, "rename_process(%s): %m", p);
 
         if (r < 0)
                 return;
@@ -449,7 +480,7 @@ static void test_rename_process_now(const char *p, int ret) {
 #endif
 
         assert_se(get_process_comm(0, &comm) >= 0);
-        log_info("comm = <%s>", comm);
+        log_debug("comm = <%s>", comm);
         assert_se(strneq(comm, p, TASK_COMM_LEN-1));
         /* We expect comm to be at most 16 bytes (TASK_COMM_LEN). The kernel may raise this limit in the
          * future. We'd only check the initial part, at least until we recompile, but this will still pass. */
@@ -476,6 +507,8 @@ static void test_rename_process_one(const char *p, int ret) {
         siginfo_t si;
         pid_t pid;
 
+        log_info("/* %s */", __func__);
+
         pid = fork();
         assert_se(pid >= 0);
 
@@ -530,6 +563,8 @@ static void test_getpid_cached(void) {
         siginfo_t si;
         pid_t a, b, c, d, e, f, child;
 
+        log_info("/* %s */", __func__);
+
         a = raw_getpid();
         b = getpid_cached();
         c = getpid();
@@ -566,6 +601,8 @@ static void test_getpid_measure(void) {
         unsigned long long i;
         usec_t t, q;
 
+        log_info("/* %s */", __func__);
+
         t = now(CLOCK_MONOTONIC);
         for (i = 0; i < MEASURE_ITERATIONS; i++)
                 (void) getpid();
@@ -586,6 +623,8 @@ static void test_safe_fork(void) {
         pid_t pid;
         int r;
 
+        log_info("/* %s */", __func__);
+
         BLOCK_SIGNALS(SIGCHLD);
 
         r = safe_fork("(test-child)", FORK_RESET_SIGNALS|FORK_CLOSE_ALL_FDS|FORK_DEATHSIG|FORK_NULL_STDIO|FORK_REOPEN_LOG, &pid);
@@ -634,6 +673,8 @@ static void test_ioprio_class_from_to_string_one(const char *val, int expected)
 }
 
 static void test_ioprio_class_from_to_string(void) {
+        log_info("/* %s */", __func__);
+
         test_ioprio_class_from_to_string_one("none", IOPRIO_CLASS_NONE);
         test_ioprio_class_from_to_string_one("realtime", IOPRIO_CLASS_RT);
         test_ioprio_class_from_to_string_one("best-effort", IOPRIO_CLASS_BE);
@@ -649,7 +690,10 @@ static void test_ioprio_class_from_to_string(void) {
 static void test_setpriority_closest(void) {
         int r;
 
-        r = safe_fork("(test-setprio)", FORK_RESET_SIGNALS|FORK_CLOSE_ALL_FDS|FORK_DEATHSIG|FORK_WAIT|FORK_LOG, NULL);
+        log_info("/* %s */", __func__);
+
+        r = safe_fork("(test-setprio)",
+                      FORK_RESET_SIGNALS|FORK_CLOSE_ALL_FDS|FORK_DEATHSIG|FORK_WAIT|FORK_LOG, NULL);
         assert_se(r >= 0);
 
         if (r == 0) {
@@ -733,7 +777,8 @@ static void test_setpriority_closest(void) {
 }
 
 int main(int argc, char *argv[]) {
-        test_setup_logging(LOG_DEBUG);
+        log_show_color(true);
+        test_setup_logging(LOG_INFO);
 
         save_argc_argv(argc, argv);