A List Apart

Menu
Issue № 202

JavaScript Logging

by Published in JavaScript43 Comments

If you spend much time working with JavaScript, there will eventually come a day when you need to know the value of a variable (or an object’s field) as the execution of the script progresses, or why a script terminates unexpectedly. In simple scripts, you can accomplish this with JavaScript’s alert function, which instructs the browser to create a dialog box with the argument set as the box’s caption. The message can be anything that helps you understand your script’s operation.

For example, the statement:

alert(
  “Node #” + i + “‘s class is:” + nodes[ i ].getClass()
);

might produce something like the following when executed:

An example of using JavaScript's alert() function to display information about an executing JavaScript

When alert() is used only a few times throughout a script’s execution, it is easy for the author to keep track of exactly what is being displayed in the dialog boxes. However, once nested loops and other advanced techniques such as recursion are introduced to the script, using alert() to debug your script can quickly degrade into wasting your time clicking an “OK” button as quickly as possible to dismiss unnecessary dialog boxes while hunting for the one box that you’re interested in.

Tools for the job

Several browsers include tools that can aid in debugging your code, including those from Opera and the Mozilla project. The Mozilla browsers and recent versions of Opera include JavaScript consoles that assist script authors in finding the error that caused a script to terminate unexpectedly:

Firefox's JavaScript console

To its credit, Internet Explorer on Windows can also notify the viewer of JavaScript errors (although its messages tend to be a little cryptic when compared to Mozilla’s and Opera’s consoles).

Firefox’s older brother, Mozilla, also includes a full-blown JavaScript debugger, dubbed Venkman, to assist scripters in finding out exactly what their code is doing. However, the art of setting breakpoints and stepping through your code function-by-function and instruction-by-instruction is more tedious and complicated than many would like it to be. Although there are several excellent tutorials that cover how to use Venkman, becoming familiar with the way a debugger works and how to use one effectively requires a large time commitment.

Mozilla's Venkman utility

The complexity and overhead of using a debugger isn’t unique to Venkman; nearly every IDE (Integrated Development Environment) includes some sort of debugger, but these are often ignored by developers due to the amount of effort that must be expended to actually use the debugger and step through their code.

However there is, in fact, a bigger problem in using the JavaScript consoles and debuggers: they don’t reveal why a script operates as expected in Browser A, but crashes and burns in Browser B, or vice-versa. The debugger/console will only let you know what’s happening in Browser A.

En vogue

Another, simpler debugging method has come into fashion in recent years, although the principle behind it must be as old as the art of programming itself. This method is called logging, and it works by echoing as much information to the screen as is necessary to find out how your code and data structures are behaving. The echoed information can include everything from descriptive statements that are used to let the programmer know what is happening in the script to the value of a variable or the field of an object; it can be any information that will inform the author of what is happening in the code.

In fact, by using JavaScript’s alert function to display snapshots of our script as it executes, we are essentially using a very basic logging method; instead of displaying the information in a terminal window or appending it to a file on the hard drive, we are presenting it directly to the viewer. Yet using alert() proves to be more of a hinderance than a benefit when used often due to the amount of mouse clicks that are needed to dismiss the dialogs. What’s needed is a proper logging mechanism for JavaScript and the browsers that it runs in.

The concept of logging was popularized by Apache’s Log4J package for Java, and its essential ideas have since been ported to other languages, including but not limited to:

This article will introduce fvlogger (available for download here), a library that brings simple logging functionality to JavaScript and the browser.

Logging in JavaScript with fvlogger

Whereas logging packages in the languages listed above provide a complex class/package structure built on top of inheritance and other object-oriented concepts, fvlogger borrows concepts from Log4J and its cousins, but eschews their complexity by providing a simple API and offloading the heavy lifting onto the DOM.

The library defines four basic functions (and provides a few others that can be considered optional), a few flags that can be set to define its behaviour, and several CSS classes that can be used to govern how the log will appear. It requires just one special element to be placed in the document, and including fvlogger in your pages is as easy as adding the following two lines to the head of your documents:

<script type=“text/javascript”
  src=”/fvlogger/logger.js” />
<link rel=“stylesheet” type=“text/css”
  href=”/fvlogger/logger.css” />

Essentially, all fvlogger does is append new elements to a specific element in the document. These new elements contain the logging messages that will assist you in debugging your script(s). The four functions used to create the log messages are: debug(msg), info(msg), warn(msg), and error(msg). Each function expects a single string that will be appended to the document.

