Tutorial - Pixida/logtest GitHub Wiki

The tool can solve some kinds of very well-known questions like

“How do I know for sure that the light inside of my fridge goes off when I close the door?”

Scenario

Imagine we want to test if a fridge we just built works correctly.

There is a manual test specification looking as follows:

  1. Switch power on.
  2. Configure temperature to 7°C.
  3. Wait 5 minutes.
  4. Open door.
  5. Close door immediately.
  6. Wait 2 minutes.
  7. Open door.
  8. Leave door open for a minute.
  9. Close door.
  10. Wait two minutes.
  11. Disconnect external power.

Assume we just performed the described steps and captured the following log output:

5 System startup
20 T=25°C
1000 System startup completed
5000 Temperature set to: 7°C
60000 T=24°C
120000 T=18°C
180000 T=14°C
240000 T=7°C
360000 T=7°C
360000 Door opened
360500 Light state: on
365000 Door closed
365500 Light state: off
420000 T=8°C
480000 T=7°C
485000 Door opened
485500 Light state: on
500000 Start alert: T=14°C
540000 T=19°C
545000 Door closed
545500 Light state: off
600000 T=18°C
660000 T=14°C
700000 Stop alert at T=7°C
720000 T=7°C

There are a lot of hidden features buried in the log file. Can you spot them? After power on and setting the temperature to 7°C, the fridge starts cooling down until the target temperature is reached. Opening and closing the door turns the light on and off, but leaving the door open also increases the inside temperature. After a significant amount of time, the temperature rises too much and an audible alert starts in order to notify the user. When the configured temperature is restored, the alarm automatically turns off.

Let’s create some meaningful tests for some core aspects which we consider very crucial for a fridge.

Preparation

First we need to configure the "log reader", a module which is responsible for reading the log data and splitting them into log entities, each of them having a timestamp and a payload. The configuration is stored inside a JSON file which is later referenced when the automaton is ran on a log file. Let's use the designer to create a configuration for reading our log file.

Menu File -> New -> Log Reader

In the configuration section, there are several options which should suffice for reading mostly all standard log file formats. The default configuration should be applicable for reading our test log file. To check this and get a feeling on what the log reader does, scroll down to the "Test Configuration" section, paste the log file into the box and click on "Read Log".

Testing the log reader

The table now shows all log entities that were extracted using the configuration above.

After the log reader generates the expected results, the configuration can be saved using File -> Save. For this tutorial, we can always deal with the default configuration, so there's no need to reference the created one, but for real log files you will definitely use your own configuration.

The first automaton

In the beginning, there was an initial state.

Let's test if the fridge started up correctly. This is probably the most basic case. It’s so intuitive that a simple grep would also do the whole job, but it’s a good idea to start with it to demonstrate some fundamentals of automaton based testing.

An automaton consists of states and edges between them, where every edge can cause a transition between two states. Each edge is linked to a set of conditions. Once an event is received, actually a log entry, the conditions of the edge are evaluated and if they are "truethy", the edge becomes a matching edge. If there is a matching edge, the transition is performed, which means that the active state of the automaton is set to the target state of the edge. Otherwise, if there is no matching edge, nothing happens and the automaton proceeds with the next event.

There are three types of states. There must be exactly one designated state which is active before the first event is received. It is called initial state. When all log events are processed, i.e. when the whole log file has been read, the test succeeds if the last state of the automaton is a so called success state. There’s also a third type called failure state, which we won’t use for now.

Sounds very much complicated, but let's have a look at our automaton, it's quite simple.

Testing the log reader

After the initial state is entered, all log lines are pushed into the automaton one after another in their original ordering as they appear in the log file. As long as no log line matches “startup completed”, the automaton will reside in state “Fridge OFF”. When log line “System startup completed” is received, the regular expression condition of the edge matches and the active state changes to “Fridge READY”. “Fridge READY” is a succeeding state such that the automaton and thereby the test succeeds when the fridge starts up successfully, which is what we desire.

Using the designer to create the automaton

Menu File -> New -> Automaton

By right button clicking somewhere into the pane, a new node can be inserted by selecting the popup menu item.

Creating nodes

An edge can be created by right clicking the node and selecting the corresponding item in the popup menu. Afterwards, an edge follows the mouse pointer and is docked on the target node by clicking onto it.

Creating edges

Nodes and edges can be configured by clicking onto them (an edge is represented by the bulp on it) and modifying their properties on the right side of the window. By clicking into an empty space on the canvas, the options return to the automatons global configuration.

For now, set the type of the inserted node to "Success" and give it a name to improve readability.

Configure node

You can also assign a name to the initial node as shown in the automaton graph above.

The edge is triggered whenever the message "startup completed" appears in a log entry, so setting the following configuration will do the magic.

Configure edge

Using the designer for testing the automaton

Automatons can easily be executed in the designer UI which is helpful when creating or debugging automatons. For running automated tests in productive build pipelines, there's a dedicated headless tool which is not explained in this tutorial, but documented elswehere in this Wiki.

First, create a new test run.

Menu File -> New -> Test Run

And configure it as follows.

Test run configuration

Below the configuration you find a button "Run Test". After clicking it you should see the following output:

Test run execution

Congratulations, you just created and successfully executed your first automaton. Maybe you found a new friend. Well, automatons are no "one fits all" solution. If you want to verify very complex behaviors or need a lot of programmatic execution logic for verification, you should better go with the common "lets code everything by ourself" approach. Nonetheless, good tests test only one behavior and can therefore be modelled by very lean automatons. From out experience, if the number of states and/or edge seems to explode and the logic is getting difficult to catch, the test is not really atomic.

