Indenting Trace Logs

Have you ever looked at CAF trace logs before? Sometimes, reproducing a bug with logging enabled is the best way to get to the bottom of unexpected system behavior.

Trace logging of course generates much too much data to run in production. Even for short runs, you probably look at mega- or even gigabytes of text output.

During development, however, skimming through logs can often times safe a lot of time. To make it easier to focus on a single actor, CAF includes a small python script called indent_trace_log.py in the repository.

But before we look at the script itself, we briefly discuss a few basics and implement a small example to generate some log output to work with.

Trace logging is disabled by default. Not just at run-time, but users must explicitly enable trace logging when building CAF. When building CAF using the configure script, you can pass --log-level=trace. When building with CMake directly, set CAF_LOG_LEVEL:STRING=TRACE during build.

To have some actor we can analyze, we implement a simple cell actor that holds an integer value that we can retrieve, set or add to:

struct cell_state {
  explicit cell_state(int32_t init_value) : value(init_value)  {
    // nop
  }

  caf::behavior make_behavior() {
    return {
      [this](caf::get_atom) {
        return value;
      },
      [this](caf::put_atom, int32_t new_value) {
        value = new_value;
      },
      [this](caf::add_atom, int32_t amount) {
        value += amount;
        return value;
      },
    };
  }

  int32_t value;

  static inline const char* name = "cell";
};

using cell_impl = caf::stateful_actor<cell_state>;

In our main, we simply spawn a cell actor with some initial value, then add to it and print the result.

void caf_main(caf::actor_system& sys) {
  using namespace std::literals;
  auto cell = sys.spawn<cell_impl>(11);
  caf::scoped_actor self{sys};
  self->request(cell, 1s, caf::add_atom_v, 9).receive(
    [](int32_t new_value) {
      println("cell responded with: ", new_value);
    },
    [](const caf::error& err) {
      println("cell failed to respond: ", err);
    });
}

Sure enough, the program prints cell responded with: 20. But how can we find our cell actor in the trace log output? And how do we get a trace log in the first place?

To get CAF to create a trace log file, the quickest way is to pass a verbosity level to the logger on the command line:

./example --caf.logger.file.verbosity=trace --caf.logger.file.path=out.log

This should put an out.log file into the current directory with a couple hundred lines of text. Setting a path is not necessary, we use it here to make sure we know the file name in advance.

Now, how to get to our cell actor? You may use more advanced tools, but for now we rely on good ol' grep:

$ grep 'NAME = cell' out.log
... SPAWN ; ID = 6 ; NAME = cell ; TYPE = ...

As we can see in the truncated output, the quickest way to find actors of a particular kind is to look for the name we have assigned to it. Our cell state has the static member variable name and whatever we assign to it is the string we can start looking for.

CAF logs each spawn event with a line that contains the ID, the name, the C++ type, constructor arguments, node ID and initial group memberships. The interesting bit to us now is the ID, because this is where our gem indent_trace_log.py comes into play. We can use the script to print out only log entries for a particular actor and to indent the output based on entry/exit events by passing -i <ID> before the file name:

$ indent_trace_log.py -i 6 out.log

If you are like us and find yourself working on the command line more often than not, give the script a try. Combined with a bit of syntax highlighting in your favorite command line editor, it can go a long way.