source: branches/profile/UNIT_TESTER/UnitTester.cxx

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