https://github.com/akkartik/mu/blob/master/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(4) << 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 incrementally dump trace
189     trace_line& t = past_lines.back();
190     if (should_incrementally_print_trace()) {
191       dump_trace_line(cerr, t);
192     }
193     // Hack: on 'subx --trace --dump', emit only to stderr, not 'last_run'.
194     if (Dump_trace) past_lines.pop_back();  // economize on memory
195     // End trace Commit
196   }
197 
198   // clean up
199   delete curr_stream;
200   curr_stream = NULL;
201   curr_label.clear();
202   curr_depth = Max_depth;
203 }
204 
205 //:: == Initializing the trace in tests
206 
207 :(before "End Includes")
208 #define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
209 :(before "End Test Setup")
210 START_TRACING_UNTIL_END_OF_SCOPE
211 
212 //: Trace_stream is a resource, lease_tracer uses RAII to manage it.
213 :(before "End Types")
214 struct lease_tracer {
215   lease_tracer();
216   ~lease_tracer();
217 };
218 :(code)
219 lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
220 lease_tracer::~lease_tracer() {
221   delete Trace_stream;
222   Trace_stream = NULL;
223 }
224 
225 //:: == Errors and warnings using traces
226 
227 :(before "End Includes")
228 #define raise  (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
229 #define warn (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Warn_depth, "warn"))
230 
231 //: Print errors and warnings to the screen by default.
232 :(before "struct trace_stream")  // include constants in all cleaved compilation units
233 const int Error_depth = 0;
234 const int Warn_depth = 1;
235 :(before "End Globals")
236 int Hide_errors = false;  // if set, don't print errors or warnings to screen
237 int Hide_warnings = false;  // if set, don't print warnings to screen
238 :(before "End Reset")
239 Hide_errors = false;
240 Hide_warnings = false;
241 //: Never dump warnings in tests
242 :(before "End Test Setup")
243 Hide_warnings = true;
244 :(code)
245 bool trace_stream::should_incrementally_print_trace() {
246   if (!Hide_errors && curr_depth == Error_depth) return true;
247   if (!Hide_warnings && !Hide_errors && curr_depth == Warn_depth) return true;
248   // End Incremental Trace Print Conditions
249   return false;
250 }
251 :(before "End trace_stream Methods")
252 bool should_incrementally_print_trace();
253 
254 :(before "End Globals")
255 int Trace_errors = 0;  // used only when Trace_stream is NULL
256 
257 // Fail tests that displayed (unexpected) errors.
258 // Expected errors should always be hidden and silently checked for.
259 :(before "End Test Teardown")
260 if (Passed && !Hide_errors && trace_contains_errors()) {
261   Passed = false;
262 }
263 :(code)
264 bool trace_contains_errors() {
265   return Trace_errors > 0 || trace_count("error") > 0;
266 }
267 
268 :(before "End Includes")
269 // If we aren't yet sure how to deal with some corner case, use assert_for_now
270 // to indicate that it isn't an inviolable invariant.
271 #define assert_for_now assert
272 #define raise_for_now raise
273 
274 //:: == Other assertions on traces
275 //: Primitives:
276 //:   - CHECK_TRACE_CONTENTS(lines)
277 //:     Assert that the trace contains the given lines (separated by newlines)
278 //:     in order. There can be other intervening lines between them.
279 //:   - CHECK_TRACE_DOESNT_CONTAIN(line)
280 //:   - CHECK_TRACE_DOESNT_CONTAIN(label, contents)
281 //:     Assert that the trace doesn't contain the given (single) line.
282 //:   - CHECK_TRACE_COUNT(label, count)
283 //:     Assert that the trace contains exactly 'count' lines with the given
284 //:     'label'.
285 //:   - CHECK_TRACE_CONTAINS_ERRORS()
286 //:   - CHECK_TRACE_DOESNT_CONTAIN_ERRORS()
287 //:   - trace_count_prefix(label, prefix)
288 //:     Count the number of trace lines with the given 'label' that start with
289 //:     the given 'prefix'.
290 
291 :(before "End Includes")
292 #define CHECK_TRACE_CONTENTS(...)  check_trace_contents(__FUNCTION__, __FILE__, __LINE__, __VA_ARGS__)
293 
294 #define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
295 
296 #define CHECK_TRACE_COUNT(label, count) \
297   if (Passed && trace_count(label) != (count)) { \
298     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): trace_count of " << label << " should be " << count << '\n'; \
299     cerr << "  got " << trace_count(label) << '\n';  /* multiple eval */ \
300     DUMP(label); \
301     Passed = false; \
302     return;  /* Currently we stop at the very first failure. */ \
303   }
304 
305 #define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
306 #define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
307   if (Passed && trace_contains_errors()) { \
308     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
309     DUMP("error"); \
310     Passed = false; \
311     return; \
312   }
313 
314 // Allow tests to ignore trace lines generated during setup.
315 #define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream
316 
317 :(code)
318 bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expected) {
319   if (!Passed) return false;
320   if (!Trace_stream) return false;
321   vector<string> expected_lines = split(expected, "\n");
322   int curr_expected_line = 0;
323   while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
324     ++curr_expected_line;
325   if (curr_expected_line == SIZE(expected_lines)) return true;
326   string label, contents;
327   split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
328   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
329     if (label != p->label) continue;
330     string t = trim(p->contents);
331     if (contents != unescape_newline(t)) continue;
332     ++curr_expected_line;
333     while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
334       ++curr_expected_line;
335     if (curr_expected_line == SIZE(expected_lines)) return true;
336     split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
337   }
338 
339   if (line_exists_anywhere(label, contents)) {
340     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): line [" << label << ": " << contents << "] out of order in trace:\n";
341     DUMP("");
342   }
343   else {
344     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): missing [" << contents << "] in trace:\n";
345     DUMP(label);
346   }
347   Passed = false;
348   return false;
349 }
350 
351 bool trace_doesnt_contain(string expected) {
352   vector<string> tmp = split_first(expected, ": ");
353   if (SIZE(tmp) == 1) {
354     raise << expected << ": missing label or contents in trace line\n" << end();
355     assert(false);
356   }
357   return trace_count(tmp.at(0), tmp.at(1)) == 0;
358 }
359 
360 int trace_count(string label) {
361   return trace_count(label, "");
362 }
363 
364 int trace_count(string label, string line) {
365   if (!Trace_stream) return 0;
366   long result = 0;
367   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
368     if (label == p->label) {
369       if (line == "" || trim(line) == trim(p->contents))
370         ++result;
371     }
372   }
373   return result;
374 }
375 
376 int trace_count_prefix(string label, string prefix) {
377   if (!Trace_stream) return 0;
378   long result = 0;
379   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
380     if (label == p->label) {
381       if (starts_with(trim(p->contents), trim(prefix)))
382         ++result;
383     }
384   }
385   return result;
386 }
387 
388 void split_label_contents(const string& s, string* label, string* contents) {
389   static const string delim(": ");
390   size_t pos = s.find(delim);
391   if (pos == string::npos) {
392     *label = "";
393     *contents = trim(s);
394   }
395   else {
396     *label = trim(s.substr(0, pos));
397     *contents = trim(s.substr(pos+SIZE(delim)));
398   }
399 }
400 
401 bool line_exists_anywhere(const string& label, const string& contents) {
402   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
403     if (label != p->label) continue;
404     if (contents == trim(p->contents)) return true;
405   }
406   return false;
407 }
408 
409 vector<string> split(string s, string delim) {
410   vector<string> result;
411   size_t begin=0, end=s.find(delim);
412   while (true) {
413     if (end == string::npos) {
414       result.push_back(string(s, begin, string::npos));
415       break;
416     }
417     result.push_back(string(s, begin, end-begin));
418     begin = end+SIZE(delim);
419     end = s.find(delim, begin);
420   }
421   return result;
422 }
423 
424 vector<string> split_first(string s, string delim) {
425   vector<string> result;
426   size_t end=s.find(delim);
427   result.push_back(string(s, 0, end));
428   if (end != string::npos)
429     result.push_back(string(s, end+SIZE(delim), string::npos));
430   return result;
431 }
432 
433 //:: == Helpers for debugging using traces
434 
435 :(before "End Includes")
436 // To debug why a test is failing, dump its trace using '?'.
437 #define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
438 
439 // To add temporary prints to the trace, use 'dbg'.
440 // `git log` should never show any calls to 'dbg'.
441 #define dbg trace(0, "a")
442 
443 //: Dump the entire trace to file where it can be browsed offline.
444 //: Dump the trace as it happens; that way you get something even if the
445 //: program crashes.
446 
447 :(before "End Globals")
448 ofstream Trace_file;
449 :(before "End Commandline Options(*arg)")
450 else if (is_equal(*arg, "--trace")) {
451   cerr << "saving trace to 'last_run'\n";
452   Trace_file.open("last_run");
453   // Add a dummy line up top; otherwise the `browse_trace` tool currently has
454   // no way to expand any lines above an error.
455   Trace_file << "   0 dummy: start\n";
456 }
457 :(before "End trace Commit")
458 if (Trace_file) {
459   dump_trace_line(Trace_file, t);
460 }
461 :(before "End One-time Setup")
462 atexit(cleanup_main);
463 :(code)
464 void cleanup_main() {
465   if (Trace_file) Trace_file.close();
466   // End cleanup_main
467 }
468 
469 :(before "End trace_stream Methods")
470 string readable_contents(string label) {
471   string trim(const string& s);  // prototype
472   ostringstream output;
473   label = trim(label);
474   for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
475     if (label.empty() || label == p->label)
476       dump_trace_line(output, *p);
477   return output.str();
478 }
479 
480 //: Print traces to the screen as they happen.
481 //: Particularly useful when juggling multiple trace streams, like when
482 //: debugging sandboxes.
483 :(before "End Globals")
484 bool Dump_trace = false;
485 :(before "End Commandline Options(*arg)")
486 else if (is_equal(*arg, "--dump")) {
487   Dump_trace = true;
488 }
489 :(before "End Incremental Trace Print Conditions")
490 if (Dump_trace) return true;
491 
492 //: Miscellaneous helpers.
493 
494 :(code)
495 string trim(const string& s) {
496   string::const_iterator first = s.begin();
497   while (first != s.end() && isspace(*first))
498     ++first;
499   if (first == s.end()) return "";
500 
501   string::const_iterator last = --s.end();
502   while (last != s.begin() && isspace(*last))
503     --last;
504   ++last;
505   return string(first, last);
506 }
507 
508 :(before "End Includes")
509 #include <vector>
510 using std::vector;
511 #include <list>
512 using std::list;
513 #include <set>
514 using std::set;
515 
516 #include <sstream>
517 using std::istringstream;
518 using std::ostringstream;
519 
520 #include <fstream>
521 using std::ifstream;
522 using std::ofstream;