https://github.com/akkartik/mu/blob/main/linux/bootstrap/003trace.cc

      1 //: The goal of layers is to make programs more easy to understand and more
      2 //: malleable, easy to rewrite in radical ways without accidentally breaking
      3 //: some corner case. Tests further both goals. They help understandability by
      4 //: letting one make small changes and get feedback. What if I wrote this line
      5 //: like so? What if I removed this function call, is it really necessary?
      6 //: Just try it, see if the tests pass. Want to explore rewriting this bit in
      7 //: this way? Tests put many refactorings on a firmer footing.
      8 //:
      9 //: But the usual way we write tests seems incomplete. Refactorings tend to
     10 //: work in the small, but don't help with changes to function boundaries. If
     11 //: you want to extract a new function you have to manually test-drive it to
     12 //: create tests for it. If you want to inline a function its tests are no
     13 //: longer valid. In both cases you end up having to reorganize code as well as
     14 //: tests, an error-prone activity.
     15 //:
     16 //: In response, this layer introduces the notion of domain-driven *white-box*
     17 //: testing. We focus on the domain of inputs the whole program needs to
     18 //: handle rather than the correctness of individual functions. All white-box
     19 //: tests invoke the program in a single way: by calling run() with some
     20 //: input. As the program operates on the input, it traces out a list of
     21 //: _facts_ deduced about the domain:
     22 //:   trace("label") << "fact 1: " << val;
     23 //:
     24 //: Tests can now check for these facts in the trace:
     25 //:   CHECK_TRACE_CONTENTS("label", "fact 1: 34\n"
     26 //:                                 "fact 2: 35\n");
     27 //:
     28 //: Since we never call anything but the run() function directly, we never have
     29 //: to rewrite the tests when we reorganize the internals of the program. We
     30 //: just have to make sure our rewrite deduces the same facts about the domain,
     31 //: and that's something we're going to have to do anyway.
     32 //:
     33 //: To avoid the combinatorial explosion of integration tests, each layer
     34 //: mainly logs facts to the trace with a common *label*. All tests in a layer
     35 //: tend to check facts with this label. Validating the facts logged with a
     36 //: specific label is like calling functions of that layer directly.
     37 //:
     38 //: To build robust tests, trace facts about your domain rather than details of
     39 //: how you computed them.
     40 //:
     41 //: More details: http://akkartik.name/blog/tracing-tests
     42 //:
     43 //: ---
     44 //:
     45 //: Between layers and domain-driven testing, programming starts to look like a
     46 //: fundamentally different activity. Instead of focusing on a) superficial,
     47 //: b) local rules on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
     48 //: we allow programmers to engage with the a) deep, b) global structure of
     49 //: the c) domain. If you can systematically track discontinuities in the
     50 //: domain, you don't care if the code used gotos as long as it passed all
     51 //: tests. If tests become more robust to run, it becomes easier to try out
     52 //: radically different implementations for the same program. If code is
     53 //: super-easy to rewrite, it becomes less important what indentation style it
     54 //: uses, or that the objects are appropriately encapsulated, or that the
     55 //: functions are referentially transparent.
     56 //:
     57 //: Instead of plumbing, programming becomes building and gradually refining a
     58 //: map of the environment the program must operate under. Whether a program
     59 //: is 'correct' at a given point in time is a red herring; what matters is
     60 //: avoiding regression by monotonically nailing down the more 'eventful'
     61 //: parts of the terrain. It helps readers new and old, and rewards curiosity,
     62 //: to organize large programs in self-similar hierarchies of example tests
     63 //: colocated with the code that makes them work.
     64 //:
     65 //:   "Programming properly should be regarded as an activity by which
     66 //:   programmers form a mental model, rather than as production of a program."
     67 //:   -- Peter Naur (http://akkartik.name/naur.pdf)
     68
     69 //:: == Core data structures
     70
     71 :(before "End Globals")
     72 trace_stream* Trace_stream = NULL;
     73
     74 :(before "End Types")
     75 struct trace_stream {
     76   vector<trace_line> past_lines;
     77   // End trace_stream Fields
     78
     79   trace_stream() {
     80     // End trace_stream Constructor
     81   }
     82   ~trace_stream() {
     83     // End trace_stream Destructor
     84   }
     85   // End trace_stream Methods
     86 };
     87
     88 //:: == Adding to the trace
     89
     90 //: Top-level method is trace() which can be used like an ostream. Usage:
     91 //:   trace(depth, label) << ... << end();
     92 //: Don't forget the 'end()' to actually append to the trace.
     93 :(before "End Includes")
     94 // No brackets around the expansion so that it prints nothing if Trace_stream
     95 // isn't initialized.
     96 #define trace(...)  !Trace_stream ? cerr : Trace_stream->stream(__VA_ARGS__)
     97
     98 :(before "End trace_stream Fields")
     99 // accumulator for current trace_line
    100 ostringstream* curr_stream;
    101 string curr_label;
    102 int curr_depth;
    103 // other stuff
    104 int collect_depth;  // avoid tracing lower levels for speed
    105 ofstream null_stream;  // never opened, so writes to it silently fail
    106
    107 //: Some constants.
    108 :(before "struct trace_stream")  // include constants in all cleaved compilation units
    109 const int Max_depth = 9999;
    110 :(before "End trace_stream Constructor")
    111 curr_stream = NULL;
    112 curr_depth = Max_depth;
    113 collect_depth = Max_depth;
    114
    115 :(before "struct trace_stream")
    116 struct trace_line {
    117   string contents;
    118   string label;
    119   int depth;  // 0 is 'sea level'; positive integers are progressively 'deeper' and lower level
    120   trace_line(string c, string l) {
    121     contents = c;
    122     label = l;
    123     depth = 0;
    124   }
    125   trace_line(string c, string l, int d) {
    126     contents = c;
    127     label = l;
    128     depth = d;
    129   }
    130 };
    131
    132 string unescape_newline(string& s) {
    133   std::stringstream ss;
    134   for (int i = 0;  i < SIZE(s);  ++i) {
    135     if (s.at(i) == '\n')
    136       ss << "\\n";
    137     else
    138       ss << s.at(i);
    139   }
    140   return ss.str();
    141 }
    142
    143 void dump_trace_line(ostream& s, trace_line& t) {
    144   s << std::setw(2) << t.depth << ' ' << t.label << ": " << unescape_newline(t.contents) << '\n';
    145 }
    146
    147 //: Starting a new trace line.
    148 :(before "End trace_stream Methods")
    149 ostream& stream(string label) {
    150   return stream(Max_depth, label);
    151 }
    152
    153 ostream& stream(int depth, string label) {
    154   if (depth > collect_depth) return null_stream;
    155   curr_stream = new ostringstream;
    156   curr_label = label;
    157   curr_depth = depth;
    158   (*curr_stream) << std::hex;  // printing addresses is the common case
    159   return *curr_stream;
    160 }
    161
    162 //: End of a trace line; append it to the trace.
    163 :(before "End Types")
    164 struct end {};
    165 :(code)
    166 ostream& operator<<(ostream& os, end /*unused*/) {
    167   if (Trace_stream) Trace_stream->newline();
    168   return os;
    169 }
    170
    171 //: Fatal error.
    172 :(before "End Types")
    173 struct die {};
    174 :(code)
    175 ostream& operator<<(ostream& /*unused*/, die /*unused*/) {
    176   if (Trace_stream) Trace_stream->newline();
    177   exit(1);
    178 }
    179
    180 :(before "End trace_stream Methods")
    181 void newline();
    182 :(code)
    183 void trace_stream::newline() {
    184   if (!curr_stream) return;
    185   string curr_contents = curr_stream->str();
    186   if (!curr_contents.empty()) {
    187     past_lines.push_back(trace_line(curr_contents, trim(curr_label), curr_depth));  // preserve indent in contents
    188     // maybe print this line to stderr
    189     trace_line& t = past_lines.back();
    190     if (should_incrementally_print_trace()) {
    191       dump_trace_line(cerr, t);
    192     }
    193     // End trace Commit
    194   }
    195
    196   // clean up
    197   delete curr_stream;
    198   curr_stream = NULL;
    199   curr_label.clear();
    200   curr_depth = Max_depth;
    201 }
    202
    203 //:: == Initializing the trace in tests
    204
    205 :(before "End Includes")
    206 #define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
    207 :(before "End Test Setup")
    208 START_TRACING_UNTIL_END_OF_SCOPE
    209
    210 //: Trace_stream is a resource, lease_tracer uses RAII to manage it.
    211 :(before "End Types")
    212 struct lease_tracer {
    213   lease_tracer();
    214   ~lease_tracer();
    215 };
    216 :(code)
    217 lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
    218 lease_tracer::~lease_tracer() {
    219   delete Trace_stream;
    220   Trace_stream = NULL;
    221 }
    222
    223 //:: == Errors and warnings using traces
    224
    225 :(before "End Includes")
    226 #define raise  (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
    227 #define warn (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Warn_depth, "warn"))
    228
    229 //: Print errors and warnings to the screen by default.
    230 :(before "struct trace_stream")  // include constants in all cleaved compilation units
    231 const int Error_depth = 0;
    232 const int Warn_depth = 1;
    233 :(before "End Globals")
    234 int Hide_errors = false;  // if set, don't print errors or warnings to screen
    235 int Hide_warnings = false;  // if set, don't print warnings to screen
    236 :(before "End Reset")
    237 Hide_errors = false;
    238 Hide_warnings = false;
    239 //: Never dump warnings in tests
    240 :(before "End Test Setup")
    241 Hide_warnings = true;
    242 :(code)
    243 bool trace_stream::should_incrementally_print_trace() {
    244   if (!Hide_errors && curr_depth == Error_depth) return true;
    245   if (!Hide_warnings && !Hide_errors && curr_depth == Warn_depth) return true;
    246   // End Incremental Trace Print Conditions
    247   return false;
    248 }
    249 :(before "End trace_stream Methods")
    250 bool should_incrementally_print_trace();
    251
    252 :(before "End Globals")
    253 int Trace_errors = 0;  // used only when Trace_stream is NULL
    254
    255 // Fail tests that displayed (unexpected) errors.
    256 // Expected errors should always be hidden and silently checked for.
    257 :(before "End Test Teardown")
    258 if (Passed && !Hide_errors && trace_contains_errors()) {
    259   Passed = false;
    260 }
    261 :(code)
    262 bool trace_contains_errors() {
    263   return Trace_errors > 0 || trace_count("error") > 0;
    264 }
    265
    266 :(before "End Includes")
    267 // If we aren't yet sure how to deal with some corner case, use assert_for_now
    268 // to indicate that it isn't an inviolable invariant.
    269 #define assert_for_now assert
    270 #define raise_for_now raise
    271
    272 //:: == Other assertions on traces
    273 //: Primitives:
    274 //:   - CHECK_TRACE_CONTENTS(lines)
    275 //:     Assert that the trace contains the given lines (separated by newlines)
    276 //:     in order. There can be other intervening lines between them.
    277 //:   - CHECK_TRACE_DOESNT_CONTAIN(line)
    278 //:   - CHECK_TRACE_DOESNT_CONTAIN(label, contents)
    279 //:     Assert that the trace doesn't contain the given (single) line.
    280 //:   - CHECK_TRACE_COUNT(label, count)
    281 //:     Assert that the trace contains exactly 'count' lines with the given
    282 //:     'label'.
    283 //:   - CHECK_TRACE_CONTAINS_ERRORS()
    284 //:   - CHECK_TRACE_DOESNT_CONTAIN_ERRORS()
    285 //:   - trace_count_prefix(label, prefix)
    286 //:     Count the number of trace lines with the given 'label' that start with
    287 //:     the given 'prefix'.
    288
    289 :(before "End Includes")
    290 #define CHECK_TRACE_CONTENTS(...)  check_trace_contents(__FUNCTION__, __FILE__, __LINE__, __VA_ARGS__)
    291
    292 #define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
    293
    294 #define CHECK_TRACE_COUNT(label, count) \
    295   if (Passed && trace_count(label) != (count)) { \
    296     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): trace_count of " << label << " should be " << count << '\n'; \
    297     cerr << "  got " << trace_count(label) << '\n';  /* multiple eval */ \
    298     DUMP(label); \
    299     Passed = false; \
    300     return;  /* Currently we stop at the very first failure. */ \
    301   }
    302
    303 #define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
    304 #define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
    305   if (Passed && trace_contains_errors()) { \
    306     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
    307     DUMP("error"); \
    308     Passed = false; \
    309     return; \
    310   }
    311
    312 // Allow tests to ignore trace lines generated during setup.
    313 #define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream
    314
    315 :(code)
    316 bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expected) {
    317   if (!Passed) return false;
    318   if (!Trace_stream) return false;
    319   vector<string> expected_lines = split(expected, "\n");
    320   int curr_expected_line = 0;
    321   while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
    322     ++curr_expected_line;
    323   if (curr_expected_line == SIZE(expected_lines)) return true;
    324   string label, contents;
    325   split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
    326   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
    327     if (label != p->label) continue;
    328     string t = trim(p->contents);
    329     if (contents != unescape_newline(t)) continue;
    330     ++curr_expected_line;
    331     while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
    332       ++curr_expected_line;
    333     if (curr_expected_line == SIZE(expected_lines)) return true;
    334     split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
    335   }
    336
    337   if (line_exists_anywhere(label, contents)) {
    338     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): line [" << label << ": " << contents << "] out of order in trace:\n";
    339     DUMP("");
    340   }
    341   else {
    342     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): missing [" << contents << "] in trace:\n";
    343     DUMP(label);
    344   }
    345   Passed = false;
    346   return false;
    347 }
    348
    349 bool trace_doesnt_contain(string expected) {
    350   vector<string> tmp = split_first(expected, ": ");
    351   if (SIZE(tmp) == 1) {
    352     raise << expected << ": missing label or contents in trace line\n" << end();
    353     assert(false);
    354   }
    355   return trace_count(tmp.at(0), tmp.at(1)) == 0;
    356 }
    357
    358 int trace_count(string label) {
    359   return trace_count(label, "");
    360 }
    361
    362 int trace_count(string label, string line) {
    363   if (!Trace_stream) return 0;
    364   long result = 0;
    365   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
    366     if (label == p->label) {
    367       if (line == "" || trim(line) == trim(p->contents))
    368         ++result;
    369     }
    370   }
    371   return result;
    372 }
    373
    374 int trace_count_prefix(string label, string prefix) {
    375   if (!Trace_stream) return 0;
    376   long result = 0;
    377   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
    378     if (label == p->label) {
    379       if (starts_with(trim(p->contents), trim(prefix)))
    380         ++result;
    381     }
    382   }
    383   return result;
    384 }
    385
    386 void split_label_contents(const string& s, string* label, string* contents) {
    387   static const string delim(": ");
    388   size_t pos = s.find(delim);
    389   if (pos == string::npos) {
    390     *label = "";
    391     *contents = trim(s);
    392   }
    393   else {
    394     *label = trim(s.substr(0, pos));
    395     *contents = trim(s.substr(pos+SIZE(delim)));
    396   }
    397 }
    398
    399 bool line_exists_anywhere(const string& label, const string& contents) {
    400   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
    401     if (label != p->label) continue;
    402     if (contents == trim(p->contents)) return true;
    403   }
    404   return false;
    405 }
    406
    407 vector<string> split(string s, string delim) {
    408   vector<string> result;
    409   size_t begin=0, end=s.find(delim);
    410   while (true) {
    411     if (end == string::npos) {
    412       result.push_back(string(s, begin, string::npos));
    413       break;
    414     }
    415     result.push_back(string(s, begin, end-begin));
    416     begin = end+SIZE(delim);
    417     end = s.find(delim, begin);
    418   }
    419   return result;
    420 }
    421
    422 vector<string> split_first(string s, string delim) {
    423   vector<string> result;
    424   size_t end=s.find(delim);
    425   result.push_back(string(s, 0, end));
    426   if (end != string::npos)
    427     result.push_back(string(s, end+SIZE(delim), string::npos));
    428   return result;
    429 }
    430
    431 //:: == Helpers for debugging using traces
    432
    433 :(before "End Includes")
    434 // To debug why a test is failing, dump its trace using '?'.
    435 #define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
    436
    437 // To add temporary prints to the trace, use 'dbg'.
    438 // `git log` should never show any calls to 'dbg'.
    439 #define dbg trace(0, "a")
    440
    441 //: Dump the entire trace to file where it can be browsed offline.
    442 //: Dump the trace as it happens; that way you get something even if the
    443 //: program crashes.
    444
    445 :(before "End Globals")
    446 ofstream Trace_file;
    447 :(before "End Commandline Options(*arg)")
    448 else if (is_equal(*arg, "--trace")) {
    449   cerr << "saving trace to 'last_run'\n";
    450   Trace_file.open("last_run");
    451   // Add a dummy line up top; otherwise the `browse_trace` tool currently has
    452   // no way to expand any lines above an error.
    453   Trace_file << "   0 dummy: start\n";
    454   // End --trace Settings
    455 }
    456 :(before "End trace Commit")
    457 if (Trace_file.is_open()) {
    458   dump_trace_line(Trace_file, t);
    459   Trace_file.flush();
    460   past_lines.pop_back();  // economize on memory
    461 }
    462 :(before "End One-time Setup")
    463 atexit(cleanup_main);
    464 :(code)
    465 void cleanup_main() {
    466   if (Trace_file.is_open()) Trace_file.close();
    467   // End cleanup_main
    468 }
    469
    470 :(before "End trace_stream Methods")
    471 string readable_contents(string label) {
    472   string trim(const string& s);  // prototype
    473   ostringstream output;
    474   label = trim(label);
    475   for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
    476     if (label.empty() || label == p->label)
    477       dump_trace_line(output, *p);
    478   return output.str();
    479 }
    480
    481 //: Print traces to the screen as they happen.
    482 //: Particularly useful when juggling multiple trace streams, like when
    483 //: debugging sandboxes.
    484 :(before "End Globals")
    485 bool Dump_trace = false;
    486 :(before "End Commandline Options(*arg)")
    487 else if (is_equal(*arg, "--dump")) {
    488   Dump_trace = true;
    489 }
    490 :(before "End Incremental Trace Print Conditions")
    491 if (Dump_trace) return true;
    492
    493 //: Miscellaneous helpers.
    494
    495 :(code)
    496 string trim(const string& s) {
    497   string::const_iterator first = s.begin();
    498   while (first != s.end() && isspace(*first))
    499     ++first;
    500   if (first == s.end()) return "";
    501
    502   string::const_iterator last = --s.end();
    503   while (last != s.begin() && isspace(*last))
    504     --last;
    505   ++last;
    506   return string(first, last);
    507 }
    508
    509 :(before "End Includes")
    510 #include <vector>
    511 using std::vector;
    512 #include <list>
    513 using std::list;
    514 #include <set>
    515 using std::set;
    516
    517 #include <sstream>
    518 using std::istringstream;
    519 using std::ostringstream;
    520
    521 #include <fstream>
    522 using std::ifstream;
    523 using std::ofstream;