Logging Best Practices

These best practices for logging can be used for any software project, not just SCADA systems, and not just Ignition.

When using software, it is very important to be able to monitor what the program is doing at any given point. This is helpful when developing code for the first time, since it will allow you to troubleshoot the program as you write it. Logs also allow you to monitor and troubleshoot code in production.

For example, you might have code that looks up information in an ERP system based on a part number. Eventually you run into a situation where you have a new part number classification that isn’t in the system. The program will display a vague error message to the operator. Since the code has been running for a while, you may have forgotten all of the intricate details and will have to dig back into the program to see what it is doing, what it should be doing, and what went wrong.

Instead, you could save yourself some time and headache by adding detailed logging into the system. Logging will let you know when the software doing something, what it was doing, and what data it was using along the way. A typical computer science class will be familiar with the common approach of printing something to a console as a program runs to troubleshoot a for loop. Logs accomplish a similar objective with more clarity and intention by design. We want to make it easy for anyone looking at our code in the future to troubleshoot it.

For the purposes of this post, we will be using the system.util.getLogger() function in Ignition, and using the functions built into this feature to log specific types of messages. Here is a very basic example of how to log information:

logger = system.util.getLogger("Log Blog Log")
logger.info("Info Log Entry")

This gets a logging context, and then writes a message with the text “Info Log Entry” into the log. This shows up in the log like this:

16:03:21:036 [AWT-EventQueue-0] INFO Log Blog Log - Info Log Entry

We recommend logging a few different things in all programs. What the program is doing so you can track when functions are called, data is exchanged, etc. What parameters you are using in function calls so you know what you are trying to query. Finally, any errors that occur, along with whatever relevant information you need to understand why the error occurred.

Log After, Not Before

While you are developing code, you might add in a lot of logs to track where something fails in your program. This includes before and after things happen. When deploying code, we don’t really need to know before something happens, we care about what happens after a function is called. For example if we want to get information about a specific work order from the database, we could log the call before it happens or after we make it. If we log before, we will still want to log something after—along with handling any error messages. So, the log entry before the call will clutter the log with unnecesary information.

#Don't do this
logger.info("Requesting Work Order info")
system.db.runPrepQuery("SELECT * FROM WorkOrders...

#Do this instead
system.db.runPrepQuery("SELECT * FROM WorkOrders...
logger.info("Requested Work Order info")

The first statement doesn’t tell us anything and we would not know if the query was successful or not. We could look for the absence of an error, although if we are in a high volume system the two log entries might not be near one another, which would add additional confusion. Instead, we will track that the request was made, and as we go further we will see how to handle exceptions to get the information we need to troubleshoot. The one exception to this approach is if we are debugging code, in which case we might need to add in more log entries while we troubleshoot the issue, then remove them once we have solved the problem.

Separate Parameters and Messages

When logging, you will want to know both what you are calling, and what parameters you are using in that call. The following example will provide our discussion points:

#Don't do this
url = "http://www.corsosystems.com"
system.net.httpGet(url)
logger.info("Made request to {} using REST API.".format(url))

#Do this instead
url = "http://www.corsosystems.com"
system.net.httpGet(url)
logger.info("Made request to REST API. [url={}]"/format(url))

The first example will work for simple log messages, however if you need to adjust the parameters you are displaying, it will require re-writing the sentence so it makes sense. Depending on the parameters, it might also push the end of the log message onto a new line or past the edge of your screen—making it more difficult to follow what is going on.

By placing the parameters at the end—and using some sort of differentiator characters like brackets—parsing these logs becomes very easy with regex tools. You can also append additional parameters to the end of the message without having to change the format of the entire message. This approach will make your life easier as your logging needs become more complicated.

Note, you can also use the same log message format with an f after the function name to pass in the parameters and automatically format the string if you like, details in the documentation:

logger.infof("Made request to REST API. [url={}],url)

Differences Between INFO, WARNING, and ERROR

There are a number of log message types you can use, detailed here in Ignition’s documentation. But, for most situations, INFO, WARN, and ERROR are sufficient. So, we will look at the various use cases for them.

INFO

INFO should be used for informative messages: “The program did XYZ.” This makes it easy for someone to monitor what calls were made and when.

WARN

WARN should be used when you run into an EXPECTED exception. This would usually be something you have coded into the program as part of a try/except block, or an if statement where you handle the outcome gracefully.

ERROR

ERROR on the other hand is usually reserved for UNEXPECTED exceptions. This is something you didn’t account for in the code as a known failure mode. ERROR is useful for tracking down and implementing changes to the code to make these occurrences common by adding exception handling.

These concepts are described below. We print an info log when the variable is printed, and then catch an expected exception where the variable is not defined, and log it as a warning. If something else goes wrong we would print an error log.

try:
   print(x)
   logger.infof("Printed variable x [x={}],x)
except NameError:
   logger.warn("Variable x is not defined")
except:
   logger.error("Something else went wrong")

WARN and ERROR should also be used as calls to action, whereas INFO is reserved for things where no user intervention is required. If no one needs to do anything or be concerned with the outcome of your code you don’t need to log a WARN or ERROR message.

INFO is for People, DEBUG is for Technology

Finally, INFO, WARN, and ERROR logs are used for people interacting with the system to track down what is happening and when. If you look through the Ignition documentation, you will also see DEBUG and TRACE messages as options you can log with.

In our projects, DEBUG/TRACE messages are used for the technology side of things when we want to log what’s happening on a technical level with more detail than the average user would care about. These logs will follow the actual code execution through a program with more information on the business processes involved to show how they work when monitoring a system. This is useful when troubleshooting code, as well as understanding how code functions when you need to add in additional functionality and need to decide where it should go in the code.

For example, following the process of a user signing up for a newsletter with debugging turned off we see a sign-up, the newsletter sending, and the user unsubscribing:

INFO  | User registered for newsletter. [user='Sarah', email='sarah@gmail.com']
INFO  | Newsletter send to user. [user='Sarah']
INFO  | User unsubscribed from newsletter. [user='Sarah', email='sarah@gmail.com']

With debugging turned on, we see the business processes happening that are useful for understanding the process in detail—but which are not required for someone monitoring when people sign up for the newsletter. In this case, you will see a welcome email sent as well as starting a job to send the newsletter itself.

DEBUG  | Saved user to newsletter list [user='Sarah', email='sarah@gmail.com']
DEBUG  | Send welcome mail. [user='Sarah', email='sarah@gmail.com']
INFO   | User registered for newsletter. [user='Sarah', email='sarah@gmail.com']
DEBUG  | Started cron job to send newsletter of the day. [subscribers=24332]
INFO   | Newsletter send to user. [user='Sarah']
INFO   | User unsubscribed from newsletter. [user='Sarah', email='sarah@gmail.com']

Beyond the Basics

There are many more concepts and best practices for a truly robust logging infrastructure. You could consider tracing, log aggregation, metrics, and tools to make parsing logs easier. When it comes down to getting started, the concepts laid out in this post will get you 80% there, especially since most software has no logging!

If you have any questions on anything in this post, or you want help with your log systems—or if you want us to dig into more concepts related to logging, please click the button below to reach out!