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* testing.
 17 //: We focus on the domain of inputs the whole program needs to handle rather
 18 //: than the correctness of individual functions. All tests invoke the program
 19 //: in a single way: by calling run() with some input. As the program operates
 20 //: on the input, it traces out a list of _facts_ deduced about the domain:
 21 //:   trace("label") << "fact 1: " << val;
 22 //:
 23 //: Tests can now check these facts:
 24 //:   :(scenario foo)
 25 //:   34  # call run() with this input
 26 //:   +label: fact 1: 34  # 'run' should have deduced this fact
 27 //:   -label: fact 1: 35  # the trace should not contain such a fact
 28 //:
 29 //: Since we never call anything but the run() function directly, we never have
 30 //: to rewrite the tests when we reorganize the internals of the program. We
 31 //: just have to make sure our rewrite deduces the same facts about the domain,
 32 //: and that's something we're going to have to do anyway.
 33 //:
 34 //: To avoid the combinatorial explosion of integration tests, each layer
 35 //: mainly logs facts to the trace with a common *label*. All tests in a layer
 36 //: tend to check facts with this label. Validating the facts logged with a
 37 //: specific label is like calling functions of that layer directly.
 38 //:
 39 //: To build robust tests, trace facts about your domain rather than details of
 40 //: how you computed them.
 41 //:
 42 //: More details: http://akkartik.name/blog/tracing-tests
 43 //:
 44 //: ---
 45 //:
 46 //: Between layers and domain-driven testing, programming starts to look like a
 47 //: fundamentally different activity. Instead of a) superficial, b) local rules
 48 //: on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
 49 //: we allow programmers to engage with the a) deep, b) global structure of the
 50 //: c) domain. If you can systematically track discontinuities in the domain,
 51 //: you don't care if the code used gotos as long as it passed the tests. If
 52 //: tests become more robust to run it becomes easier to try out radically
 53 //: different implementations for the same program. If code is super-easy to
 54 //: rewrite, it becomes less important what indentation style it uses, or that
 55 //: the objects are appropriately encapsulated, or that the functions are
 56 //: referentially transparent.
 57 //:
 58 //: Instead of plumbing, programming becomes building and gradually refining a
 59 //: map of the environment the program must operate under. Whether a program is
 60 //: 'correct' at a given point in time is a red herring; what matters is
 61 //: avoiding regression by monotonically nailing down the more 'eventful' parts
 62 //: of the terrain. It helps readers new and old, and rewards curiosity, to
 63 //: organize large programs in self-similar hierarchies of example scenarios
 64 //: colocated with the code that makes them work.
 65 //:
 66 //:   "Programming properly should be regarded as an activity by which
 67 //:   programmers form a mental model, rather than as production of a program."
 68 //:   -- Peter Naur (http://alistair.cockburn.us/ASD+book+extract%3A+%22Naur,+Ehn,+Musashi%22)
 69 
 70 :(before "End Types")
 71 struct trace_line {
 72   int depth;  // optional field just to help browse traces later
 73   string label;
 74   string contents;
 75   trace_line(string l, string c) :depth(0), label(l), contents(c) {}
 76   trace_line(int d, string l, string c) :depth(d), label(l), contents(c) {}
 77 };
 78 
 79 //: Support for tracing an entire run.
 80 //: Traces can have a lot of overhead, so only turn them on when asked.
 81 :(before "End Commandline Options(*arg)")
 82 else if (is_equal(*arg, "--trace")) {
 83   Save_trace = true;
 84 }
 85 :(before "End Commandline Parsing")
 86 if (Save_trace) {
 87   cerr << "initializing trace\n";
 88   Trace_stream = new trace_stream;
 89 }
 90 :(code)
 91 void cleanup_main() {
 92   if (!Trace_stream) return;
 93   if (Save_trace)
 94     Trace_stream->save();
 95   delete Trace_stream;
 96   Trace_stream = NULL;
 97 }
 98 :(before "End One-time Setup")
 99 atexit(cleanup_main);
