Debugging and Logs

8 Aufrufe Markdown

Find out what actually happened: where failures are recorded and how to read them from a shell. A silent page is usually a caught error rather than a missing one.

Overview

Failures do not print themselves. They go through one handler that decides what the caller sees. That is an HTML error page, a JSON error body, or nothing at all when the diagnostics are off. In every case the failure is written to the error log, and the log is what you read.

The absence of a message on screen tells you almost nothing; the log tells you everything.

Prerequisites

  • The diagnostics switched on for the installation you work against.
  • Shell access to the same PHP the site runs on. The tool answers 404 over HTTP; it is command line only.

Walkthrough

Start with the Overview

  1. Run php coremio/errlog.php stats.
  2. Read the fatal and error counts, and the last twenty-four hours. A number that jumped is where to look.
  3. If the command prints nothing useful, logging is off or the storage directory is not writable. Fix that first.

Find the Failure

  1. List recent entries with php coremio/errlog.php list --limit=10, or narrow with --level=FATAL.
  2. Each entry carries a signature, a count, a file and line, and when it was last seen.
  3. Open one with php coremio/errlog.php show <signature>: the full record has the request and the stack.

Follow a Reported Identifier

  1. A failure that surfaces to a user or an API caller carries an error identifier.
  2. Look it up with php coremio/errlog.php find <identifier>.
  3. You get the exact record for that occurrence, which makes a user report actionable.

Reference

One entry point, eight commands. Arguments are positional and options are --name=value in any order. An option the command does not read is ignored.

CommandArgumentOptionsWhat it does
helpnonenoneThe command list. Also the default, and the answer to -h.
statsnonenoneTotals by level and type, plus the last twenty-four hours.
listnone--level --type --limit --offset --fileEntries from the manifest, newest sighting first, one signature per row.
finderror identifiernoneScans every log file for that identifier and prints the record. Exit code 1 when nothing matches.
showsignaturenoneDecrypts and dumps one entry in full: request, message, context, stack, POST body.
deletesignature--forceRemoves one log file and its manifest row. Prompts unless forced.
cleanupnone--days --forceDeletes files older than N days, in both log types. Prompts unless forced.
rebuildnonenoneRe-indexes every log file into a fresh manifest, after files are copied in or removed by hand.

The two positional arguments are not interchangeable. A signature is the 32 character fingerprint of a call site, printed under every list row. An error identifier is the short code shown to whoever hit the failure. Both are matched case insensitively, and passing one where the other belongs fails the format check.

Options

--level=NAME One of FATAL, ERROR, WARNING, INFO, DEBUG, DEPRECATED. Case does not matter. One level per run.
--type=NAME system or database. The two are stored separately and stats counts them separately.
--limit=N How many rows to print. Default 20, floored at 1.
--offset=N How many rows to skip, for paging. Default 0.
--file=PATTERN Case insensitive substring of the recorded path, not a glob. A directory fragment narrows a whole subsystem.
--days=N Retention for cleanup, in days. Default 30; below 1 stops the command.
--force Skips the confirmation on delete and cleanup.

The Side That Writes

Everything the CLI reads was written through these two classes. Both write methods return the error identifier that find takes back.

signatures
// coremio/classes/MioException.php
public static function getInstance(): MioException;
public function logError(string $message, array $context = [], string $level = 'ERROR', string $type = 'system'): string;
public function logDatabaseError(string $query, string $error, array $params = []): string;
public function sanitizeData(array $data): array;

// coremio/classes/Logger.php
public function log(string $level, string $message, array $context = [], string $type = 'system'): string;
public static function stats(): array;
public static function entries(array $filters = [], int $start = 0, int $limit = 50, array $sort = []): array;
public static function entriesCount(array $filters = []): int;
public static function cleanup(int $daysToKeep = 30, ?int $cutoffTimestamp = null, string $type = 'system'): int;
public static function deleteOne(string $signature): bool;
public static function rebuild(): int;

