From 6bdb154da597ee6bb6cf45cffa952cbf71e80c59 Mon Sep 17 00:00:00 2001 From: James Prestwood Date: Mon, 4 Nov 2019 11:44:30 -0800 Subject: [PATCH] test-runner: log process output to host system All the processes verbose output is just written to stdout, and very hard to parse after the test runs. Having test-runner write the processes output to separate log files is much nicer to view after the test runs. A read/write file system is created which is separate and isolated from the current FS mount (which mounts the whole host file system). Doing this requires the user to create a folder somewhere to be used as the mount point. This folder is where all the log files will end up after test-runner runs. Since test-runner must be run as root, care was taken to keep the log files owned by the user which runs test-runner. The UID/GID are passed to the VM, and any log files created are chown'ed back to the user who ran test-runner. execute_program was refactored, and both verbose and log arguments were removed. The verbose argument was not really required since we can do check_verbosity(argv[0]) internally. The 'log' flag was only used along with --shell, and now the user can simply use --log instead of dumping /tmp/iwd.log. You can use this feature by specifying --log[=path] to test-runner. If no path is provided the current directory will be used. Using the --log flag will result in all processes being run with the --verbose flag. A new folder will be created under the --log path. The folder will be of the name "run----". Under this folder you will find any global process logs. These are processes that are only run once for ALL tests (hwsim, ifconfig, dbus etc.). There will also be folders for specific tests that were run. Inside these test folders will be logs of processes that are run per-test (iwd, hostapd, python etc.). --- tools/test-runner.c | 297 ++++++++++++++++++++++++++++++++++++-------- 1 file changed, 243 insertions(+), 54 deletions(-) diff --git a/tools/test-runner.c b/tools/test-runner.c index 37afac85..5ef9552e 100644 --- a/tools/test-runner.c +++ b/tools/test-runner.c @@ -45,6 +45,7 @@ #include #include #include +#include #include #include "linux/nl80211.h" @@ -82,6 +83,10 @@ const char *debug_filter; static struct l_settings *hw_config; static bool native_hw; static bool shell; +static bool log; +static char log_dir[PATH_MAX]; +static uid_t log_uid; +static gid_t log_gid; static const char *qemu_binary; static const char *kernel_image; static const char *exec_home; @@ -168,6 +173,21 @@ static bool check_verbosity(const char *app) { char **apps = verbose_apps; + /* + * All processes are verbose if logging is enabled. Kernel is a bit + * different as we just pipe dmesg into a log file at the end of + * execution. + */ + if (log && strcmp(app, "kernel") != 0) + return true; + + /* + * Turn on output if this is a unit test run. Nothing should output + * anything except the tests themselves and the kernel. + */ + if (test_action == ACTION_UNIT_TEST && strcmp(app, "kernel") != 0) + return true; + if (!apps) return false; @@ -358,6 +378,7 @@ static bool start_qemu(void) int num_pci = 0, num_usb = 0; char **pci_keys = NULL; char **usb_keys = NULL; + L_AUTO_FREE_VAR(char *, log_option) = NULL; has_virt = check_virtualization(); @@ -388,7 +409,8 @@ static bool start_qemu(void) "TESTVERBOUT=\'%s\' DEBUG_FILTER=\'%s\'" "TEST_ACTION=%u TEST_ACTION_PARAMS=\'%s\' " "TESTARGS=\'%s\' PATH=\'%s\' VALGRIND=%u" - "GDB=\'%s\' HW=\'%s\' SHELL=%u", + "GDB=\'%s\' HW=\'%s\' SHELL=%u " + "LOG_PATH=\'%s\' LOG_UID=\'%d\' LOG_GID=\'%d\'", check_verbosity("kernel") ? "ignore_loglevel" : "quiet", initcmd, cwd, verbose_opt ? verbose_opt : "none", enable_debug ? debug_filter : "", @@ -399,7 +421,9 @@ static bool start_qemu(void) valgrind, gdb_opt ? gdb_opt : "none", hw_config ? "real" : "virtual", - shell); + shell, + log ? log_dir : "none", + log_uid, log_gid); if (hw_config) { if (l_settings_has_group(hw_config, "PCIAdapters")) { @@ -429,9 +453,10 @@ static bool start_qemu(void) * -kernel,-append,-cpu,-host parameters (7) * -enable-kvm and/or -usb (2) * PCI and/or USB parameters (num_pci * 2) (num_usb * 2) + * Logging directory/device (2) */ argv = alloca(sizeof(qemu_argv) + sizeof(char *) * - (7 + (2 + (num_pci * 2) + (num_usb * 2)))); + (7 + (2 + (num_pci * 2) + (num_usb * 2) + 2))); memcpy(argv, qemu_argv, sizeof(qemu_argv)); pos = (sizeof(qemu_argv) / sizeof(char *)) - 1; @@ -480,6 +505,18 @@ static bool start_qemu(void) } } + if (log) { + /* + * Create a virtfs device and tag it. This allows the guest to + * mount 'logdir' in the path specified with --log. + */ + log_option = l_strdup_printf("local,path=%s,mount_tag=logdir," + "security_model=passthrough,id=logdir", + log_dir); + argv[pos++] = "-virtfs"; + argv[pos++] = log_option; + } + argv[pos] = NULL; execve(argv[0], argv, qemu_envp); @@ -492,15 +529,27 @@ static bool start_qemu(void) } static pid_t execute_program(char *argv[], char *envp[], bool wait, - bool verbose, bool log) + const char *test_name) { int status; pid_t pid, child_pid; char *str; + bool verbose; + char *log_name = argv[0]; if (!argv[0]) return -1; + /* + * We have to special case this. execute_program automatically logs to + * .log, which would put all iwd output into valgrind.log + * rather than iwd.log. Since we are explicitly having valgrind output + * to a log file we can assume any output from this is only IWD, and not + * valgrind. + */ + if (!strcmp(log_name, "valgrind")) + log_name = "iwd"; + str = l_strjoinv(argv, ' '); l_debug("Executing: %s", str); l_free(str); @@ -512,21 +561,34 @@ static pid_t execute_program(char *argv[], char *envp[], bool wait, } if (child_pid == 0) { - if (!verbose) { - int fd; - char log_file[PATH_MAX]; + int fd = -1; + L_AUTO_FREE_VAR(char *, log_file) = NULL; - if (!log) - fd = open("/dev/null", O_WRONLY); - else { - sprintf(log_file, "/tmp/%s.log", argv[0]); - fd = open(log_file, O_WRONLY | O_CREAT, - S_IRUSR | S_IWUSR); - } + verbose = check_verbosity(argv[0]); - if (fd == -1) - exit(EXIT_FAILURE); + /* No stdout and no logging */ + if (!verbose && !log) + fd = open("/dev/null", O_WRONLY); + else if (log && verbose) { + /* + * Create the log file for this process. If no test name + * was specified this is a 'global' process (only run + * once, not per-test). + */ + if (test_name) { + log_file = l_strdup_printf("%s/%s/%s.log", + log_dir, test_name, log_name); + } else + log_file = l_strdup_printf("%s/%s.log", + log_dir, log_name); + fd = open(log_file, O_WRONLY | O_CREAT | O_APPEND, + S_IRUSR | S_IWUSR); + if (fchown(fd, log_uid, log_gid) < 0) + l_error("fchown failed"); + } + + if (fd > -1) { dup2(fd, 1); dup2(fd, 2); @@ -631,8 +693,7 @@ static bool start_dbus_daemon(void) if (check_verbosity("dbus")) setenv("DBUS_VERBOSE", "1", true); - pid = execute_program(argv, environ, false, - check_verbosity("dbus"), false); + pid = execute_program(argv, environ, false, NULL); if (pid < 0) return false; @@ -643,7 +704,7 @@ static bool start_dbus_daemon(void) argv[0] = "dbus-monitor"; argv[1] = "--system"; argv[2] = NULL; - execute_program(argv, environ, false, true, false); + execute_program(argv, environ, false, NULL); } l_debug("D-Bus is running"); @@ -659,7 +720,7 @@ static bool start_haveged(void) argv[0] = "haveged"; argv[1] = NULL; - pid = execute_program(argv, environ, true, false, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -681,7 +742,7 @@ static bool set_interface_state(const char *if_name, bool isUp) argv[2] = state; argv[3] = NULL; - pid = execute_program(argv, environ, true, false, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -703,7 +764,7 @@ static bool create_interface(const char *if_name, const char *phy_name) argv[7] = "managed"; argv[8] = NULL; - pid = execute_program(argv, environ, true, false, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -721,7 +782,7 @@ static bool delete_interface(const char *if_name) argv[3] = "del"; argv[4] = NULL; - pid = execute_program(argv, environ, true, false, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -737,7 +798,7 @@ static bool list_interfaces(void) argv[1] = "-a"; argv[2] = NULL; - pid = execute_program(argv, environ, true, true, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -753,7 +814,7 @@ static bool list_hwsim_radios(void) argv[1] = "--list"; argv[2] = NULL; - pid = execute_program(argv, environ, true, true, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -801,8 +862,7 @@ static int create_hwsim_radio(const char *radio_name, argv[idx] = NULL; - pid = execute_program(argv, environ, true, - check_verbosity(BIN_HWSIM), false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return -1; @@ -821,7 +881,7 @@ static bool destroy_hwsim_radio(int radio_id) argv[1] = destroy_param; argv[2] = NULL; - pid = execute_program(argv, environ, true, false, false); + pid = execute_program(argv, environ, true, NULL); if (pid < 0) return false; @@ -841,8 +901,7 @@ static pid_t register_hwsim_as_trans_medium(void) argv[idx++] = BIN_HWSIM; argv[idx++] = NULL; - return execute_program(argv, environ, false, - check_verbosity(BIN_HWSIM), false); + return execute_program(argv, environ, false, NULL); } static void terminate_medium(pid_t medium_pid) @@ -866,13 +925,13 @@ static void start_loopback(void) argv[2] = "127.0.0.1"; argv[3] = "up"; argv[4] = NULL; - execute_program(argv, environ, false, false, false); + execute_program(argv, environ, false, NULL); argv[0] = "route"; argv[1] = "add"; argv[2] = "127.0.0.1"; argv[3] = NULL; - execute_program(argv, environ, false, false, false); + execute_program(argv, environ, false, NULL); loopback_started = true; } @@ -891,7 +950,7 @@ static pid_t start_phonesim(void) setenv("OFONO_PHONESIM_CONFIG", "/tmp/phonesim.conf", true); - return execute_program(argv, environ, false, false, false); + return execute_program(argv, environ, false, NULL); } static void stop_phonesim(pid_t pid) @@ -917,7 +976,7 @@ static pid_t start_ofono(void) start_loopback(); - return execute_program(argv, environ, false, verbose, false); + return execute_program(argv, environ, false, NULL); } static void stop_ofono(pid_t pid) @@ -925,7 +984,8 @@ static void stop_ofono(pid_t pid) kill_process(pid); } -static pid_t start_hostapd(char **config_files, struct wiphy **wiphys) +static pid_t start_hostapd(char **config_files, struct wiphy **wiphys, + const char *test_name) { char **argv; pid_t pid; @@ -972,7 +1032,7 @@ static pid_t start_hostapd(char **config_files, struct wiphy **wiphys) argv[idx++] = NULL; } - pid = execute_program(argv, environ, false, verbose, false); + pid = execute_program(argv, environ, false, log ? test_name : NULL); if (pid < 0) { goto exit; } @@ -1410,7 +1470,8 @@ hostapd_done: (*phys_used)++; } - hostapd_pids_out[0] = start_hostapd(hostapd_config_file_paths, wiphys); + hostapd_pids_out[0] = start_hostapd(hostapd_config_file_paths, wiphys, + basename(config_dir_path)); hostapd_pids_out[1] = -1; done: @@ -1423,17 +1484,38 @@ done: } static pid_t start_iwd(const char *config_dir, struct l_queue *wiphy_list, - const char *ext_options, int num_phys) + const char *ext_options, int num_phys, const char *test_name) { char *argv[13], **envp; char *iwd_phys = NULL; pid_t ret; int idx = 0; + L_AUTO_FREE_VAR(char *, fd_option) = NULL; if (valgrind) { + int fd; + argv[idx++] = "valgrind"; argv[idx++] = "--leak-check=full"; - argv[idx++] = "--log-file=/tmp/valgrind.log"; + + /* + * Valgrind needs --log-fd if we want both stderr and stdout + */ + if (log) { + L_AUTO_FREE_VAR(char *, valgrind_log); + + valgrind_log = l_strdup_printf("%s/%s/valgrind.log", + log_dir, test_name); + fd = open(valgrind_log, O_WRONLY | O_CREAT | O_APPEND, + S_IRUSR | S_IWUSR); + + if (fchown(fd, log_uid, log_gid) < 0) + l_error("chown failed"); + + fd_option = l_strdup_printf("--log-fd=%d", fd); + argv[idx++] = fd_option; + } else + argv[idx++] = "--log-file=/tmp/valgrind.log"; } if (strcmp(gdb_opt, "iwd") == 0) { @@ -1490,8 +1572,7 @@ static pid_t start_iwd(const char *config_dir, struct l_queue *wiphy_list, envp = l_strv_append_printf(envp, "STATE_DIRECTORY=%s", DAEMON_STORAGEDIR); - ret = execute_program(argv, envp, false, - check_verbosity(BIN_IWD), shell); + ret = execute_program(argv, envp, false, test_name); l_strv_free(envp); @@ -1715,7 +1796,8 @@ struct test_stats { static void run_py_tests(struct l_settings *hw_settings, struct l_queue *test_queue, - struct l_queue *test_stats_queue) + struct l_queue *test_stats_queue, + const char *test_name) { char *argv[3]; pid_t test_exec_pid, test_timer_pid = -1; @@ -1746,8 +1828,7 @@ start_next_test: argv[2] = NULL; print_test_status(py_test, TEST_STATUS_STARTED, 0); - test_exec_pid = execute_program(argv, environ, false, - check_verbosity("pytests"), false); + test_exec_pid = execute_program(argv, environ, false, test_name); gettimeofday(&time_before, NULL); @@ -1888,7 +1969,7 @@ static void set_reg_domain(const char *domain) argv[3] = (char *) domain; argv[4] = NULL; - execute_program(argv, environ, false, false, false); + execute_program(argv, environ, false, NULL); } static void wiphy_up(void *data, void *user_data) @@ -1932,6 +2013,7 @@ static void create_network_and_run_tests(void *data, void *user_data) int phys_used; int num_radios; struct test_entry *entry = data; + char *test_name = NULL; memset(hostapd_pids, -1, sizeof(hostapd_pids)); @@ -1953,6 +2035,19 @@ static void create_network_and_run_tests(void *data, void *user_data) l_info("Configuring network..."); + if (log) { + char *log_path; + + test_name = basename(config_dir_path); + log_path = l_strdup_printf("%s/%s", log_dir, test_name); + + mkdir(log_path, 0755); + if (chown(log_path, log_uid, log_gid) < 0) + l_error("chown failed"); + + l_free(log_path); + } + if (chdir(config_dir_path) < 0) { l_error("Failed to change to test directory: %s", strerror(errno)); @@ -2077,7 +2172,7 @@ static void create_network_and_run_tests(void *data, void *user_data) iwd_config_dir = DAEMON_CONFIGDIR; iwd_pid = start_iwd(iwd_config_dir, wiphy_list, - iwd_ext_options, iwd_phys); + iwd_ext_options, iwd_phys, test_name); if (iwd_pid == -1) goto exit_hostapd; @@ -2095,7 +2190,8 @@ static void create_network_and_run_tests(void *data, void *user_data) set_wiphy_list(wiphy_list); if (!shell) - run_py_tests(hw_settings, test_queue, test_stats_queue); + run_py_tests(hw_settings, test_queue, test_stats_queue, + test_name); else { if (system("/bin/sh")) l_info("executing /bin/sh failed"); @@ -2107,10 +2203,24 @@ static void create_network_and_run_tests(void *data, void *user_data) if (iwd_pid > 0) terminate_iwd(iwd_pid); - if (valgrind) + /* /tmp/valgrind.log will only exist without logging turned on */ + if (valgrind && !log) if (system("cat /tmp/valgrind.log")) l_info("cat /tmp/valgrind.log failed"); + if (log) { + L_AUTO_FREE_VAR(char *, dmesg); + L_AUTO_FREE_VAR(char *, kernel_log); + + kernel_log = l_strdup_printf("%s/kernel.log", log_dir); + dmesg = l_strdup_printf("dmesg > %s", kernel_log); + + if (system(dmesg)) + l_error("dmesg failed"); + if (chown(kernel_log, log_uid, log_gid)) + l_error("chown failed"); + } + if (ofono_req) { loopback_started = false; stop_ofono(ofono_pid); @@ -2253,13 +2363,21 @@ static void free_test_entry(void *data) static void run_auto_tests(void) { - L_AUTO_FREE_VAR(char*, test_home_path); - L_AUTO_FREE_VAR(char*, env_path); + L_AUTO_FREE_VAR(char*, test_home_path) = NULL; + L_AUTO_FREE_VAR(char*, env_path) = NULL; int i; struct l_queue *test_config_queue; struct l_queue *test_stat_queue; char **test_config_dirs; + if (log) { + if (mount("logdir", log_dir, "9p", 0, + "trans=virtio,version=9p2000.L") < 0) { + l_error("Mounting %s failed", log_dir); + return; + } + } + env_path = l_strdup_printf("%s/src:%s/tools:%s", top_level_path, top_level_path, getenv("PATH")); @@ -2409,8 +2527,7 @@ static void run_unit_tests(void) argv[1] = NULL; l_info("\n---------- Unit %s ----------", dirent->d_name); - execute_program(argv, environ, true, - check_verbosity("unit"), false); + execute_program(argv, environ, true, NULL); next: l_free(unit_test_abs_path); @@ -2661,6 +2778,38 @@ static void run_tests(void) return; } + ptr = strstr(cmdline, "LOG_GID="); + if (ptr) { + *ptr = '\0'; + test_action_str = ptr + 9; + ptr = strchr(test_action_str, '\''); + *ptr = '\0'; + log_gid = atoi(test_action_str); + } + + ptr = strstr(cmdline, "LOG_UID="); + if (ptr) { + *ptr = '\0'; + test_action_str = ptr + 9; + ptr = strchr(test_action_str, '\''); + *ptr = '\0'; + log_uid = atoi(test_action_str); + } + + ptr = strstr(cmdline, "LOG_PATH="); + if (ptr) { + *ptr = '\0'; + test_action_str = ptr + 10; + + ptr = strchr(test_action_str, '\''); + *ptr = '\0'; + + if (strcmp(test_action_str, "none")) { + log = true; + strcpy(log_dir, test_action_str); + } + } + ptr = strstr(cmdline, "SHELL="); if (ptr) { *ptr = '\0'; @@ -2869,7 +3018,13 @@ static void usage(void) "\t\t\t\tbut no test will be run. If no" " test is specified\n" "\t\t\t\tthe 'shell' test" - " will be used"); + " will be used\n" + "\t-l, --log [dir] Directory used for log output. " + "If no directory\n" + "\t\t\t\tis specified the " + "current directory will be used\n" + "\t\t\t\tThis option sets --verbose on " + "all apps"); l_info("Commands:\n" "\t-A, --auto-tests Comma separated list of the " "test configuration\n\t\t\t\t" @@ -2889,6 +3044,7 @@ static const struct option main_options[] = { { "valgrind", no_argument, NULL, 'V' }, { "hw", required_argument, NULL, 'w' }, { "shell", optional_argument, NULL, 's' }, + { "log", optional_argument, NULL, 'l' }, { "help", no_argument, NULL, 'h' }, { } }; @@ -2896,6 +3052,8 @@ static const struct option main_options[] = { int main(int argc, char *argv[]) { uint8_t actions = 0; + struct tm *timeinfo; + time_t t; l_log_set_stderr(); @@ -2917,7 +3075,7 @@ int main(int argc, char *argv[]) for (;;) { int opt; - opt = getopt_long(argc, argv, "A:q:k:v:g:UVdh", main_options, + opt = getopt_long(argc, argv, "A:q:k:v:g:UVldh", main_options, NULL); if (opt < 0) break; @@ -2977,6 +3135,37 @@ int main(int argc, char *argv[]) break; case 's': shell = true; + break; + case 'l': + /* + * Setup the log directory. This is created under the + * passed in log dir (--log) in the format: + * /run---- + * + * The created log dir is then chown'ed to the user + * who started test-runner, as are all files created + * under this directory. + */ + log = true; + + if (!optarg) + optarg = "."; + + time(&t); + timeinfo = localtime(&t); + + log_gid = atoi(getenv("SUDO_GID")); + log_uid = atoi(getenv("SUDO_UID")); + + snprintf(log_dir, sizeof(log_dir), "%s/run-%d-%d-%d-%d", + optarg, timeinfo->tm_year, + timeinfo->tm_mon, timeinfo->tm_mday, + getpid()); + mkdir(log_dir, 0755); + + if (chown(log_dir, log_uid, log_gid) < 0) + l_error("fchown failed"); + break; case 'h': usage();