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();