Added tailpipe.py and improved redirecting test trace/log output over fifos

This mostly involved futzing around with some of the less intuitive
parts of Unix's named-pipes behavior.

This is a bit important since the tests can quickly generate several
gigabytes of trace output.

runners/test_runner.c

@@ -1,4 +1,8 @@
 
+#ifndef _POSIX_C_SOURCE
+#define _POSIX_C_SOURCE 199309L
+#endif
+
 #include "runners/test_runner.h"
 #include "bd/lfs_testbd.h"
 
@@ -6,6 +10,10 @@
 #include <sys/types.h>
 #include <errno.h>
 #include <setjmp.h>
+#include <fcntl.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <unistd.h>
 
 
 // test suites in a custom ld section
@@ -219,10 +227,10 @@ static void run_powerloss_none(
         size_t perm,
         const lfs_testbd_powercycles_t *cycles,
         size_t cycle_count);
-static const test_powerloss_t *test_powerlosses = (const test_powerloss_t[]){
+const test_powerloss_t *test_powerlosses = (const test_powerloss_t[]){
     {'0', "none", run_powerloss_none, NULL, 0},
 };
-static size_t test_powerloss_count = 1;
+size_t test_powerloss_count = 1;
 
 
 typedef struct test_id {
@@ -233,23 +241,70 @@ typedef struct test_id {
     size_t cycle_count;
 } test_id_t;
 
-static const test_id_t *test_ids = (const test_id_t[]) {
+const test_id_t *test_ids = (const test_id_t[]) {
     {NULL, NULL, -1, NULL, 0},
 };
-static size_t test_id_count = 1;
+size_t test_id_count = 1;
 
 
-static const char *test_geometry = NULL;
+const char *test_geometry = NULL;
 
-static size_t test_start = 0;
-static size_t test_stop = -1;
-static size_t test_step = 1;
+size_t test_start = 0;
+size_t test_stop = -1;
+size_t test_step = 1;
 
-static const char *test_disk = NULL;
-FILE *test_trace = NULL;
-static lfs_testbd_delay_t test_read_delay = 0.0;
-static lfs_testbd_delay_t test_prog_delay = 0.0;
-static lfs_testbd_delay_t test_erase_delay = 0.0;
+const char *test_disk_path = NULL;
+const char *test_trace_path = NULL;
+FILE *test_trace_file = NULL;
+uint32_t test_trace_cycles = 0;
+lfs_testbd_delay_t test_read_delay = 0.0;
+lfs_testbd_delay_t test_prog_delay = 0.0;
+lfs_testbd_delay_t test_erase_delay = 0.0;
+
+
+// trace printing
+void test_trace(const char *fmt, ...) {
+    if (test_trace_path) {
+        if (!test_trace_file) {
+            // Tracing output is heavy and trying to open every trace
+            // call is slow, so we only try to open the trace file every
+            // so often. Note this doesn't affect successfully opened files
+            if (test_trace_cycles % 128 != 0) {
+                test_trace_cycles += 1;
+                return;
+            }
+            test_trace_cycles += 1;
+
+            int fd;
+            if (strcmp(test_trace_path, "-") == 0) {
+                fd = dup(1);
+            } else {
+                fd = open(
+                        test_trace_path,
+                        O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK,
+                        0666);
+            }
+            if (fd < 0) {
+                return;
+            }
+
+            FILE *f = fdopen(fd, "a");
+            assert(f);
+            int err = setvbuf(f, NULL, _IOLBF, BUFSIZ);
+            assert(!err);
+            test_trace_file = f;
+        }
+
+        va_list va;
+        va_start(va, fmt);
+        int res = vfprintf(test_trace_file, fmt, va);
+        if (res < 0) {
+            fclose(test_trace_file);
+            test_trace_file = NULL;
+        }
+        va_end(va);
+    }
+}
 
 
 // how many permutations are there actually in a test case
@@ -613,13 +668,13 @@ static void run_powerloss_none(
         .erase_value        = ERASE_VALUE,
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
-        .disk_path          = test_disk,
+        .disk_path          = test_disk_path,
         .read_delay         = test_read_delay,
         .prog_delay         = test_prog_delay,
         .erase_delay        = test_erase_delay,
     };
 
-    int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
+    int err = lfs_testbd_createcfg(&cfg, test_disk_path, &bdcfg);
     if (err) {
         fprintf(stderr, "error: could not create block device: %d\n", err);
         exit(-1);
@@ -679,7 +734,7 @@ static void run_powerloss_linear(
         .erase_value        = ERASE_VALUE,
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
-        .disk_path          = test_disk,
+        .disk_path          = test_disk_path,
         .read_delay         = test_read_delay,
         .prog_delay         = test_prog_delay,
         .erase_delay        = test_erase_delay,
@@ -689,7 +744,7 @@ static void run_powerloss_linear(
         .powerloss_data     = &powerloss_jmp,
     };
 
-    int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
+    int err = lfs_testbd_createcfg(&cfg, test_disk_path, &bdcfg);
     if (err) {
         fprintf(stderr, "error: could not create block device: %d\n", err);
         exit(-1);
@@ -760,7 +815,7 @@ static void run_powerloss_exponential(
         .erase_value        = ERASE_VALUE,
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
-        .disk_path          = test_disk,
+        .disk_path          = test_disk_path,
         .read_delay         = test_read_delay,
         .prog_delay         = test_prog_delay,
         .erase_delay        = test_erase_delay,
@@ -770,7 +825,7 @@ static void run_powerloss_exponential(
         .powerloss_data     = &powerloss_jmp,
     };
 
-    int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
+    int err = lfs_testbd_createcfg(&cfg, test_disk_path, &bdcfg);
     if (err) {
         fprintf(stderr, "error: could not create block device: %d\n", err);
         exit(-1);
@@ -839,7 +894,7 @@ static void run_powerloss_cycles(
         .erase_value        = ERASE_VALUE,
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
-        .disk_path          = test_disk,
+        .disk_path          = test_disk_path,
         .read_delay         = test_read_delay,
         .prog_delay         = test_prog_delay,
         .erase_delay        = test_erase_delay,
@@ -849,7 +904,7 @@ static void run_powerloss_cycles(
         .powerloss_data     = &powerloss_jmp,
     };
 
-    int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
+    int err = lfs_testbd_createcfg(&cfg, test_disk_path, &bdcfg);
     if (err) {
         fprintf(stderr, "error: could not create block device: %d\n", err);
         exit(-1);
@@ -1025,7 +1080,7 @@ static void run_powerloss_exhaustive(
         .erase_value        = ERASE_VALUE,
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
-        .disk_path          = test_disk,
+        .disk_path          = test_disk_path,
         .read_delay         = test_read_delay,
         .prog_delay         = test_prog_delay,
         .erase_delay        = test_erase_delay,
@@ -1034,7 +1089,7 @@ static void run_powerloss_exhaustive(
         .powerloss_data     = NULL,
     };
 
-    int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
+    int err = lfs_testbd_createcfg(&cfg, test_disk_path, &bdcfg);
     if (err) {
         fprintf(stderr, "error: could not create block device: %d\n", err);
         exit(-1);
@@ -1153,6 +1208,9 @@ static void run_perms(
 }
 
 static void run(void) {
+    // ignore disconnected pipes
+    signal(SIGPIPE, SIG_IGN);
+
     for (size_t t = 0; t < test_id_count; t++) {
         for (size_t i = 0; i < TEST_SUITE_COUNT; i++) {
             if (test_ids[t].suite && strcmp(
@@ -1563,19 +1621,10 @@ powerloss_next:
                 break;
             }
             case OPT_DISK:
-                test_disk = optarg;
+                test_disk_path = optarg;
                 break;
             case OPT_TRACE:
-                if (strcmp(optarg, "-") == 0) {
-                    test_trace = stdout;
-                } else {
-                    test_trace = fopen(optarg, "w");
-                    if (!test_trace) {
-                        fprintf(stderr, "error: could not open for trace: %d\n",
-                                -errno);
-                        exit(-1);
-                    }
-                }
+                test_trace_path = optarg;
                 break;
             case OPT_READ_DELAY: {
                 char *parsed = NULL;

runners/test_runner.h

@@ -1,7 +1,26 @@
 #ifndef TEST_RUNNER_H
 #define TEST_RUNNER_H
 
-#include "lfs.h"
+
+// override LFS_TRACE
+void test_trace(const char *fmt, ...);
+
+#define LFS_TRACE_(fmt, ...) \
+    test_trace("%s:%d:trace: " fmt "%s\n", \
+        __FILE__, \
+        __LINE__, \
+        __VA_ARGS__)
+#define LFS_TRACE(...) LFS_TRACE_(__VA_ARGS__, "")
+#define LFS_TESTBD_TRACE(...) LFS_TRACE_(__VA_ARGS__, "")
+
+
+// note these are indirectly included in any generated files
+#include "bd/lfs_testbd.h"
+#include <stdio.h>
+
+// give source a chance to define feature macros
+#undef _FEATURES_H
+#undef _STDIO_H
 
 
 // generated test configurations
@@ -10,6 +29,8 @@ enum test_flags {
 };
 typedef uint8_t test_flags_t;
 
+struct lfs_config;
+
 struct test_case {
     const char *id;
     const char *name;

scripts/pretty_asserts.py

@@ -422,7 +422,8 @@ if __name__ == "__main__":
     parser.add_argument('-p', '--pattern', action='append',
         help="Regex patterns to search for starting an assert statement. This"
             " implicitly includes \"assert\" and \"=>\".")
-    parser.add_argument('-l', '--limit', default=LIMIT, type=int,
+    parser.add_argument('-l', '--limit',
+        default=LIMIT, type=lambda x: int(x, 0),
         help="Maximum number of characters to display in strcmp and memcmp.")
     sys.exit(main(**{k: v
         for k, v in vars(parser.parse_args()).items()

scripts/tailpipe.py

@@ -0,0 +1,102 @@
+#!/usr/bin/env python3
+
+import os
+import sys
+import threading as th
+import time
+
+
+def openio(path, mode='r'):
+    if path == '-':
+        if 'r' in mode:
+            return os.fdopen(os.dup(sys.stdin.fileno()), 'r')
+        else:
+            return os.fdopen(os.dup(sys.stdout.fileno()), 'w')
+    else:
+        return open(path, mode)
+
+def main(path, lines=1, keep_open=False):
+    ring = [None] * lines
+    i = 0
+    count = 0
+    lock = th.Lock()
+    event = th.Event()
+    done = False
+
+    # do the actual reading in a background thread
+    def read():
+        nonlocal i
+        nonlocal count
+        nonlocal done
+        while True:
+            with openio(path, 'r') as f:
+                for line in f:
+                    with lock:
+                        ring[i] = line
+                        i = (i + 1) % lines
+                        count = min(lines, count + 1)
+                    event.set()
+            if not keep_open:
+                break
+        done = True
+
+    th.Thread(target=read, daemon=True).start()
+
+    try:
+        last_count = 1
+        while not done:
+            time.sleep(0.01)
+            event.wait()
+            event.clear()
+
+            # create a copy to avoid corrupt output
+            with lock:
+                ring_ = ring.copy()
+                i_ = i
+                count_ = count
+
+            # first thing first, give ourself a canvas
+            while last_count < count_:
+                sys.stdout.write('\n')
+                last_count += 1
+
+            for j in range(count_):
+                # move cursor, clear line, disable/reenable line wrapping
+                sys.stdout.write('\r%s\x1b[K\x1b[?7l%s\x1b[?7h%s' % (
+                    '\x1b[%dA' % (count_-1-j) if count_-1-j > 0 else '',
+                    ring_[(i_-count+j) % lines][:-1],
+                    '\x1b[%dB' % (count_-1-j) if count_-1-j > 0 else ''))
+
+            sys.stdout.flush()
+
+    except KeyboardInterrupt:
+        pass
+
+    sys.stdout.write('\n')
+
+
+if __name__ == "__main__":
+    import sys
+    import argparse
+    parser = argparse.ArgumentParser(
+        description="Efficiently displays the last n lines of a file/pipe.")
+    parser.add_argument(
+        'path',
+        nargs='?',
+        default='-',
+        help="Path to read from.")
+    parser.add_argument(
+        '-n',
+        '--lines',
+        type=lambda x: int(x, 0),
+        default=1,
+        help="Number of lines to show, defaults to 1.")
+    parser.add_argument(
+        '-k',
+        '--keep-open',
+        action='store_true',
+        help="Reopen the pipe on EOF, useful when multiple "
+            "processes are writing.")
+    sys.exit(main(**{k: v
+        for k, v in vars(parser.parse_args()).items()
+        if v is not None}))

scripts/test.py

@@ -22,16 +22,7 @@ import toml
 
 TEST_PATHS = ['tests']
 RUNNER_PATH = './runners/test_runner'
-
-SUITE_PROLOGUE = """
-#include "runners/test_runner.h"
-#include "bd/lfs_testbd.h"
-#include <stdio.h>
-"""
-CASE_PROLOGUE = """
-"""
-CASE_EPILOGUE = """
-"""
+HEADER_PATH = 'runners/test_runner.h'
 
 
 def testpath(path):
@@ -49,14 +40,21 @@ def testcase(path):
     _, case, *_ = path.split('#', 2)
     return '%s#%s' % (testsuite(path), case)
 
-def openio(path, mode='r'):
+def openio(path, mode='r', buffering=-1, nb=False):
     if path == '-':
         if 'r' in mode:
-            return os.fdopen(os.dup(sys.stdin.fileno()), 'r')
+            return os.fdopen(os.dup(sys.stdin.fileno()), 'r', buffering)
         else:
-            return os.fdopen(os.dup(sys.stdout.fileno()), 'w')
+            return os.fdopen(os.dup(sys.stdout.fileno()), 'w', buffering)
+    elif nb and 'a' in mode:
+        return os.fdopen(os.open(
+                path,
+                os.O_WRONLY | os.O_CREAT | os.O_APPEND | os.O_NONBLOCK,
+                0o666),
+            mode,
+            buffering)
     else:
-        return open(path, mode)
+        return open(path, mode, buffering)
 
 def color(**args):
     if args.get('color') == 'auto':
@@ -252,19 +250,8 @@ def compile(**args):
             f.writeln("//")
             f.writeln()
 
-            # redirect littlefs tracing
-            f.writeln('#define LFS_TRACE_(fmt, ...) do { \\')
-            f.writeln(8*' '+'extern FILE *test_trace; \\')
-            f.writeln(8*' '+'if (test_trace) { \\')
-            f.writeln(12*' '+'fprintf(test_trace, '
-                '"%s:%d:trace: " fmt "%s\\n", \\')
-            f.writeln(20*' '+'__FILE__, __LINE__, __VA_ARGS__); \\')
-            f.writeln(8*' '+'} \\')
-            f.writeln(4*' '+'} while (0)')
-            f.writeln('#define LFS_TRACE(...) LFS_TRACE_(__VA_ARGS__, "")')
-            f.writeln('#define LFS_TESTBD_TRACE(...) '
-                'LFS_TRACE_(__VA_ARGS__, "")')
-            f.writeln()
+            # include test_runner.h in every generated file
+            f.writeln("#include \"%s\"" % HEADER_PATH)
 
             # write out generated functions, this can end up in different
             # files depending on the "in" attribute
@@ -316,10 +303,6 @@ def compile(**args):
                     f.writeln('void __test__%s__%s__run('
                         '__attribute__((unused)) struct lfs_config *cfg) {'
                         % (suite.name, case.name))
-                    if CASE_PROLOGUE.strip():
-                        f.writeln(4*' '+'%s'
-                            % CASE_PROLOGUE.strip().replace('\n', '\n'+4*' '))
-                        f.writeln()
                     f.writeln(4*' '+'// test case %s' % case.id())
                     if case.code_lineno is not None:
                         f.writeln(4*' '+'#line %d "%s"'
@@ -328,17 +311,10 @@ def compile(**args):
                     if case.code_lineno is not None:
                         f.writeln(4*' '+'#line %d "%s"'
                             % (f.lineno+1, args['output']))
-                    if CASE_EPILOGUE.strip():
-                        f.writeln()
-                        f.writeln(4*' '+'%s'
-                            % CASE_EPILOGUE.strip().replace('\n', '\n'+4*' '))
                     f.writeln('}')
                     f.writeln()
 
             if not args.get('source'):
-                # write test suite prologue
-                f.writeln('%s' % SUITE_PROLOGUE.strip())
-                f.writeln()
                 if suite.code is not None:
                     if suite.code_lineno is not None:
                         f.writeln('#line %d "%s"'
@@ -427,9 +403,6 @@ def compile(**args):
                     shutil.copyfileobj(sf, f)
                 f.writeln()
 
-                f.write(SUITE_PROLOGUE)
-                f.writeln()
-
                 # write any internal tests
                 for suite in suites:
                     for case in suite.cases:
@@ -638,6 +611,7 @@ def run_stage(name, runner_, **args):
 
         # run the tests!
         cmd = runner_.copy()
+        # TODO move all these to runner?
         if args.get('disk'):
             cmd.append('--disk=%s' % args['disk'])
         if args.get('trace'):
@@ -656,8 +630,7 @@ def run_stage(name, runner_, **args):
         os.close(spty)
         children.add(proc)
         mpty = os.fdopen(mpty, 'r', 1)
-        if args.get('output'):
-            output = openio(args['output'], 'w')
+        output = None
 
         last_id = None
         last_output = []
@@ -675,8 +648,18 @@ def run_stage(name, runner_, **args):
                     break
                 last_output.append(line)
                 if args.get('output'):
+                    try:
+                        if not output:
+                            output = openio(args['output'], 'a', 1, nb=True)
                         output.write(line)
-                elif args.get('verbose'):
+                    except OSError as e:
+                        if e.errno not in [
+                                errno.ENXIO,
+                                errno.EPIPE,
+                                errno.EAGAIN]:
+                            raise
+                        output = None
+                if args.get('verbose'):
                     sys.stdout.write(line)
 
                 m = pattern.match(line)
@@ -709,8 +692,6 @@ def run_stage(name, runner_, **args):
         finally:
             children.remove(proc)
             mpty.close()
-            if args.get('output'):
-                output.close()
 
         proc.wait()
         if proc.returncode != 0:
@@ -722,6 +703,7 @@ def run_stage(name, runner_, **args):
 
     def run_job(runner, start=None, step=None):
         nonlocal failures
+        nonlocal killed
         nonlocal locals
 
         start = start or 0
@@ -756,6 +738,7 @@ def run_stage(name, runner_, **args):
                     continue
                 else:
                     # stop other tests
+                    killed = True
                     for child in children.copy():
                         child.kill()
                     break
@@ -766,10 +749,12 @@ def run_stage(name, runner_, **args):
     if 'jobs' in args:
         for job in range(args['jobs']):
             runners.append(th.Thread(
-                target=run_job, args=(runner_, job, args['jobs'])))
+                target=run_job, args=(runner_, job, args['jobs']),
+                daemon=True))
     else:
         runners.append(th.Thread(
-            target=run_job, args=(runner_, None, None)))
+            target=run_job, args=(runner_, None, None),
+            daemon=True))
 
     def print_update(done):
         if not args.get('verbose') and (color(**args) or done):
@@ -830,8 +815,10 @@ def run_stage(name, runner_, **args):
     
 
 def run(**args):
+    # measure runtime
     start = time.time()
 
+    # query runner for tests
     runner_ = runner(**args)
     print('using runner: %s'
         % ' '.join(shlex.quote(c) for c in runner_))
@@ -844,6 +831,15 @@ def run(**args):
             total_perms))
     print()
 
+    # truncate and open logs here so they aren't disconnected between tests
+    output = None
+    if args.get('output'):
+        output = openio(args['output'], 'w', 1)
+    trace = None
+    if args.get('trace'):
+        trace = openio(args['trace'], 'w', 1)
+
+    # spawn runners
     expected = 0
     passed = 0
     powerlosses = 0
@@ -857,7 +853,9 @@ def run(**args):
 
         # spawn jobs for stage
         expected_, passed_, powerlosses_, failures_, killed = run_stage(
-            by or 'tests', stage_runner, **args)
+            by or 'tests',
+            stage_runner,
+            **args)
         expected += expected_
         passed += passed_
         powerlosses += powerlosses_
@@ -865,6 +863,11 @@ def run(**args):
         if (failures and not args.get('keep_going')) or killed:
             break
 
+    if output:
+        output.close()
+    if trace:
+        trace.close()
+
     # show summary
     print()
     print('%sdone:%s %s' % (
@@ -974,9 +977,11 @@ def main(**args):
 if __name__ == "__main__":
     import argparse
     import sys
+    argparse.ArgumentParser._handle_conflict_ignore = lambda *_: None
+    argparse._ArgumentGroup._handle_conflict_ignore = lambda *_: None
     parser = argparse.ArgumentParser(
         description="Build and run tests.",
-        conflict_handler='resolve')
+        conflict_handler='ignore')
     parser.add_argument('test_ids', nargs='*',
         help="Description of testis to run. May be a directory, path, or \
             test identifier. Test identifiers are of the form \
@@ -1013,11 +1018,11 @@ if __name__ == "__main__":
         help="Comma-separated list of power-loss scenarios to test. \
             Defaults to 0,l.")
     test_parser.add_argument('-d', '--disk',
-        help="Redirect block device operations to this file.")
+        help="Direct block device operations to this file.")
     test_parser.add_argument('-t', '--trace',
-        help="Redirect trace output to this file.")
+        help="Direct trace output to this file.")
     test_parser.add_argument('-o', '--output',
-        help="Redirect stdout and stderr to this file.")
+        help="Direct stdout and stderr to this file.")
     test_parser.add_argument('--read-delay',
         help="Artificial read delay in seconds.")
     test_parser.add_argument('--prog-delay',