Logging aboard the Millenium Falcon

Millenium Falcon never wants to jump hyperspace, unless R2-D2 fixes it for you. How happens that even infamous Han Solo struggles to understand his spaceship? Is it because the Corellians have a very peculiar sense of logging humor? Let’s find out!

People are sometimes reading the logs. They should be taken care of (logs, not people) like any other piece of code, with readability in mind. If MF log system was following these 7 rules, maybe Star Wars wouldn’t have been the same.

Let’s assume MF’s onboard computer is in php, even if we are all convinced that it is a terrible language. $logger will be a correctly configured Monolog\Logger instance.

What are you talking about?

Try to explain what happens, making sentences and giving context. Yeah this is important. Not everyone understands what an integer means, that’s why rfc2616 HTTP status codes has a string explanation sent in the headers too.

$shieldLevel = 20;
// …should be 100 when encountering an Imperial Destroyer, right ?
// Bad
// MF - 20
// Good
$logger->info(“Shieldlevel: $shieldLevel%”);
// MF - Shieldlevel: 20%
// Even better, embedding metadata
$logger->info(“Shieldlevel: $shieldLevel%”, [‘shieldLevel’ => $shieldLevel]);

Another example if you weren’t convinced:

// Bad
$logger->info(“no hd”);
// Chewie - Brwarrga hahagh (TN, "hard drive or hyper drive?")
// Good, Subject-Verb-Complement, punctuation, thank you school!
$logger->info(“Hyperdrive reports failure, Bezel condensator is discharged”);

Do not remove information

Some habits can lead to information being truncated from the log messages.

try {
throw new \Exception(“oops”);
} catch(\Exception $e) {
// Bad
// MF - oops
    // Good
$logger->error((string) $e);
// MF - oops in Example at line:...

Causality principle

We dwell in many threads running systems, and two nearby log entries can be separated by a lot of noise

// Bad
$logger->info(“The hyperdrive just failed”);
$logger->info(“It could be related to the Bezel condensator”);

// MF - The hyperdrive just failed (thread 1)
// MF - Cargo door is open (thread 2)
// MF - Picking up weird proximity signals (thread 3)
// MF - It could be related to the Bezel condensator (thread 1)
// Han — Proximity probes are complaining about Bezel, disable it!

// Good
$logger->info(“The hyperdrive just failed, probably because of the Bezel condensator”);

Horribly wrong level

Logging levels are your very own noise/signal ratio protection. So design logs at the righteous level. Luckily, each harness has its definition, stick to it.

// Bad
$logger->debug(“Darth Vader just boarded the ship”);
$logger->emergency(“Bulb jammed in the ladies room”);

// Good
$logger->emergency(“Darth Vader just boarded the ship”);
$logger->debug(“Bulb jammed in the ladies room”);

Id is for l33t

Try to stuff your log messages with granular information when available.

// Not that bad, but…
$logger->debug(“Tie just fired”);
// MF - Tie just fired
// …Better
$logger->debug(“Tie:$tieId just fired”);
// MF - Tie:2 just fired
// Han — Chewie, target that second Tie!

If your language allows such nonsense like __toString, time to use it:

class Tie {
function __toString(){return __CLASS__.’:’.2;}

$tie = new Tie();
$logger->debug(“$tie just fired”);
// MF - Tie:2 just fired

Production var_dump

Avoid dumping big objects in the logs. See guzzle where the Exception only dumps the first 120 chars of the Request.

// Bad
$logger->debug(var_export($darkStarTrooperCollection, true));
// Good
$logger->debug(“Current count of troopers on the darkstar is “.count($darkStarTrooperCollection));

Logging superstructure

Don’t go raw file logging. You need something that aggregates your logs into one single accessible place, with powerful search and analysis tools. Since Logstash and Kibana ship in Docker containers, you really have no excuses to avoid this. If you don’t know about them, I strongly suggest having a look at it.

A good logging harness will help you too. Add helpers everywhere and make sure everyone understands it (and reads this article). For php, you can use the classic but unmissable monolog.

Most logging harnesses can add metadata to log entries. Logstash understands the type field for example, to filter/transform log entries.

And you, have you been seeing weird log entries on your ship ? Have Corellians written a piece of code for your company ? I’d love to hear a good logging story from you !

A single golf clap? Or a long standing ovation?

By clapping more or less, you can signal to us which stories really stand out.