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