Diagnostic Differential Logging with JavaScript Example

Synopsis
Reducing the quantity of information to what is essential is very important in maintaining complex software. Modern development environments have debuggers and other tools to assist in this effort: conditional breakpoints, watch expressions, logging, stop on change techniques, and so forth.
As a supplementary technique an approach to debugging is shown which uses the dynamic differences in a running system to output a reduced level of information. A simple programmatic implementation is shown in a JavaScript scenario, but the technique is applicable using other languages and automated techniques.

KEYWORDS: logging, diff, debugging, diagnostics, BIST, JavaScript, AOP, BIST

Context
Recently I was debugging a legacy JavaScript program. I used the outstanding FireBug plug-in in the FireFox browser. By the way, FireBug is truly indispensible, such a wealth of features and it is FOSS. Now combine that with Selenium which gives you the ability automate the browser and you have a powerful Integrated Development Environment (IDE). All that could be lacking is time and skill.
Unfortunately, I was not finding the problem. Later at home I got an idea. What if I could simply log what changed? That way I could more clearly see how the program behaves. All programs are just obfuscated state machines. Through a use-case or scenario, state variables are being manipulated and non-state data is being changed. Correlating these two with the events that drive the system, is a prime aspect of debugging.

Forces
• You want to log what is happening in a system, but you don’t want to be inundated with non-useful data.
• You or someone else want to be able to quickly resume this investigation in another situation or project.
• By saving ‘interests’, a Built-in-self-test aid can be implemented.
• During development hooks can be put in place to provide differential logging.
• You want to capture the live system not a system which is controlled by a debugger.
• You cannot install new systems, tools, or frameworks to help.
• Breakpoints will break as the system is maintained.

Solution
My solution was to dynamically log the differences. I’m sure this is not new. However, it probably is not explicitly discussed. The usual approach is to log as much as possible, but since this is prohibitive, instead the logging is limited, level filters, and contexts are used to control the output. Breakpoints and watches while usually enough to do the job are in the long term brittle since the target program may change during the dev and debug process. Thus, dynamic difference reporting would be a better approach in this situation.

Consequences
Todo.

Implementation
There are a few implementation choices.

API
One is to declare the data of interest. Then the logging system will track these and only output anything when there is a change in any of the data. With this approach the logger must be triggered either manually or automated. Manually is very easy; at an event change or at enter and exit points of a module or function, the differential logger is invoked.

Automated
To avoid changing the source code (it may not even be available), AOP could be used to implement the above. For example, an Around advise can be used to differentially trace the changes in methods.

Framework Plugin
If the system under test is running as part of a debug or is instrumented, it may already have a facility to capture change events. For example, FireBug, the FireFox plugin has this and the FireBug plug-in, FireDiff, implements a change monitor and visualization output. There may be or should be a comparable plug-in for other systems like the Eclipse IDE.

Code Example
To illustrate this concept it is used to debug a web page’s DOM changes via JavaScript. The page has a button that when clicked will randomly change two input field’s content. Notice that when the change involves just an ordering of two adjacent characters in a field, it is not readily apparent. The Differential logging makes it explicit. The log output is just the result object converted to JSON. An example: {“event”:”run”,”record”:{“foo2”:[“”,”accd”],”foo4″:[“”,”ollrr”]}}. A real implementation would do otherwise.

To specify which DOM nodes to monitor, a JavaScript object is used:

{"foo2":{"get":"v"},"foo4":{"get":"v"}};

The “get” field is used to specify how to get the value from the browser DOM. Another method would be “innerHTML” access. A better approach is to detect the appropriate ‘getter’ via using the node type.

demo screen capture

Listing 1, implementation


/**
 * 
 * Differ constructor.
 * 
 * @param data which nodes to record
 * @param formatter how to show results
 * @returns
 */
function Differ(data, formatter){
	this.data = data;
	this.formatter = formatter;
	
	if(!formatter){
		this.formatter =this.format;
	}
};

/**
 * Data and methods of class.
 * 
 */
