5 Logging in SuiteScript 2.0

Created: May 29, 2017

Logging is an incredibly important tool in software development, and that's no different in SuiteScript. We use logging to write messages to our Script's Execution Log. These messages can help us track down errors, audit the execution path of the script, and trace through data values as the script progresses.

In SuiteScript 1.0, we added log messages using the nlapiLogExecution function; in SuiteScript 2.0, we use the methods found in the N/log module.

N/log

On the log module, there is one method per Log Level, and each accepts a single Object parameter.

The severity and importance of the message we want to log dictates which level we should use. Later, when we are viewing our messages, we can use the Log Level to filter down to a very specific view of what our script is doing. If we always log everything at DEBUG, then we are only making it harder on ourselves and other developers to trace through our script to analyze it appropriately.

All four log methods accept exactly the same input options, so we really only need to see an example of one to get familiar with all of them. However, I want to make sure we're using logging effectively, so I'll show the logging strategy that I employ using an example we've seen previously in the series.

Logging Strategy

To explain the strategy briefly, let's go through how I use each log level.

DEBUG is the lowest, or most detailed, logging level. For that reason, I use DEBUG for the very minute details of my script. I primarily use it for writing the values of specific variables throughout my script.

AUDIT is the next level, and I use this level as an indicator of where the script currently is in its execution. Primarily, I put an AUDIT log at the very beginning of every function that simply tells me which function we're entering.

ERROR comes next, and as you might imagine, I use this for problems that are encountered during my script, but there is a little more to it than that. I specifically use ERROR when I am able to recover from the problem.

For example, let's say I have a Map/Reduce script responsible for finding all of my un-invoiced Sales Orders and creating an Invoice for them. If the script fails to transform a specific Sales Order into an Invoice for whatever reason, I would consider that an ERROR because there's no reason the script can't just continue on to more Sales Orders. When I know the problem isn't severe enough to cause more problems later in my script, I use the ERROR level.

But what about more serious errors? What if in that same Map/Reduce script, the search I am running to get the data to process in the first place fails? Well, my script certainly can't continue without those results, so that is where I use EMERGENCY because at that point, my script can no longer continue on and do anything meaningful.

Example

To start, here's a module we used in the sublists video along with its function to find and remove a line from a sublist. Notice I've added the N/log module to our dependency list. This actually isn't necessary, as the log module is actually available globally. You can reference it from any 2.0 module at any time without including it in your dependencies, but I prefer to be explicit.

/**
 * @NApiVersion 2.0
 * @NScriptType Suitelet
 * @NModuleScope SameAccount
 */
define(["N/record", "N/log"], function (r, log) {
    // ...
    function removeLine(rec) {
        var index = rec.findSublistLineWithValue({
            sublistId: "item",
            fieldId: "item",
            value: 77
        });

        if (index === -1) {
            // Not found
            return;
        }

        try {
            rec.removeLine({
                sublistId: "item",
                line: index
            });
        } catch (e) {
            // Fails silently
        }
    }
    // ...
});

Now let's update it with some logging.

First I want to add my AUDIT message immediately upon entering the function; all it needs to do is log the name of the function being called:

function removeLine(rec) {
    log.audit({title:"removeLine"});
    // ...

Next I want a DEBUG message that tells me the value of index after it's initialized:

var index = rec.findSublistLineWithValue({
    sublistId: "item",
    fieldId: "item",
    value: 77
});
log.debug({details:"index = " + index});

Now how about another AUDIT message that lets me know we didn't find the line:

if (index === -1) {
    log.audit({details:"Could not find item"}); 
    return;
}

Lastly, instead of my catch block failing silently on any exception from removeLine, I at least want some more details on the exception. Since failing to remove the line is probably still a problem I can recover from, I'll just use the ERROR level:

try {
    rec.removeLine({
        sublistId: "item",
        line: index
    });
} catch (e) {
    log.error({
        title: "Error removing line item",
        details: e.message
    });
}

By following this pattern, I can establish a very consistent routine for tracking down a problem in a script. When a script encounters an error, I look at its AUDIT-level messages. This shows me a trail of the functions that were executed, leading right up to the error. When I find the error, I also see the last function that was executed in the logs; this gives me a great starting point for investigation.

Once I've identified the function, then I switch to viewing DEBUG-level messages between the function start and the error, which can help me identify the cause. Even if there aren't any messages in between, I know right where I can start adding new messages to help me trace the source of the error.