The filter array behind list accepts more than the CLI exposes. An unknown key is ignored, so a typo silently widens the result instead of narrowing it.

Filter keyValueMatch
levelsarray of level namesexact, uppercased
typesarray of system or databaseexact
signaturestringsubstring
filestringsubstring, case insensitive
messagestringsubstring of the stored preview
exception_classstringsubstring
request_uristringsubstring
http_methodGET, POST and so onexact, uppercased
user_idintexact, ignored when 0
ipstringsubstring
min_occurrenceintcount at or above
start_datetime / end_datetimeanything the date parser acceptswindow on the last sighting

The sort array is ['field' => 'last_seen', 'order' => 'desc']. Useful fields: last_seen, first_seen, count and level, where sorting is by severity rather than alphabet.

How a Failure Surfaces

RequestDiagnostics onDiagnostics off
Normal page, fatalError page with detailGeneric error page
Normal page, non-fatalNotice on the pageNothing visible
AJAX or APIJSON error with detailJSON error with an identifier
Hook listenerCaught and logged; the flow continues either way
Command lineWritten to the log; the output buffer may hide the message

Example

shell
# Health first: is anything failing at all?
php coremio/errlog.php stats

# The five most recent fatals
php coremio/errlog.php list --level=FATAL --limit=5

# Only what came out of one subsystem, second page of ten
php coremio/errlog.php list --file=modules/Servers --limit=10 --offset=10

# Only database failures
php coremio/errlog.php list --type=database --limit=5

# The full record for one signature
php coremio/errlog.php show f05bc1f49d2963a58a7c378dc3430c48

# A user reported an error identifier; look up that exact occurrence
php coremio/errlog.php find 25EE72D6527

# Drop one signature once it is fixed, and trim the rest to a week
php coremio/errlog.php delete f05bc1f49d2963a58a7c378dc3430c48 --force
php coremio/errlog.php cleanup --days=7 --force

# Re-index after log files were moved or removed by hand
php coremio/errlog.php rebuild

The same records from PHP. The identifier returned by the write is what the CLI reads back.

write, then read
// Write: returns the identifier you would hand to `errlog.php find`.
$id = MioException::getInstance()->logError(
    'Provisioning refused by the panel',
    ['service_id' => 41, 'response' => $body],
    Logger::LEVEL_ERROR,
    Logger::TYPE_SYSTEM
);

// Read: the same rows `errlog.php list` prints.
$rows = Logger::entries(
    ['levels' => [Logger::LEVEL_FATAL], 'file' => 'modules/Servers'],
    0,
    10,
    ['field' => 'count', 'order' => 'desc']
);

foreach ($rows as $row)
    echo $row['signature'], '  x', (int) ($row['count'] ?? 1), '  ',
         $row['file'] ?? '-', ':', (int) ($row['line'] ?? 0), '  ',
         $row['message_preview'] ?? '', PHP_EOL;

// Aggregates: total, system, database, fatal, error, warning, info,
// last_24h, occurrences, and recent[] broken down by level.
$health = Logger::stats();

Pitfalls

A silent command line is not a successful one

An output buffer is installed during startup, so a message written to standard output can disappear. Write diagnostics to standard error, and check the log before believing a script did nothing wrong.

Every warning costs a disk write

The handler records non-fatal warnings too, so a missing array key read inside a loop turns into one write per iteration. Read values with a default.

Without --force the destructive commands wait for an answer

delete and cleanup read a yes or no from the terminal. In a scheduled job or a piped shell there is nobody to answer, so the command blocks or does nothing. Pass the option deliberately.

A high occurrence count can be a single page load

Entries are grouped by signature and counted. When the first and last sighting are the same moment, the line ran many times in one request. That is the fingerprint of a warning inside a loop.

War das hilfreich?

Vielen Dank für Ihre Rückmeldung!

Brauchen Sie weitere Hilfe?

Unser Support-Team ist rund um die Uhr für Sie da, wenn Sie oben nicht fündig werden.