Logging Tab and Klog()

Learn how to debug KRL code

If you have ever needed to make an application more complex than a simple output of “Hello World!” then you most likely understand the need to be able to debug.

Without debugging tools, we spend more time looking at our code than we do writing it. We are forced to develop, execute, then guess what could possibly be going wrong with our code, even though we seem positive that it is the computers fault instead of ours.

Luckily, when dealing with KRL, there is already a default debugger set up, all you need to do is make use of the ‘Logging’ tab, or the terminal screen where you fired up your pico engine. Both options output the same information, so it is up to you to decide which one you want to use since there are pros and cons to either.

In this post, we will also talk about the use of the klog() operator which allows the developer to see the value of an object at runtime. Let’s get into it shall we?

Debugging From Your Terminal

Your first debugging option is the easiest to find. When you first started your pico engine from the terminal, you should have noticed that it automatically started running a script that produced a lot of output. Although you don’t need to understand what is happening behind the scenes to get your pico engine up and running, you do need to pay close attention to that terminal window from there on out. This is where any debug or klog statements, shown as [DEBUG] and [KLOG] respectively, will be output upon the execution of any rule.

Debug From The Logging Tab

Your second debugging option is a little more difficult to find, but it does look a lot cleaner than a messy terminal window. After starting up the pico engine and navigating to localhost:8080 (or wherever your pico engine is hosted), click on your pico, and then click on the ‘Logging’ tab.

If you see a message saying: “Logging is disabled. To enable, install the “io.picolabs.logging” ruleset”, simply click on the install link and the ruleset for logging will be added to your pico for you. Thanks KRL! :)

Photo by Zan on Unsplash

Observing [DEBUG] and [KLOG] Statements

Now that you have set your pico up successfully for debugging and logging, let’s observe it in action.

As mentioned before, debug and klog statements are output upon the execution of any rule. Some of these rules are very low level and unknown to you. To see what I mean, do the following:

1. Fire up your pico engine and go to localhost:8080
2. Click and drag on your root pico to move its position on the screen.
3. Observe your terminal window when you release the drag movement and you will see output that says rule added to schedule: io.picolabs.visual_params -> visual_moved and rule selected: io.picolabs.visual_params -> visual_moved. Note: It is easier to observe the terminal window in this case rather than the picos logging tab since you can see the rule being scheduled and selected in real time. However, the logging tab in the pico engine UI can still be used.

The io.picolabs.visual_params is a ruleset that is installed by default to any pico upon creation, and visual_moved is one of its rules that is called whenever the pico is moved positions in the UI. In the logs, you will see a lot of [DEBUG] logs and [KLOG] logs. They most likely don’t mean much to you right now, so let’s look at our own example ruleset.

How To Use klog()

The klog() operator allows us to see the value of an object and insert commentary logs. For this example we will briefly examine a ruleset that allows a user to populate an array with movie names, and then call a function to retrieve that array. The array will be stored in an entity variable, which is beyond the scope of this article, but just think of it as a normal variable that maintains its state even upon exiting the ruleset. In other words, it is a persistent variable.

The beauty of klog() is that it can be placed nearly anywhere in KRL code, as it is attached to the instantiation of a variable. It is also valuable to add a klog() statement on the final line of a function, as it allows you to examine the logs and see if your function is behvaing the way you expect it to.

If we have a rule called getMovies which simply returns the array of movies, it would look like this:

getMovies = function() {
   ent:movies
}

Simple enough right? But suppose that we are suspicious that this function is returning an array with incorrect values. We can use klog() in the following way to examine it:

getMovies = function() {
   ent:movies.klog("Current list of movies contains: ")
}

And there we go! The last line of the function is what is being returned, and by simply appending .klog(<optional message>) we can make it that much easier to see what may be going wrong.

Now we are ready to examine the logs. Well… almost ready. If you don’t know how to set up and use the ‘Testing’ tab in the UI, then see read this post to show you how to set your function up for testing. When we test our function, we will see that it will say “null” as a result of the function. This is understandable since we haven’t instantiated a movie entity variable, so it does not actually exist yet.

However, if we add the klog() operator to the return statement of the function, navigate to the testing tab (or terminal window) and click on the most recent timestap to observe the logs, we will see a [KLOG] log that will look something like this:

[KLOG] Current list of movies:  null

We will see plenty of [DEBUG] logs, which are added by defualt, so make sure to look for the [KLOG] logs to find your own custom logs (that was a mouthful).

Now go back to the pico engine UI and click and drag the position of your pico and observe the output logs. Do they make more sense now? The [KLOG] logs are simply showing the position of the pico in terms of “left” and “top”. If we were to examine the io.picolabs.visual_params ruleset, we could remove those klog statements and they wouldn’t appear anymore, but the [DEBUG] logs would.

Expanding The Movie Ruleset

That is how simple it is to use klog(), and if you are still fuzzy about it, follow along to see how we can implement it in a rule. If you think that you have got the idea, feel free to start playing around with it in your own code, and come back here if you get stuck. Once you get the hang of it, using klog() is super simple and powerful. What we will do next is make a rule that lets us instantiate and add movies to the movie array, which will then make the getMovies function more useful.

rule add_movies {
    select when add movie
    pre {
      movie_name = event:attr("name")
    }
    if movie_name then noop()
    fired {
      ent:movies := ent:movies.defaultsTo([]).append(movie_name).klog("ent:movie : ")
    }
  }

Here we have a rule that is sent an attribute of the name of the movie. That name is then appended to a movie array. If the movie_name local variable is non-null, then do nothing, and enter into the fired block. Think of the defaultsTo() operator as a classic if-else statement. If ent:movies is empty or not initialized, initialize it as an empty array and then append the movie, otherwise, don’t worry about initialization and only append the name of the movie to the array. The klog() operator will show up in our logs the state that the array is in upon rule execution. Let’s take a look at the logs now that we can add movies. Here is what the logs look like if we add the first movie “Thor Ragnarock”:

See the nice little [KLOG] statement in the logs to let us know what our variable looks like? 😏 Pretty helpful! Keep adding videos and you will see the same log, but it will contain a growing array of movie titles. If you wanted to remove a movie from the array, then you would need a rule for that, so that is up to you to mess around with. Definitely give it a shot and experiment with klog().

TL;DR (too long didn’t read)

• There are two places where you can check for debug and log statements when writing KRL code:

1. Logging tab
2. Terminal window from which you started your pico engine.

Both have pros and cons, so it is up to you to use the one that you like best. Sometimes it can be determined by occasion and what you are trying to accomplish.

• Using klog() is a powerful tool to help you customize what variables and states you want to examine. Usually, klog() is placed at the end of a line of a return statement or instantiation/assignment of a variable. The more that you play around with it, the more likely that it will be that you will begin you use klog() statements almost without thinking about it.

Documentation Links

Logging Documentation

Explicit Logging

klog() Operator

Happy KRL adventures! ✈️