Why the falcon millenium's always broken?

Updated
En français : Pourquoi le Faucon Millenium ne passe jamais en hyperespace ?

What’s broken?

… or how to improve your logs with these 7 rules

Millenium falcon never wants to jump to hyperspace, unless r2d2 fixes it for you. How happen that even infamous Han Solo struggles to understand his spaceship? Is it because the Corellian have a very peculiar sense of logging humor? Let’s find out.

Let me illustrate this with some php examples, even if we are all convinced that it is a terrible language.

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 harness can add metadata to log entries. Logstash for example understand the type field to filter/transform log entries.

In the incoming examples, $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 mean, that’s why rfc2616 HTTP status codes has a string explanation sent in the headers too for example.

$shieldLevel = 20; // ...should be 100 when encountering an Imperial Star Destroyer 
// Bad
$logger->info($shieldLevel); // "20"

// Good
$logger->info("Shieldlevel: $shieldLevel%"); // "Shieldlevel: 20%"
// Even better, but watch out for context spam
$logger->info("Shieldlevel: $shieldLevel%", ['shieldLevel' => $shieldLevel]); // Same, but not same

Another example if you weren’t convinced:

// Bad
$logger->info("no hd"); // 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
    $logger->error($e->getMessage()); // "oops"
    
    // Good
    $logger->error((string) $e); // "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");

// "The hyperdrive just failed" (thread 1)
// "Cargo door is open" (thread 2)
// "Picking up weird hyperspace signals" (thread 3)
// "It could be related to the Bezel condensator" (thread 1)
// - Chewie, hyperspace probes are complaining about Bezel, disable it!...
// ... Hey why that thing don't go hyperspace?

// 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("Dark Vador just boarded the falcon");
$logger->emergency("Bulb jammed in the ladies room");

// Good
$logger->emergency("Dark Vador just boarded the falcon");
$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"); // Tie just fired
// ...Better
$logger->debug("Tie:$tieId just fired."); // Tie:2 just fired
// - 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"); // 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));