Incident investigation with Logs

Incident investigation becomes fairly straight forward when your application matches these 2 conditions: 1) Every PHP process captures relevant information (preferably into logs) regarding what’s happening, 2) In case of error, PHP process exposes a unique ID, which binds all the current process logs together.

Given that you have completed a basic setup with Phplogger (https://blog.phplogger.com/2019/07/15/error-collection-via-phplogger/), you would have a $logger object available to collect logs.

Let’s imagine we have a simple application which displays a list of most relevant books for an authorized user. We’ve implemented basic logging and track most of the events from the page. We even log the SQL we use to select list of books.

<?php
# include basic setup
include __DIR__ . '/bootstrap.php';
# authentication check
if (empty($_SESSION['user_auth']) === true) {
    $logger->warning('Unauthorized user. Redirecting to login page.');
    header('Location: /login.php');
    exit;
}
$logger->info('Page view', 
    ['page' => 'index.php', 'user' => $_SESSION['user_auth']]);
# log SQL statement
$select = 'SELECT id, title, description, author FROM books ORDER BY relevance LIMIT 30';
$logger->info($select);
# perform SQL statement
$PDO = new PDO("mysql:host=localhost;dbname=mydb", "user12", "12user");
$statement = $PDO->query($select);
$statement->setFetchMode(PDO::FETCH_ASSOC);
$list = $statement->execute();
# log the results
$logger->info('Books displayed', ['amount' => count($list)]);
?>
<!--Display list of books-->
<table>
    <tr>
        <th>Title</th>
        <th>Description</th>
        <th>Author</th>
        <th></th>
    </tr>
<?php foreach($list as $item) : ?>
    <tr>
        <td><?=$item['title'];?></td>
        <td><?=$item['description'];?></td>
        <td><?=$item['author'];?></td>
        <td><a href="view.php?id=<?=$item['id'];?>">view</a></td>
    </tr>
<?php endforeach; ?>
</table>

If everything works as expected – the person sees the list of books in a pretty table. The results of the logged information in Log Stream should look similar to this

Log Stream for the given code snippet

Default Phplogger setup supports automatic incident logging as well. Imagine that for a short time period our database is not available and PDO throws an exception. The unhandled exception would create a fatal error and terminate the script execution.

The database unavailable error would be captured by Phplogger and you would find an “error” in your Log Stream. You will be able to investigate what’s happening and take action.

Log Stream with Database error

Your users, on the other hand, would be left in the dark. Unhandled exceptions result in a default Apache / Ngnix messages or event blank pages. Who should user contact in case he/she encounters the blank page? What if the user would like a follow up?

The solution would be to handle all the exceptions with a try / catch, because then you can define what the user actually sees. The database query part of the above code should be changed to this.

# perform SQL statement
$list = [];
try {
    $PDO = new PDO("mysql:host=localhost;dbname=mydb", "user12", "12user");
    $statement = $PDO->query($select);
    $statement->setFetchMode(PDO::FETCH_ASSOC);
    $list = $statement->execute();
} catch (\Throwable $exception) {
    # log the exception with Phplogger formatting
    $loggable = \PhpLogger\Format\Format::createFromException($exception);
    $logger->critical($loggable->toString(), $loggable->toArray());
    # display error message
    echo sprintf(
            'Unexpected error happened. <br>Please contact our support (<b>%s</b>) and provide them with error ID <b>"%s"</b>.',
            'support@support.com',
        (string) $logger
    );
    exit;
}

You will get the same error with the same information in Phplogger. Your users, on the other hand, will get the proper error message, with an option to track the incident.

Incident information for the User

In Phplogger interface, you can use “Jump to process ID” functionality to open logs for the exact process that crushed for the user – “pvcfp3.gbh88.15.0“.