source: tags/testbuild/UNIT_TESTER/UnitTester.cxx

Last change on this file was 13193, checked in by westram, 10 years ago
File size: 20.9 KB
Line 
1// ================================================================ //
2//                                                                  //
3//   File      : UnitTester.cxx                                     //
4//   Purpose   :                                                    //
5//                                                                  //
6//   Coded by Ralf Westram (coder@reallysoft.de) in February 2010   //
7//   Institute of Microbiology (Technical University Munich)        //
8//   http://www.arb-home.de/                                        //
9//                                                                  //
10// ================================================================ //
11
12#include "UnitTester.hxx"
13
14#include <cstdarg>
15#include <cstdlib>
16#include <cstdio>
17#include <cstring>
18#include <cerrno>
19#include <climits>
20
21#include <sys/time.h>
22#include <sys/stat.h>
23
24#include <arb_simple_assert.h>
25#include <arb_backtrace.h>
26#include <arb_pathlen.h>
27
28#include <test_unit.h>
29#include <ut_valgrinded.h>
30#include <valgrind.h>
31
32#include <SuppressOutput.h>
33
34#include <SigHandler.h>
35#include <setjmp.h>
36#include <unistd.h>
37#include <string>
38#include <signal.h>
39
40#include "../SOURCE_TOOLS/arb_main.h"
41
42#define ut_assert(cond) arb_assert(cond)
43
44#if defined(DEVEL_ELMAR)
45#define COLORED_MESSAGES
46#endif
47
48#if defined(DEBUG)
49# if defined(DEVEL_RALF)
50#  if (GCC_VERSION_CODE>=408)
51#   warning TEST_VALID_LOCATION disabled - does not work with this gcc version
52#  else
53#   define TEST_VALID_LOCATION
54#  endif
55# endif
56#endif
57
58#ifdef COLORED_MESSAGES
59
60#define ESC_BOLD      "\033[1m"
61#define ESC_RED       "\033[31m"
62#define ESC_GREEN     "\033[32m"
63#define ESC_YELLOW    "\033[33m"
64#define ESC_RESET_COL "\033[39m"
65#define ESC_RESET_ALL "\033[0m"
66
67#endif
68
69using namespace std;
70
71// --------------------------------------------------------------------------------
72
73struct Globals : virtual Noncopyable {
74    bool        inside_test;
75    bool        running_on_valgrind;
76    char       *runDir;
77    pid_t       pid;
78    const char *libname;
79
80    Globals()
81        : inside_test(false),
82          runDir(NULL),
83          pid(getpid()),
84          libname(NULL)
85    {
86        running_on_valgrind = (RUNNING_ON_VALGRIND>0);
87    }
88    ~Globals() {
89        free(runDir);
90    }
91
92    inline void setup_test_precondition() {
93        TEST_EXPECT_ZERO_OR_SHOW_ERRNO(chdir(runDir));
94    }
95    inline void setup_test_postcondition() {
96        TEST_ANNOTATE(NULL);
97    }
98};
99
100static Globals GLOBAL;
101
102// --------------------------------------------------------------------------------
103// #define TRACE_PREFIX "UnitTester:0: "
104#define TRACE_PREFIX "UnitTester: "
105
106__ATTR__FORMAT(1) static void trace(const char *format, ...) {
107    va_list parg;
108
109    fflush(stdout);
110    fflush(stderr);
111
112#if defined(COLORED_MESSAGES)
113    fputs(ESC_BOLD, stderr);
114#endif
115    fputs(TRACE_PREFIX, stderr);
116    va_start(parg, format);
117    vfprintf(stderr, format, parg);
118    va_end(parg);
119#if defined(COLORED_MESSAGES)
120    fputs(ESC_RESET_ALL, stderr);
121#endif
122    fputc('\n', stderr);
123    fflush(stderr);
124}
125
126// --------------------------------------------------------------------------------
127
128#ifdef COLORED_MESSAGES
129static const char *readable_result[] = {
130    ESC_GREEN "OK"           ESC_RESET_COL,
131    ESC_RED   "TRAPPED"      ESC_RESET_COL,
132    ESC_RED   "VIOLATED"     ESC_RESET_COL,
133    ESC_RED   "INTERRUPTED"  ESC_RESET_COL,
134    ESC_RED   "THREW"        ESC_RESET_COL,
135    ESC_RED   "INVALID"      ESC_RESET_COL,
136    ESC_RED   "{unknown}"    ESC_RESET_COL,
137};
138#else
139static const char *readable_result[] = {
140    "OK"           ,
141    "TRAPPED"      ,
142    "VIOLATED"     ,
143    "INTERRUPTED"  ,
144    "THREW"        ,
145    "INVALID"      , // use TEST_PUBLISH to make it valid
146    "{unknown}"    ,
147};
148#endif
149
150// --------------------------------------------------------------------------------
151
152static jmp_buf UNITTEST_return_after_segv;
153static bool    terminate_was_called = false;
154
155enum TrapCode {
156    TRAP_UNEXPECTED = 668,
157    TRAP_SEGV,
158    TRAP_INT,
159    TRAP_TERM,
160};
161
162__ATTR__NORETURN static void UNITTEST_sigsegv_handler(int sig) {
163    if (GLOBAL.inside_test) {
164        int  trap_code;
165        const char *backtrace_cause = NULL;
166        switch (sig) {
167            case SIGSEGV: {
168                trap_code = TRAP_SEGV;
169               
170                arb_test::GlobalTestData& test_data = arb_test::test_data();
171                if (!test_data.assertion_failed) { // not caused by assertion
172                    backtrace_cause = "Caught SIGSEGV not caused by assertion";
173                }
174                break;
175            }
176            case SIGINT:
177                trap_code = TRAP_INT;
178                backtrace_cause = "Caught SIGINT (deadlock in test function?)";
179                break;
180
181            case SIGTERM:
182                trap_code = TRAP_TERM;
183                if (terminate_was_called) {
184                    backtrace_cause = "Caught SIGTERM, cause std::terminate() has been called in test-code (might be an invalid throw)";
185                }
186                else {
187                    backtrace_cause = "Caught SIGTERM (deadlock in uninterruptable test function?)";
188                }
189                break;
190
191            default:
192                trap_code = TRAP_UNEXPECTED;
193                test_assert(0, true);
194                break;
195        }
196        if (backtrace_cause) demangle_backtrace(BackTraceInfo(0), stderr, backtrace_cause);
197        siglongjmp(UNITTEST_return_after_segv, trap_code); // suppress signal
198    }
199
200    const char *signame = NULL;
201    switch (sig) {
202        case SIGSEGV: signame = "SEGV"; break;
203        case SIGINT: signame  = "INT"; break;
204        case SIGTERM: signame = "TERM"; break;
205    }
206
207    fputs("[UnitTester catched unexpected signal ", stderr);
208    if (signame) fputs(signame, stderr); else fprintf(stderr, "%i", sig);
209    fputs("]\n", stderr);
210    BackTraceInfo(0).dump(stderr, "Unexpected signal (NOT raised in test-code)");
211    exit(EXIT_FAILURE);
212}
213
214#define SECOND 1000000
215
216static void terminate_called() {
217    // example-test triggering call of terminate_called(): ../CORE/arb_signal.cxx@TEST_throw_during_throw
218    terminate_was_called = true;
219    raise(SIGTERM);
220    // GBK_dump_backtrace(stdout, "just raised SIGTERM - wtf am i doing here"); fflush(stdout);
221}
222
223static UnitTestResult execute_guarded_ClientCode(UnitTest_function fun, long *duration_usec) {
224    terminate_handler old_terminate = std::set_terminate(terminate_called);
225
226    SigHandler old_int_handler  = INSTALL_SIGHANDLER(SIGINT,  UNITTEST_sigsegv_handler, "execute_guarded");
227    SigHandler old_term_handler = INSTALL_SIGHANDLER(SIGTERM, UNITTEST_sigsegv_handler, "execute_guarded");
228    SigHandler old_segv_handler = INSTALL_SIGHANDLER(SIGSEGV, UNITTEST_sigsegv_handler, "execute_guarded");
229
230    // ----------------------------------------
231    // start of critical section
232    // (need volatile for modified local auto variables, see man longjump)
233    volatile timeval        t1;
234    volatile UnitTestResult result  = TEST_OK;
235    volatile int            trapped = sigsetjmp(UNITTEST_return_after_segv, 1);
236
237    if (trapped) {
238        switch (trapped) {
239            case TRAP_UNEXPECTED: ut_assert(0); // fall-through
240            case TRAP_SEGV: result = TEST_TRAPPED; break;
241
242            case TRAP_INT:
243            case TRAP_TERM: result = TEST_INTERRUPTED; break;
244        }
245    }
246    else { // normal execution
247        GLOBAL.inside_test = true;
248
249        gettimeofday((timeval*)&t1, NULL);
250
251        arb_test::test_data().assertion_failed = false;
252        arb_test::test_data().running_test = true;
253
254        // Note: fun() may do several ugly things, e.g.
255        // - segfault                           (handled)
256        // - never return                       (handled by caller)
257        // - exit() or abort()                  (std::terminate is handled, direct call to abort is not)
258        // - throw an exception                 (catched by caller of execute_guarded_ClientCode)
259        // - change working dir                 (should always be reset before i get called)
260
261        fun();
262
263        // sleepms(10000); // simulate a deadlock
264    }
265    // end of critical section
266    // ----------------------------------------
267
268    timeval t2;
269    gettimeofday(&t2, NULL);
270    *duration_usec = (t2.tv_sec - t1.tv_sec) * SECOND + (t2.tv_usec - t1.tv_usec);
271
272    GLOBAL.inside_test = false;
273
274    UNINSTALL_SIGHANDLER(SIGSEGV, UNITTEST_sigsegv_handler, old_segv_handler, "execute_guarded");
275    UNINSTALL_SIGHANDLER(SIGTERM, UNITTEST_sigsegv_handler, old_term_handler, "execute_guarded");
276    UNINSTALL_SIGHANDLER(SIGINT,  UNITTEST_sigsegv_handler, old_int_handler,  "execute_guarded");
277
278    terminate_handler handler = std::set_terminate(old_terminate);
279    if (handler != terminate_called) {
280        fputs("Error: test-code has modified std::terminate (this is invalid)\n", stderr);
281        fflush(stderr);
282        result = TEST_INVALID;
283    }
284
285    return result;
286}
287
288inline bool kill_verbose(pid_t pid, int sig, const char *signame) {
289    int result = kill(pid, sig);
290    if (result != 0) {
291        fprintf(stderr, "Failed to send %s to test (%s)\n", signame, strerror(errno));
292        fflush(stderr);
293    }
294    return result == 0;
295}
296
297class Flag {
298    string flagname;
299
300public:
301    Flag(const string& flagname_) : flagname(flagname_) {}
302
303    bool is_up() const { struct stat stt; return stat(flagname.c_str(), &stt) == 0 && S_ISREG(stt.st_mode); }
304    void raise() {
305        fprintf(stderr, "Raising flag '%s'\n", flagname.c_str()); fflush(stderr);
306        ut_assert(!is_up());
307        FILE *fp = fopen(flagname.c_str(), "w");
308        fclose(fp);
309    }
310    void lower() {
311        fprintf(stderr, "Lowering flag '%s'\n", flagname.c_str()); fflush(stderr);
312        ut_assert(is_up());
313        TEST_EXPECT_ZERO_OR_SHOW_ERRNO(unlink(flagname.c_str()));
314    }
315
316    void lower_if_up() { if (is_up()) lower(); }
317};
318
319inline Flag getLocalFlag(const char *flagname) {
320    string localname  = string(GLOBAL.runDir)+"/../flags/"+flagname+'.'+GLOBAL.libname;
321    return Flag(localname);
322}
323
324static bool flag_callback(arb_test::FlagAction action, const char *name) {
325    using namespace arb_test;
326
327    Flag flag   = getLocalFlag(name);
328    bool result = true;
329
330    switch (action) {
331        case FLAG_RAISE:
332            if (!flag.is_up()) flag.raise();
333            break;
334        case FLAG_IS_RAISED:
335            result = flag.is_up();
336            break;
337    }
338
339    return result;
340}
341
342inline bool been_inside_environment() {
343    return getLocalFlag(ANY_SETUP).is_up() || arb_test::test_data().entered_mutex_loop;
344}
345inline bool did_valgrinded_syscall() { 
346    return seen_valgrinded_call();
347}
348inline void reset_test_local_flags() {
349    getLocalFlag(ANY_SETUP).lower_if_up();
350}
351
352void sleepms(long ms) {
353    int  seconds = ms/1000;
354    long rest_ms = ms - seconds*1000;
355
356    if (seconds) sleep(seconds);
357    usleep(rest_ms*1000);
358}
359
360#if (DEADLOCKGUARD == 1)
361__ATTR__NORETURN static void deadlockguard(long max_allowed_duration_ms, bool detect_environment_calls) {
362    // this function is completely incompatible with debuggers
363    sleepms(max_allowed_duration_ms);
364
365    if (detect_environment_calls && been_inside_environment()) {
366        fprintf(stderr, "[test_environment has been called. Added %li ms tolerance]\n", MAX_EXEC_MS_ENV);
367        fflush(stderr);
368        sleepms(MAX_EXEC_MS_ENV);
369        max_allowed_duration_ms += MAX_EXEC_MS_ENV;
370    }
371
372    if (did_valgrinded_syscall()) {
373        const long additional    = max_allowed_duration_ms*3 + MAX_EXEC_MS_VGSYS;
374        fprintf(stderr, "[external calls are running valgrinded. Added %li ms tolerance]\n", additional);
375        fflush(stderr);
376        sleepms(additional);
377        max_allowed_duration_ms += additional;
378    }
379
380    const useconds_t aBIT = 50*1000; // 50 microseconds
381
382    fprintf(stderr,
383            "[deadlockguard woke up after %li ms]\n"
384            "[interrupting possibly deadlocked test]\n",
385            max_allowed_duration_ms); fflush(stderr);
386    kill_verbose(GLOBAL.pid, SIGINT, "SIGINT");
387    usleep(aBIT); // give parent a chance to kill me
388
389    fprintf(stderr, "[test still running -> terminate]\n"); fflush(stderr);
390    kill_verbose(GLOBAL.pid, SIGTERM, "SIGTERM");
391    usleep(aBIT); // give parent a chance to kill me
392
393    fprintf(stderr, "[still running -> kill]\n"); fflush(stderr);
394    kill_verbose(GLOBAL.pid, SIGKILL, "SIGKILL"); // commit suicide
395    // parent had his chance
396    fprintf(stderr, "[still alive after suicide -> perplexed]\n"); fflush(stderr);
397    exit(EXIT_FAILURE);
398}
399#endif
400
401UnitTestResult execute_guarded(UnitTest_function fun, long *duration_usec, long max_allowed_duration_ms, bool detect_environment_calls) {
402    if (GLOBAL.running_on_valgrind) max_allowed_duration_ms *= 4;
403    UnitTestResult result;
404
405    pid_t child_pid = fork();
406    if (child_pid) { // parent
407        try { result = execute_guarded_ClientCode(fun, duration_usec); }
408        catch (...) { result = TEST_THREW; }
409        if (kill(child_pid, SIGKILL) != 0) {
410            fprintf(stderr, "Failed to kill deadlock-guard (%s)\n", strerror(errno)); fflush(stderr);
411        }
412    }
413    else { // child
414#if (DEADLOCKGUARD == 1)
415        deadlockguard(max_allowed_duration_ms, detect_environment_calls);
416#else
417#warning DEADLOCKGUARD has been disabled (not default!)
418        detect_environment_calls = detect_environment_calls; // dont warn
419#endif
420        exit(EXIT_FAILURE);
421    }
422
423    return result;
424}
425
426// --------------------------------------------------------------------------------
427
428class SimpleTester {
429    const UnitTest_simple *tests;
430    const UnitTest_simple *postcond;
431    size_t                 count;
432    size_t                 postcount;
433    double                 duration_ms;
434
435    bool perform(size_t which);
436    UnitTestResult run_postcond(long *duration_usec, long max_allowed_duration_ms, bool print_errors);
437
438public:
439    SimpleTester(const UnitTest_simple *tests_, const UnitTest_simple *postcond_)
440        : tests(tests_),
441          postcond(postcond_),
442          duration_ms(0.0)
443    {
444        for (count = 0; tests[count].fun; ++count) {}
445        for (postcount = 0; postcond[postcount].fun; ++postcount) {}
446    }
447
448    size_t perform_all();
449    size_t get_test_count() const { return count; }
450
451    double overall_duration_ms() const { return duration_ms; }
452};
453
454
455size_t SimpleTester::perform_all() {
456    // returns number of passed tests
457
458    trace("performing %zu simple tests..", count);
459    size_t passed = 0;
460    for (size_t c = 0; c<count; ++c) {
461        GLOBAL.setup_test_precondition();
462        passed += perform(c);
463        GLOBAL.setup_test_postcondition();
464    }
465    return passed;
466}
467
468
469UnitTestResult SimpleTester::run_postcond(long *duration_usec_sum, long abort_after_ms, bool print_errors) {
470    UnitTestResult result = TEST_OK;
471    *duration_usec_sum    = 0;
472    for (size_t pc = 0; pc<postcount && result == TEST_OK; ++pc) {
473        long duration_usec;
474        result              = execute_guarded(postcond[pc].fun, &duration_usec, abort_after_ms, true);
475        *duration_usec_sum += duration_usec;
476
477        if (result != TEST_OK && print_errors) {
478            postcond[pc].print_error(stderr, result);
479        }
480    }
481    return result;
482}
483
484void UnitTest_simple::print_error(FILE *out, UnitTestResult result) const {
485    switch (result) {
486        case TEST_OK:
487            break;
488
489        case TEST_TRAPPED:
490            fprintf(out, "%s: Error: %s failed (details above)\n", location, name);
491            break;
492
493        case TEST_FAILED_POSTCONDITION:
494            fprintf(out, "%s: Error: %s succeeded, but violates general postconditions (see above)\n", location, name);
495            break;
496
497        case TEST_INTERRUPTED:
498            fprintf(out, "%s: Error: %s has been interrupted (details above)\n", location, name);
499            break;
500
501        case TEST_THREW:
502            fprintf(out, "%s: Error: %s has thrown an exception\n", location, name);
503            break;
504
505        case TEST_INVALID:
506            fprintf(out, "%s: Error: %s is invalid (see above)\n", location, name);
507            break;
508
509        case TEST_UNKNOWN_RESULT:
510            ut_assert(0);
511            break;
512    }
513}
514
515bool SimpleTester::perform(size_t which) {
516    ut_assert(which<count);
517
518    const UnitTest_simple& test = tests[which];
519    UnitTest_function      fun  = test.fun;
520
521    reset_test_local_flags();
522
523    bool       marked_as_slow = strlen(test.name) >= 10 && memcmp(test.name, "TEST_SLOW_", 10) == 0;
524    const long abort_after_ms = marked_as_slow ? MAX_EXEC_MS_SLOW : MAX_EXEC_MS_NORMAL;
525
526#if defined(TEST_VALID_LOCATION)
527    bool invalid = test.location == NULL; // in NDEBUG mode location is always missing
528#else
529    bool invalid = false;
530#endif
531
532    long           duration_usec;
533    UnitTestResult result           = invalid ? TEST_INVALID : execute_guarded(fun, &duration_usec, abort_after_ms, true); // <--- call test
534    double         duration_ms_this = invalid ? 0.0 : duration_usec/1000.0;
535
536    duration_ms += duration_ms_this;
537
538    long           duration_usec_post = 0;
539    UnitTestResult postcond_result    = TEST_UNKNOWN_RESULT;
540
541    if (result == TEST_OK) {
542        // if test is ok -> check postconditions
543        postcond_result = run_postcond(&duration_usec_post, MAX_EXEC_MS_NORMAL, true);
544        if (postcond_result != TEST_OK) {
545            result = TEST_FAILED_POSTCONDITION; // fail test, if any postcondition fails
546        }
547    }
548
549    trace("* %s = %s (%.1f ms)", test.name, readable_result[result], duration_ms_this);
550
551    if (result == TEST_OK) {
552        if (duration_ms_this >= WARN_SLOW_ABOVE_MS) {                    // long test duration
553            if (!marked_as_slow) {
554                bool accept_slow = GLOBAL.running_on_valgrind || did_valgrinded_syscall();
555                if (!accept_slow) {
556                    fprintf(stderr, "%s: Warning: Name of slow tests shall start with TEST_SLOW_ (it'll be run after other tests)\n",
557                            test.location);
558                }
559            }
560        }
561    }
562
563    test.print_error(stderr, result);
564
565    if (result != TEST_OK && result != TEST_FAILED_POSTCONDITION) { // postconditions not checked yet
566        // also check postconditions when test failed
567        // (because they are used to clean up side effects of failing tests)
568        SuppressOutput here;
569        postcond_result = run_postcond(&duration_usec_post, MAX_EXEC_MS_NORMAL, false); // but do not print anything
570    }
571
572    double duration_ms_postcond  = duration_usec_post/1000.0;
573    duration_ms                 += duration_ms_postcond;
574
575    return result == TEST_OK;
576}
577
578
579// --------------------------------------------------------------------------------
580
581static char text_buffer[100];
582
583inline const char *as_text(size_t z) { sprintf(text_buffer, "%zu", z); return text_buffer; }
584inline const char *as_text(double d) { sprintf(text_buffer, "%.1f", d); return text_buffer; }
585
586inline void appendValue(string& report, const char *tag, const char *value) { report = report+' '+tag+'='+value; }
587
588inline void appendValue(string& report, const char *tag, size_t value) { appendValue(report, tag, as_text(value)); }
589inline void appendValue(string& report, const char *tag, double value) { appendValue(report, tag, as_text(value)); }
590
591static const char *generateReport(const char *libname, size_t tests, size_t skipped, size_t passed, double duration_ms, size_t warnings) {
592    // generate a report consumed by reporter.pl@parse_log
593   
594    static string report;
595    report.clear();
596
597    size_t tested = tests-skipped;
598    size_t failed = tested-passed;
599
600    appendValue(report, "target", libname);
601    appendValue(report, "time", duration_ms);
602    appendValue(report, "tests", tests);
603    if (skipped) appendValue(report, "skipped", skipped);
604    if (tests) {
605        if (!failed) appendValue(report, "passed", "ALL");
606        else         appendValue(report, "passed", passed);
607    }
608    if (failed) appendValue(report, "failed", failed);
609    if (warnings) appendValue(report, "warnings", warnings);
610
611    return report.c_str()+1; // skip leading space
612}
613
614UnitTester::UnitTester(const char *libname, const UnitTest_simple *simple_tests, int warn_level, size_t skippedTests, const UnitTest_simple *postcond) {
615    // this is the "main()" of the unit test
616    // it is invoked from code generated by sym2testcode.pl@InvokeUnitTester
617
618    start_of_main();
619
620    TEST_EXPECT_ZERO_OR_SHOW_ERRNO(chdir("run"));
621    GLOBAL.runDir  = getcwd(0, ARB_PATH_MAX);
622    GLOBAL.libname = libname;
623
624    size_t tests  = 0;
625    size_t passed = 0;
626
627    {
628        arb_test::GlobalTestData& global = arb_test::test_data();
629
630        global.init(flag_callback);
631        global.show_warnings = (warn_level != 0);
632
633        double duration_ms = 0;
634        {
635            SimpleTester simple_tester(simple_tests, postcond);
636
637            tests = simple_tester.get_test_count();
638            if (tests) {
639                passed      = simple_tester.perform_all();
640                duration_ms = simple_tester.overall_duration_ms();
641            }
642        }
643
644        trace("%s", generateReport(libname,
645                                   tests+skippedTests, skippedTests, passed,
646                                   duration_ms, global.warnings));
647    }
648
649    arb_test::GlobalTestData::erase_instance();
650    exit(tests == passed ? EXIT_SUCCESS : EXIT_FAILURE);
651}
652
653
Note: See TracBrowser for help on using the repository browser.