Logging levels and classes

One of the fundamental ideas behind logging is the ability to set the granularity of what information will be logged: Should only errors be displayed? What about information to indicate which branches and/or loops are being executed?

While it is possible to get away with only using one function to log messages to the browser, by using all four you will be able to filter your log messages based on their importance; debug messages are the least critical and can often be dismissed, while error messages are the most important and should always be taken into consideration.

By default, all messages will be appended to the element whose id is “fvlogger” (although this can easily be changed). The log messages are wrapped in <p> elements—which, like the id, can be changed—and have a single class applied to them that corresponds to the logging function that was used to create it. Debug messages will have the debug class applied to them, error messages will have the error class applied to them, et cetera. These classes allow you to style your log messages any way you like using CSS; the project includes a default stylesheet and supporting images to get you started but you are, of course, free to change its appearance to your heart’s content.

The convenience functions mentioned above allow you to quickly filter which log messages are displayed in the browser:

  • showAll() shows all log messages,
  • showDebug() shows all debug messages, and hides all others,
  • showInfo() shows all info messages, and hides all others,
  • showWarn() shows all warn messages, and hides all others,
  • showError() shows all error messages, and hides all others,
  • eraseLog() will erase all messages from the log.

(The filter methods work by simply setting the display style of a log message to either be visible or invisible based on the message’s class.)

Getting started

That being said, let’s take a look at the steps required to set up fvlogger. The following snippet of XHTML defines the elements that will be used to interact with fvlogger, although we could get a way with just a simple <div> if we really wanted to. You will notice that none of the log messages in the <div> below are shown; this is because the messages are created dynamically by fvlogger and apppended to the document after it was loaded into the browser.

<div id="fvlogger">
  <dl>
    <dt>fvlogger</dt>
    <dd class="all">
      <a href="#fvlogger" onclick="showAll();" 
        title="show all">all</a>
    </dd>
    <dd class="debug">
      <a href="#fvlogger" onclick="showDebug();" 
        title="show debug">debug</a>
    </dd>
    <dd class="info">
      <a href="#fvlogger" onclick="showInfo();" 
        title="show info">info</a>
    </dd>
    <dd class="warn">
      <a href="#fvlogger" onclick="showWarn();" 
        title="show warnings">warn</a>
    </dd>
    <dd class="error">
      <a href="#fvlogger" onclick="showError();" 
        title="show errors">error</a>
    </dd>
    <dd class="fatal">
      <a href="#fvlogger" onclick="showFatal();" 
        title="show fatals">fatal</a>
    </dd>
    <dd>
      <a href="#fvlogger" onclick="eraseLog(true);" 
        title="erase">erase</a>
      </dd>
  </dl>
</div>

Nothing too advanced, really. Although the markup required to get up and running could be as minimal as…

<div id="fvlogger" />

…if you don’t require all the bells and whistles. As for the log messages themselves, the following code snippet illustrates how to create log messages and outlines which level of severity should be used for your log messages.

