AJS_Logger User-Guide

AJS_Logger supports the concept of 'streams', where a stream is an object to which you pass information that it writes out to a 'log', and where the term 'log' is used here in the abstract sense of an 'output channel', meaning, for example, an on-screen window or a file. Streams in AJS_Logger are exactly the same concept as in, say, languages like C++, where you write to an 'ostream' object using 'cout'.

In the examples used so far in this guide, createLogger creates logger objects that possess a default stream. This is a very simple object that simply concatenates the method-name in question with the string ' Entry' or ' Exit' (note the leading spaces), and then uses the log method of the console object to write that concatenation out to the console window. However, you can change this behaviour by coercing a given logger to use a stream that you provide at the time of that logger's creation.

Streams give us the flexibility to separate the objects to which we apply logging from the way that logging data is generated for the methods of those objects, and this is of value where you wish to customise the information that a given logger generates. Moreover, as explored below, it also allows you to deploy an application with logging in place in order to study its behaviour in the wild.

A stream object must support two methods called onMethodEntry and onMethodExit, which are called respectively when a logged method is invoked and when the thread of execution returns. onMethodEntry must accept an argument that represents the name of the method that has been called, and a second argument representing the arguments array that the JS run-time passes implicitly when a method is called.

Similarly, onMethodExit must also accept a MethodName argument, and a second argument that represents the arguments array that was passed on invocation, and a third argument, which is the value or reference the the method returned (and which will have a value of undefined if the method returned nothing).

Note that the arguments array is passed to onMethodExit as well as onMethodEntry in order to permit before-and-after comparisons, and that the first two arguments are identical for onMethodEntry and onMethodExit in order to permit the use of the same function for logging both entry-to and exit-from a given method.

Example 9 shows the composition of a stream object.

Building on this, you can create a 'buffering stream', where logging data is stored rather than being written immediately to some form of output. The value here is that, for example, this allows statistical analysis of the data, before anything is written to the log.

Example 10 shows an implementation of a simple buffering-stream. Here the code creates a stream object, by self-execution of an anonymous function. This creates a closure within which is held a message buffer; a simple string. This stream is then passed in a call to createLogger (which we assume was created previously by a call to createLoggerFactory – see Example 2), after which a LogDef is applied to an object called MyObj.

Every time a MyObj-method executes, the logger in question calls the onMethodEntry method of the stream object, whereupon that method appends the message passed to the MsgBuffer object within the closure. Similarly, when the method returns, the stream's onMethodExit method executes, and that appends the message it is passed to the internal MsgBuffer. The report method of the stream is simply a proprietary method that allows us to output the buffer contents to the console, although it could easily dispatch the buffered information to the server using, say, an XHR object or a WebSocket.

Clearly, streams also give us the flexibility to enhance the logging behaviour we implement, in order to allow the capture of much more information than a default stream does. Example 11 demonstrates this, where an object called ArithmeticWidget has one method that will calculate and display all the Fibonacci numbers up to a given digit, which is specified by the Digit argument that callers provide.

The code also creates a stream object called TimingStream that uses the time and timeEnd methods of the console object (as supported by Firebug) to ascertain the time it takes for calculateFibNum to execute. Additionally, the code creates a logger object, to which it passes the TimingStream, and to which a LogDef is passed that causes all methods of the ArithmeticWidget to be subject to logging (in this case, just the one method).

The example then calls calculateFibNum, asking it to calculate the first 42 Fibonnacci numbers. When this method executes, the logger calls onMethodEntry in the stream object and, when it returns, it calls that object's onMethodExit method. The output from running this code (after a little editing to maintain brevity) shows that 165,580,141 is the 42^nd Fibonacci number, and that calculateFibNum takes 12ms (on the machine on which the code was executed) to complete its task.

A the Buffering Streams section above suggests, a potent application of AJS_Logger is to log method executions on a remote machine, for debugging or profiling purposes, and this requires communication with the server by means of an XMLHTTPRequest or WebSocket object. Technicalities aside, sending a message to a server using either of these types involves essentially the same process – you create a communication object, and dispatch messages to the server through that object – so this guide concentrates on XMLHTTPRequest alone, but the principles extend very easily to the use of WebSockets.

A central issue here is how frequently the stream object should report method-executions to the server. Sending a single logging-message for every execution is out of the question – if every method in the application is logged then this could result in periodic torrents of messages from the client, which, at the least, would exceptionally inefficient.

Given this, it is better that a remote stream-object collect log entries in the way that the buffering-stream example above demonstrates, and dispatch them periodically in batches, and Example 12 shows the creation and use of such a stream. Given its nature, this example is rather involved, and so is broken here into four sections. The first, a JavaScript listing, defines a function called createRemoteStream, which creates a closure that ensconces a function that performs XHR transactions, along with a message buffer and various other essentials.

The function returns a small object that implements the onMethodEntry and onMethodExit methods that all AJS_Logger streams must provide. Both methods call an inner function of createXHRStream called addToBuffer, which concatenates the arguments provided by its callers onto the end of a MsgBuffer string. This operation also increments the MsgCount variable such that, when the number of concatenated-messages reaches a critical value (provided by the caller of createXHRStream), the message is dispatched to the server via the submitXHRRequest function.

The second listing shows some client code that calls createXHRStream, passing the name of a PHP file that resides on the server-side of the equation (and which passes a batch-size of six – sufficient to make the stream write its buffer-contents after three method calls). The stream object that is returned from that call is then passed into a call to createLogger. Following that, the code creates a simple test-object with three methods, along with a LogDef for that object, which it passes to the applyLogDef method of the logger object. It then performs three calls, one to each of the methods of the test object, which the logger logs accordingly.

The third listing is the contents of the server-side PHP file that the stream object invokes. This is painfully simple in that, each time it executes, it opens a file for appending, writes the contents of the Msg object sent by the client to that file, which it then closes. It could, of course, be considerably more-complex, such that it writes to a database of some kind.

The fourth part of the example show the contents of the file to which the PHP code writes the logging data, after one execution of the code in the third listing, giving the arguments and return values (if any) involved in the calls to the three test-methods.

Note that, if you use a WebSocket instead of an XHR object, you have a clear advantage in that you can send a message to the client to suspend and resume logging on a dynamic basis.

As stated in the section on LogDef queues, a given logger-object will not allow the application of a given LogDef to a given method of a given object more than once. This is because doing so would be redundant and, if it occurred accidentally, could be a source of confusion because identical details of a given call to a given method would appear twice in the log.

However, the AJS object permits multiple affixes to be attached to the same method, and AJS_Logger exploits this to allow different loggers to apply different logging-affixes to the method in question. This allows great precision when debugging or profiling a given application; you can apply very simple logging to a large number of methods (using the default stream), such that only the execution paths are mapped out, while applying relatively-complex logging to just a handful of methods through a second logger that uses a custom stream to gather a greater amount of information.

Example 15 demonstrates this by applying two LogDefs to the same object, where the assumption is that we have only a cursory interest in logging method_A and method_C of that object, but that we wish to study calls to method_B in detail. Given this, the code creates two loggers, where the first uses the default stream, and the second employs a user-defined stream. The code applies then the two LogDefs, one through each of the loggers, and then calls each method in the test-object in turn.

Note that the ability to apply multiple LogDefs to the same methods of the same object through different loggers means that you may still shoot yourself in the foot – by using identical streams (i.e. the same stream object, or different streams with the same functionality) you will invite confusion, as described above in the opening paragraph of this section. This is one of those areas where you just have to keep your wits about you.

Go forward to Part 4 of this guide.
Go back to Part 2 of this guide.