Saturday, January 14, 2017

Tracing Tests

Having read an interesting blog article by Kartik Agaram about using traces for testing, I decided to add this capability to c-libutl.

On top of the existing logging functions:

  • logerror() for messages that report about critical failures;
  • logwarning() for messages that report about potential issues (but are not real errors);
  • loginfo() for messages about the status of the program (e.g. for auditing purposes);
  • logdebug() for debugging messages;
  • logtrace() for detailed traces of program executions (for debugging or to better understanding of software internals);
and the checking functions:
  • logcheck() for checking a boolean condition;
  • logexpect() for checking and print a failure notice;
  • logassert() for checking and aborting on failure;

I've intrduced a logwatch() statement that will check whether a specific string appears or not in the log file:

       62:  logopen("mylog.log","w");
       63:  for (k=0; k &lt NUM_VALVES; k++) {
       64:    logwatch ("[open]","[closed]","![failed]") {
       65:      vlv = opennextvalve();
       65:      if (vlv ! NULL) {
       66:        loginfo("The valve %d is [open]",vlv);
       67:        flowthrough(vlv);
       68:      ]
       69:      else logerror("Valve [failed] to open at step %d",k);
       70:      if (closevalve(vlv))
       71:        loginfo("Valve %d is now [closed]",vlv);
       72:      else 
       73:        logerror("Valve %d [failed] to close",vlv);
       74:    }
       75:  }
       75:  logclose();
In the example above, we are checking that, within the logwatch() scope, the strings "[open]" and "[closed]" appear in the log at least once. We are also checking that the string "[failed]" does not appear at all.

Say that everything goes well, the log file will look like this:
       ...     
       2017-01-10 21:47:25 WCH START  :mytest.c:64 
       2017-01-10 21:47:25 INF The valve 321 is [open]  :mytest.c:66 
       2017-01-10 21:47:25 CHK PASS ([open])?  :mytest.c:66 
       2017-01-10 21:47:25 INF Valve 321 is now [closed] :mytest.c:71 
       2017-01-10 21:47:25 CHK PASS ([closed])?  :mytest.c:71 
       2017-01-10 21:47:25 CHK PASS (![failed])? :mytest.c:64 
       2017-01-10 21:47:25 WCH START  :mytest.c:64 
       ...
       2017-01-10 21:47:25 CHK #KO: 0 (of 12)
       2017-01-10 21:47:25 LOG STOP
The string "[failed]" is expected not to appear being preceeded, in the logwatch(), by the character '!'.
In our example if a valve can't be closed, we'll have a log like:
       ...     
       2017-01-10 21:47:25 WCH START  :mytest.c:64 
       2017-01-10 21:47:25 INF The valve 321 is [open]  :mytest.c:66 
       2017-01-10 21:47:25 CHK PASS ([open])?  :mytest.c:66 
       2017-01-10 21:47:25 ERR Valve 321 [failed] to close :mytest.c:73 
       2017-01-10 21:47:25 CHK FAIL (![failed])? :mytest.c:73 
       2017-01-10 21:47:25 CHK FAIL ([closed])?  :mytest.c:64 
       2017-01-10 21:47:25 WCH STOP  :mytest.c:64 
       ...
       2017-01-10 21:47:25 CHK #KO: 2 (of 12)
       2017-01-10 21:47:25 LOG STOP
and we'll get two failed checks: one for the unexpected presence of the string "[failed]" and one for the lack of the string "[closed]" in the log.

*   *   *   *

This mechanism is made very flexibile by the fact that the strings to specify are, actually, patterns that follow the pmx syntax specified here. I'll write soon a post on pmx, the c-libutl pattern matching expressions, for more details.

As Kartik pointed out in his post, writing unit tests based based on traces can prove itself more effective than the usual approach of directly checking the functions return value (or the variables value). The need to restructure tests should decrease as traces would contain informaton about high-level events whereas variables and functions could change for
Since the events reported in the log files are at an higher level of abstraction, they are more resilient to changes in the code. The drawback is that this is an indirect test and that it may be difficult to ensure that the result is indeed what one expects.

In the end, I believe this is a very useful tool that could help in writing robust and effective unit tests and I hope you'll find it useful too.

0 comments :

Post a Comment