Before you start playing around with it or creating productive automatons, you should carefully read at least the following section, because there's something important which you must definitely know. It will save you a lot of headache, I promise.

Busy automatons

Now we can test if the software runs steadily, i.e. it does not reboot due to internal errors which might have occured during the test scenario. As we know, a system boot triggers the log event “System startup”. Consequently, all we have to do is to check if the log file contains that event once, and exactly once. Note that we have to end the perl style regular expression with a "$" sign, as there's another log line "System startup completed" that we don't want to match. Fortunately, when omitting the "$" sign, the test won't behave as expected, so you have a change to fix it before the test goes into production.

Consider the following automaton.

Fridge runs steadily

It waits for the “System startup” message to enter the success state “Fridge BOOTED”. If another “System startup” message is pushed into the automaton, it proceeds to an error state.

Error states are sinks that can be used to improve the readability of an automaton. Whenever you want to mark a state explicitly as “test failure”, you should flag it as an error state. Error states must not have outgoing edges, i.e. once an error state is reached, the automaton will stop execution and reside in this state, such that later log entries won't accidentally drive your automaton to success, which would be a false positive test result.

Try running that automaton on our log.

Fridge runs steadily fails

Ouch, it fails even if the fridge works correctly. We got a false negative. What happened?

When a log event is processed, an automaton performs as much transitions as possible, before continuing with the next one. This behavior allows for testing also complex behaviors, but it might be unexpected when writing simple tests like this. It’s a very important concept that you should always keep in mind, as being fooled by it can be very frustrating.

In this case, the log event "System startup" is processed twice, i.e. it leads from initial state to "Fridge BOOTED" and from "Fridge BOOTED" to "Fridge REBOOTED".

Ok, so what can we do? Actually, there’s a quite simple way to solve this. We just tell the automaton not to proceed any further with the same log event after the “Fridge BOOTED” state is joined, by setting the property "Wait". Now, the automaton waits for the next log event, after the "Fridge BOOTED" state is reached.

Fridge runs steadily fixed

To be honest, you will rarely need this flag. For now, it’s very important to point out the business of automatons: Given one log event, automatons always try to proceed as far they can.

At the same time, you don’t need to worry about circles though. In practice, they appear quite often and are automatically detected. When a circle is entered, the automaton will stop processing the current log entry and continue with the next one from the current state.

Test the compressor

Although this feature is the very basic function of a fridge, the example is already quite complicated and uses a lot of techniques presented. For testing the compressor, we check if the temperature continuously decreases, but only while the door is closed.

In this example, we use scripting. Why should scripting be used when there are automatons? Automatons were made for not having to write any code, weren't they? Yes, in general, this is true. Scripting should be used only if really necessary, and in most cases, there will be no reason for it. Nonetheless, not every problem can be solved by only using states and transitions. From the formal languages theory, automatons can only recognize regular languages. In short this means that an automaton would need infinite states to represent infinite combinations of inputs. As the temperature is expressed as integer, we would need a state for every value - which is far from feasible.

In the designer it's possible to select the desired script language as part of the automaton properties.

Script language selection in designer

The script in the "On Load" property is a handler which is called when the automaton is initialized. Consequently, it can be used to initialize variables used later on. Actually, we don't need it for this automaton, but we need lots of other stuff. There it goes:

Temperature decreases when door is closed

After entering the initial state, it is waited until the temperature is reported. When the regular expression matches, the temperature is stored in a matching group. When the edge is triggered afterwards, the On Walk handler is executed. As the edge is only "walked" after all conditions are truethy, it knows there is a valid matching in group 1 (as usual, 0 references the whole matching) and fetches by calling the corresponding built-in function. It's strongly recommended always to parse numeric values to their type after they were obtained from the engine! The temperature is assigned to the variable T. Note that this T is not the T which appears in log entries reporting the current temperature.

Now we wait in state "Wait for temperature report" until the temperature decreases. The conditions below the state will lead us back to this state and is triggered whenever a temperature is reported and when the temperature decreases. It will also save the updated temperature back to T. A Check expression condition is executed after the regular expression condition is checked, regardless of whether the regular expression matched or not, and must return true to make the condition itself true. Therefore, we first check if the matching group returns "not null" which indicates the regular expression matched. Afterwards, we check if the new temperatur is below or equal to the recent one. If yes, the edge is "walked" and the corresponding event handler updates the temperature variable T.

Right beside the state "Wait for temperature report" we do the same, but trigger the edge if the temperature increased. Furthermore, the "on walk" handler is used to write some diagnostics to the log file of the automaton execution itself.

Handling the door is quite easy. If the door is opened, the automaton suspends in state "Door open" until it is closed again. Note that the regular expressions match the whole payload by adding ^ and $ respectively.

You can test the automaton by increasing some temperature in the log file, before the door was opened or after it was closed.

As you can see, scripts are quite powerful but they can also make the logic behind the automaton very hard to understand. Designing automatons without scripting and still keeping the number of states and transitions low needs some practise. It's always good to start with very simple assumptions. And to have some sleep before stepping up to more complex ones.

And what about the light?

Let's have a look.

Light goes off when door is closed

We wait until the door is closed. Note that if the door is never closed, we also let the test fail, so we make sure we really test the desired behavior and discover tests which became useless by accident, i.e. after changing the test specification. The condition for entering the failure state is more crucial for this test: The light must turn off until the door is opened again. If the end of the log file is reached, the automaton will still reside in the "Door just closed" state which is not accepting. At the same time, when the door is closed and the light turns off, we succeed. In this example, we actually do!

Concluding this tutorial, yes, the light turns off after the door is closed. At least, our fridge seems to behave quite perfectly, so it's time to develop and test somewhat more exciting products!