100 
101 :(before "End Types")
102 // Pre-define some global constants that trace_stream needs to know about.
103 // Since they're in the Types section, they'll be included in any cleaved
104 // compilation units. So no extern linkage.
105 const int Max_depth = 9999;
106 const int Error_depth = 0;  // definitely always print errors
107 const int App_depth = 2;  // temporarily where all Mu code will trace to
108 
109 struct trace_stream {
110   vector<trace_line> past_lines;
111   // accumulator for current line
112   ostringstream* curr_stream;
113   string curr_label;
114   int curr_depth;
115   int callstack_depth;
116   int collect_depth;
117   ofstream null_stream;  // never opens a file, so writes silently fail
118   trace_stream() :curr_stream(NULL), curr_depth(Max_depth), callstack_depth(0), collect_depth(Max_depth) {}
119   ~trace_stream() { if (curr_stream) delete curr_stream; }
120 
121   ostream& stream(string label) {
122     return stream(Max_depth, label);
123   }
124 
125   ostream& stream(int depth, string label) {
126     if (depth > collect_depth) return null_stream;
127     curr_stream = new ostringstream;
128     curr_label = label;
129     curr_depth = depth;
130     return *curr_stream;
131   }
132 
133   void save() {
134     cerr << "saving trace to 'last_run'\n";
135     ofstream fout("last_run");
136     fout << readable_contents("");
137     fout.close();
138   }
139 
140   // be sure to call this before messing with curr_stream or curr_label
141   void newline();
142   // useful for debugging
143   string readable_contents(string label);  // empty label = show everything
144 };
145 
146 :(code)
147 void trace_stream::newline() {
148   if (!curr_stream) return;
149   string curr_contents = curr_stream->str();
150   if (!curr_contents.empty()) {
151     past_lines.push_back(trace_line(curr_depth, trim(curr_label), curr_contents));  // preserve indent in contents
152     if ((!Hide_errors && curr_label == "error")
153         || Dump_trace
154         || (!Dump_label.empty() && curr_label == Dump_label))
155       cerr << curr_label << ": " << curr_contents << '\n';
156   }
157   delete curr_stream;
158   curr_stream = NULL;
159   curr_label.clear();
160   curr_depth = Max_depth;
161 }
162 
163 string trace_stream::readable_contents(string label) {
164   ostringstream output;
165   label = trim(label);
166   for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
167     if (label.empty() || label == p->label)
168       output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
169   return output.str();
170 }
171 
172 :(before "End Globals")
173 trace_stream* Trace_stream = NULL;
174 int Trace_errors = 0;  // used only when Trace_stream is NULL
175 
176 :(before "End Globals")
177 bool Hide_errors = false;  // if set, don't print even error trace lines to screen
178 bool Dump_trace = false;  // if set, print trace lines to screen
179 string Dump_label = "";  // if set, print trace lines matching a single label to screen
180 :(before "End Reset")
181 Hide_errors = false;
182 Dump_trace = false;  // toggle this to print traces to screen as they are emitted
183 Dump_label = "";
184 
185 :(before "End Includes")
186 #define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream;
187 
188 // Top-level helper. IMPORTANT: can't nest
189 #define trace(...)  !Trace_stream ? cerr /*print nothing*/ : Trace_stream->stream(__VA_ARGS__)
190 
191 // Just for debugging; 'git log' should never show any calls to 'dbg'.
192 #define dbg trace(0, "a")
193 #define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
194 
195 // Errors are a special layer.
196 #define raise  (!Trace_stream ? (scroll_to_bottom_and_close_console(),++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
197 // If we aren't yet sure how to deal with some corner case, use assert_for_now
198 // to indicate that it isn't an inviolable invariant.
199 #define assert_for_now assert
200 
201 //: Automatically close the console in some situations.
202 :(before "End One-time Setup")
203 atexit(scroll_to_bottom_and_close_console);
204 :(code)
205 void scroll_to_bottom_and_close_console() {
206   if (!tb_is_active()) return;
207   // leave the screen in a relatively clean state
208   tb_set_cursor(tb_width()-1, tb_height()-1);
209   cout << "\r\n";
210   tb_shutdown();
211 }
212 
213 // Inside tests, fail any tests that displayed (unexpected) errors.
214 // Expected errors in tests should always be hidden and silently checked for.
215 :(before "End Test Teardown")
216 if (Passed && !Hide_errors && trace_contains_errors()) {
217   Passed = false;
218 }
219 :(code)
220 bool trace_contains_errors() {
221   return Trace_errors > 0 || trace_count("error") > 0;
222 }
223 
224 :(before "End Types")
225 struct end {};
226 :(code)
227 ostream& operator<<(ostream& os, end /*unused*/) {
228   if (Trace_stream) Trace_stream->newline();
229   return os;
230 }
231 
232 :(before "End Globals")
233 bool Save_trace = false;  // if set, write out trace to disk
234 
235 // Trace_stream is a resource, lease_tracer uses RAII to manage it.
236 :(before "End Types")
237 struct lease_tracer {
238   lease_tracer();
239   ~lease_tracer();
240 };
241 :(code)
242 lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
243 lease_tracer::~lease_tracer() {
244   if (Save_trace) Trace_stream->save();
245   delete Trace_stream, Trace_stream = NULL;
246 }
247 :(before "End Includes")
248 #define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
249 :(before "End Test Setup")
250 START_TRACING_UNTIL_END_OF_SCOPE
251 
252 :(before "End Includes")
253 #define CHECK_TRACE_CONTENTS(...)  check_trace_contents(__FUNCTION__, __FILE__, __LINE__, __VA_ARGS__)
254 
255 #define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
256 #define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
257   if (Passed && trace_contains_errors()) { \
258     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
259     DUMP("error"); \
260     Passed = false; \
261     return; \
262   }
263 
264 #define CHECK_TRACE_COUNT(label, count) \
265   if (Passed && trace_count(label) != (count)) { \
266     cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): trace_count of " << label << " should be " << count << '\n'; \
267     cerr << "  got " << trace_count(label) << '\n';  /* multiple eval */ \
268     DUMP(label); \
269     Passed = false; \
270     return;  /* Currently we stop at the very first failure. */ \
271   }
272 
273 #define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
274 
275 :(code)
276 bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expected) {
277   if (!Passed) return false;
278   if (!Trace_stream) return false;
279   vector<string> expected_lines = split(expected, "^D");
280   int curr_expected_line = 0;
281   while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
282     ++curr_expected_line;
283   if (curr_expected_line == SIZE(expected_lines)) return true;
284   string label, contents;
285   split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
286   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
287     if (label != p->label) continue;
288     if (contents != trim(p->contents)) continue;
289     ++curr_expected_line;
290     while (curr_expected_line < SIZE(expected_lines) && expected_lines.at(curr_expected_line).empty())
291       ++curr_expected_line;
292     if (curr_expected_line == SIZE(expected_lines)) return true;
293     split_label_contents(expected_lines.at(curr_expected_line), &label, &contents);
294   }
295 
296   if (line_exists_anywhere(label, contents)) {
297     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): line [" << label << ": " << contents << "] out of order in trace:\n";
298     DUMP("");
299   }
300   else {
301     cerr << "\nF - " << FUNCTION << "(" << FILE << ":" << LINE << "): missing [" << contents << "] in trace:\n";
302     DUMP(label);
303   }
304   Passed = false;
305   return false;
306 }
307 
308 void split_label_contents(const string& s, string* label, string* contents) {
309   static const string delim(": ");
310   size_t pos = s.find(delim);
311   if (pos == string::npos) {
312     *label = "";
313     *contents = trim(s);
314   }
315   else {
316     *label = trim(s.substr(0, pos));
317     *contents = trim(s.substr(pos+SIZE(delim)));
318   }
319 }
320 
321 bool line_exists_anywhere(const string& label, const string& contents) {
322   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
323     if (label != p->label) continue;
324     if (contents == trim(p->contents)) return true;
325   }
326   return false;
327 }
328 
329 int trace_count(string label) {
330   return trace_count(label, "");
331 }
332 
333 int trace_count(string label, string line) {
334   if (!Trace_stream) return 0;
335   long result = 0;
336   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
337     if (label == p->label) {
338       if (line == "" || trim(line) == trim(p->contents))
339         ++result;
340     }
341   }
342   return result;
343 }
344 
345 int trace_count_prefix(string label, string prefix) {
346   if (!Trace_stream) return 0;
347   long result = 0;
348   for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
349     if (label == p->label) {
350       if (starts_with(trim(p->contents), trim(prefix)))
351         ++result;
352     }
353   }
354   return result;
355 }
356 
357 bool trace_doesnt_contain(string label, string line) {
358   return trace_count(label, line) == 0;
359 }
360 
361 bool trace_doesnt_contain(string expected) {
362   vector<string> tmp = split_first(expected, ": ");
363   if (SIZE(tmp) == 1) {
364     raise << expected << ": missing label or contents in trace line\n" << end();
365     assert(false);
366   }
367   return trace_doesnt_contain(tmp.at(0), tmp.at(1));
368 }
369 
370 vector<string> split(string s, string delim) {
371   vector<string> result;
372   size_t begin=0, end=s.find(delim);
373   while (true) {
374     if (end == string::npos) {
375       result.push_back(string(s, begin, string::npos));
376       break;
377     }
378     result.push_back(string(s, begin, end-begin));
379     begin = end+SIZE(delim);
380     end = s.find(delim, begin);
381   }
382   return result;
383 }
384 
385 vector<string> split_first(string s, string delim) {
386   vector<string> result;
387   size_t end=s.find(delim);
388   result.push_back(string(s, 0, end));
389   if (end != string::npos)
390     result.push_back(string(s, end+SIZE(delim), string::npos));
391   return result;
392 }
393 
394 string trim(const string& s) {
395   string::const_iterator first = s.begin();
396   while (first != s.end() && isspace(*first))
397     ++first;
398   if (first == s.end()) return "";
399 
400   string::const_iterator last = --s.end();
401   while (last != s.begin() && isspace(*last))
402     --last;
403   ++last;
404   return string(first, last);
405 }
406 
407 :(before "End Includes")
408 #include <vector>
409 using std::vector;
410 #include <list>
411 using std::list;
412 #include <set>
413 using std::set;
414 
415 #include <sstream>
416 using std::istringstream;
417 using std::ostringstream;
418 
419 #include <fstream>
420 using std::ifstream;
421 using std::ofstream;
422 
423 #include "termbox/termbox.h"
424 
425 :(before "End Globals")
426 //: In future layers we'll use the depth field as follows:
427 //:
428 //: Errors will be depth 0.
429 //: Mu 'applications' will be able to use depths 1-100 as they like.
430 //: Primitive statements will occupy 101-9989
431 extern const int Initial_callstack_depth = 101;
432 extern const int Max_callstack_depth = 9989;
433 //: Finally, details of primitive Mu statements will occupy depth 9990-9999
434 //: (more on that later as well)
435 //:
436 //: This framework should help us hide some details at each level, mixing
437 //: static ideas like layers with the dynamic notion of call-stack depth.