debug('Scatter debug messages throughout your
  code to provide a high-level overview of
  what your code is doing, such as which
  function is currently in scope and the
  values of loop counters.');

info('Information messages are the meat and
  potatoes of logging messages; sprinkle them
  around to reveal more detailed information
  about your script's execution, such as the
  values of variables and function/method
  return values.');

warn('Warning messages are used to indicate
  potentially hazardous situations, such as
  missing function arguments…');

error('While error messages are used to
  indicate that something bad is about to
  happen; note that these kinds of errors
  are considered to be run-time errors,
  which are a different type of beast from
  the parse errors mentioned below.');

…and the following is how they appear after having the default fvlogger styles applied:

     
fvlogger
     
        All      
     
        Debug      
     
        Info      
     
        Warn      
     
        Error      
     
        Fatal      
     
        Erase      
 

Note: For those developers who are testing their scripts in IE or one of the many Mozilla-based browsers, JavaScript parse errors will also be appended to the log as fatal errors. This feat is accomplished by simply overriding the <body>’s onerror handler to add another message to the log.

Now you’re probably asking what that other gunk in the log is. Those are the log messages generated by code included later in the article. Which brings me to the second half of the article. Now that you’re familiar with the theory and practice behind developing with fvlogger, I’ll walk through a real-life example—one that I came across in the development of the package—of the way logging can aid in debugging your scripts.

Developing with fvlogger

Included in the styles of this page is the following rule:

.labrat { font-weight: bold; color: red; }

So, theoretically, any elements in the document whose class is “labrat”—whether they be a part of the document when the page is loaded into the browser or appended at some point thereafter—should appear in bold-faced red type, including the following two examples.

This is the first example.

This is the second example.

Easy-peasy, right? Almost, but not quite.

The problem

The examples shown above are included in the document (ie: they were created when authoring the rest of this page), so it should come as no surprise that they appear as they should in every browser that supports CSS. However, with the cross-browser support of the DOM, dynamically creating elements and appending them to the document has become commonplace—even required—by many websites and applications, this article being one of them. Let’s make sure that we can apply classes to these dynamic elements as well.
 
The code to accomplish our task should look something like the following:

var p = document.createElement("p");
p.appendChild(
  document.createTextNode(
    "This paragraph (#3) is created dynamically and appears
    with the proper bold-faced red type in virtually all
    modern browsers except for Internet Explorer, where the
    paragraph is created and the text is appended, but the
    styles are not properly applied. Why?")
);
p.setAttribute("class", "labrat");
document.appendChild(p);

The above snippet of code works in all modern browser families—WebKit, Gecko, and Opera—except for IE. With Internet Explorer, the following paragraph will have the same font as all regular paragraphs, even though it has the “labrat” class applied (go ahead and load this page in IE and another browser and compare the differences).

After a little investigating, the cause is IE’s implementation of the setAttribute and createElement methods. Take a look at the following code (which contains the logging statements shown in bold) which is used to create example paragraph #4…

// create and append the paragraph to the document
var p2 = document.createElement("p");
p2.appendChild(
  document.createTextNode(
    "This is example paragraph #4.")
);
p2.setAttribute("class", "labrat");
var bottle = document.getElementById("bottle");
bottle.appendChild(p2);

// use fvlogger to log all attributes to the document
var i = 0; var attrs = p2.attributes;
for (i = 0; i < attrs.length; i++) {
  debug("attribute #" + i + ": " +
    attrs[i].name + "=" + attrs[i].value);
}

// display a summary of attrs length
if (i == 0) {
  error("new element has no attributes");
} else {
  info("p has " + i + " attribute(s)");
}

…and the log message that it generates, shown previously in the page. In Opera, Mozilla, and WebKit-based browsers, there are only two logging statements produced by this snippet of code: one debug statement that shows the class of the element that we created, and the other indicating the number of attributes belonging to the element. Because we are only assigning one attribute to the element (its class), the output is exactly what we would expect it to be: the paragraph has one attribute named—not surprisingly—“labrat.”
 
However, Internet Explorer is “special” in the way that it creates elements. Instead of having zero attributes (as one would expect) immediately after creation, new elements inherit all attributes and their default values as defined in Internet Explorer’s default DTD. So instead of our new element having a single attribute after setting its class, it actually has 84. Zoinks!
 
But what’s equally as odd is that when attempting to set the class of a new element through its setAttribute() method, IE will actually create another attribute node instead of replacing the value of the existing class attribute. Thus, we end up with two class attributes instead of one in IE (attributes #3 and #83 in the log statements shown above).

The solution

Luckily, there is, a relatively simple fix for IE’s problem: instead of simply setting the value of an attribute based on its name, we can loop through all existing attributes until we find the one that we’re looking for and then set its value based on its numeric index in the node’s attributes array. The following snippet of JavaScript will get the job done:

var className = 'labrat';
var p3 = document.createElement('p');
p3.appendChild(
  document.createTextNode(
    "And guess what. It works!" 
  )
);

// if the node's class already exists
// then replace its value
if (p3.getAttributeNode("class")) {
  for (var i = 0; i < p3.attributes.length; i++) {
    var attrName = p3.attributes[i].name.toUpperCase();
    if (attrName == 'CLASS') {
      p3.attributes[i].value = className;
    }
  }
// otherwise create a new attribute
} else {
  p3.setAttribute("class", className);
}
    

The moral of the story

In this article we saw how logging unveiled one of Internet Explorer’s many quirks. But more importantly, we saw how logging provides an easy way to create transparent code—you, the author, can stay on top of your data structures as they pass through each line of your code and know exactly what is happening inside the black box of a web browser’s JavaScript engine (or, similarly, your Dashboard widget). This transparency can prove invaluable since your code is likely to run in three or more different browsers that, while similar, are by no means identical.

About the Author

43 Reader Comments

Load Comments