source: tags/arb-6.0/UNIT_TESTER/UnitTester.cxx

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