Differ.prototype = {
  MAXSIZE : 15,
	
  /**
   * Detect changes and save latest.
   * 
   * @param event Where was diff created
   * @returns result object
   */
  diff : function(event){
    var results = {};
		
    if(!data){
    	return results;
    }
		
    if(event){
    	results = {"event":event};
    }
		
    results["record"] = {};
		
    var record = results["record"];
		
    for(var key in data){			
      var ref = document.getElementById(key);			
      var domValue = "";			
			
      switch (data[key].get) {
        case "v":
          domValue = ref ? this.shorten(ref.value) : "";
          break;
        }
			
        var prior = data[key].value ? data[key].value : "";
			
        if((domValue != prior)){
          record[key] = [prior, domValue];
          data[key].value = domValue;
        }
    } // end for	
		
    return results;
		
  }, 

  /**
   * Convert results to message.
   * 
   * @param results object
   * @returns JSON
   */
  toMessage : function(results){
    var obj = results;
    if(!results){
      obj ={"error":"results is undefined or null"};
    }		
		
    return this.format(JSON.stringify(obj));
  },
	
  /**
   * Get size of an object
   * @param obj
   * @returns {Number}
   */
  size : function(obj){
    var len = 0;
    for(var key in obj){
      if(obj.hasOwnProperty(key)){
        len++;
      }
    }
		
    return len;
  },
	
  /**
   * Limit size of value.
   * 
   * @param value
   * @returns
   */
  shorten : function(value){
    return (value.length > this.MAXSIZE) ? 
	value.substring(0,this.MAXSIZE-1):value;		
  },
	
  /**
   * Make message human readable.
   * 
   * @param message
   */
  format : function(str){
  	return str + '<br/>';
  }	
	
};	

Listing 2, Demo script

var data = {
  "foo2" : {
    "get" : "v"
   },
  "foo4" : {
    "get" : "v"
   }
};

var differ = new Differ(data);
differ.diff(); // prime values

function runIt() {
  var ref2 = document.getElementById('foo2');
  var ref4 = document.getElementById('foo4');
	
  if(Math.floor(Math.random()*101) > 60){
    swapInputs(ref2,ref4);
  }else{
    scramble(ref2,ref4);
  }

  var msg = differ.toMessage(differ.diff("run"));
  document.getElementById('output').innerHTML += msg;
  document.getElementById('output').innerHTML += 
    Array(60).join("-") + "<br/>";
}

function scramble(ref2, ref4){
  var ch = ref2.value.charAt(1);
  var r2v = ref2.value;
  ref2.value = replaceChar(r2v, 2, ch);
  ref4.value = replaceChar(ref4.value, 2, ref4.value.
    charAt(1));
}

function swapInputs(ref2,ref4){
  var temp = ref2.value;
  ref2.value = ref4.value;
  ref4.value = temp;	
}

function replaceChar(str, ndx, v) {
  return str.substr(0, ndx) + v + 
    str.substr(ndx + v.length);
}

Listing 3, the demo web page

<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" 
    "http://www.w3.org/TR/html4/loose.dtd">
<html>
<head>
  <meta http-equiv="Content-Type" content="text/html; 
    charset=iso-8859-1">
  <link rel="stylesheet" type="text/css" href="style.css" />	
  <script type="text/javascript" src="DebugUtils.js"></script>	
  <script type="text/javascript" src="DemoDiff.js"></script>	
</head>
<body>
  <span class="mytitle">Differential Logging Example</span>
  <div style="width:600px;">
	<div class="box inputBox">		
		1: <input type="text" id="foo1" value="xyyz"/>
		2: <input type="text" id="foo2" value="acbd"/><br/>
		3: <input type="text" id="foo3" value="wzlm"/>
		4: <input type="text" id="foo4" value="olxrr"/>

          <span class="buttonClass">
	    <input type="button" id="run" value="Test" 
               onclick="runIt()"/>
	  </span>		
	</div>
	Output
	<div id="output" class="box inputBox"></div>
	<span style="float:right;margin-right:10em;font-size:xx-small;">
           &copy; Josef Betancourt</span>		
	</div>
</body>
</html>

Listing 3, css

body {
  background-color:#E6E6E6;margin:3em 8em 12em 3em;
}	
.box{
  border: 3px solid #D4D4D4;padding:8px;
  padding:2em 1em 2em;margin:10px 5px 20px;
}
.inputBox{
   background-color:Beige;margin-right:36px;
   width:475px;font-family:monospace;
}
.buttonClass{
    float:right;margin-left:1em;margin-right:3em;
}
.mytitle{
   text-decoration:underline;font-weight:bold;
}

Related Patterns
None.

Related Intellectual Property
None.

Further Reading

Debuggers are for Losers

Similar Posts:

Creative Commons License
This work is licensed under a Creative Commons Attribution-NonCommercial-NoDerivs 3.0 Unported License.

One thought on “Diagnostic Differential Logging with JavaScript Example”

Leave a Reply

Your email address will not be published. Required fields are marked *