Improve logging and error handling (#3059)

* refactor: logging and errror handling

actions/DisplayAction.php

@@ -163,18 +163,17 @@ class DisplayAction implements ActionInterface
                         // Create "new" error message every 24 hours
                         $request['_error_time'] = urlencode((int)(time() / 86400));
 
-                        $message = sprintf('Bridge returned error %s! (%s)', $e->getCode(), $request['_error_time']);
+                        $itemTitle = sprintf('Bridge returned error %s! (%s)', $e->getCode(), $request['_error_time']);
-                        $item->setTitle($message);
+                        $item->setTitle($itemTitle);
                         $item->setURI(get_current_url());
                         $item->setTimestamp(time());
 
-                        $message = create_sane_exception_message($e);
+                        $content = render_template(__DIR__ . '/../templates/bridge-error.html.php', [
-                        $content = render_template('bridge-error.html.php', [
+                            'message' => create_sane_exception_message($e),
-                            'message' => $message,
+                            'trace' => trace_from_exception($e),
-                            'stacktrace' => create_sane_stacktrace($e),
                             'searchUrl' => self::createGithubSearchUrl($bridge),
-                            'issueUrl' => self::createGithubIssueUrl($bridge, $e, $message),
+                            'issueUrl' => self::createGithubIssueUrl($bridge, $e, create_sane_exception_message($e)),
-                            'bridge' => $bridge,
+                            'maintainer' => $bridge->getMaintainer(),
                         ]);
                         $item->setContent($content);
 
@@ -211,7 +210,7 @@ class DisplayAction implements ActionInterface
             'body' => sprintf(
                 "```\n%s\n\n%s\n\nQuery string: %s\nVersion: %s\nOs: %s\nPHP version: %s\n```",
                 $message,
-                implode("\n", create_sane_stacktrace($e)),
+                implode("\n", trace_to_call_points(trace_from_exception($e))),
                 $_SERVER['QUERY_STRING'] ?? '',
                 Configuration::getVersion(),
                 PHP_OS_FAMILY,

bridges/PatreonBridge.php

@@ -19,7 +19,8 @@ class PatreonBridge extends BridgeAbstract
 
     public function collectData()
     {
-        $html = getSimpleHTMLDOMCached($this->getURI(), 86400);
+        $url = $this->getURI();
+        $html = getSimpleHTMLDOMCached($url);
         $regex = '#/api/campaigns/([0-9]+)#';
         if (preg_match($regex, $html->save(), $matches) > 0) {
             $campaign_id = $matches[1];

lib/AuthenticationMiddleware.php

@@ -20,7 +20,7 @@ final class AuthenticationMiddleware
         $password = $_SERVER['PHP_AUTH_PW'] ?? null;
 
         if ($user === null || $password === null) {
-            $this->renderAuthenticationDialog();
+            print $this->renderAuthenticationDialog();
             exit;
         }
         if (
@@ -29,14 +29,14 @@ final class AuthenticationMiddleware
         ) {
             return;
         }
-        $this->renderAuthenticationDialog();
+        print $this->renderAuthenticationDialog();
         exit;
     }
 
-    private function renderAuthenticationDialog(): void
+    private function renderAuthenticationDialog(): string
     {
         http_response_code(401);
         header('WWW-Authenticate: Basic realm="RSS-Bridge"');
-        print render('error.html.php', ['message' => 'Please authenticate in order to access this instance !']);
+        return render('access-denied.html.php');
     }
 }

lib/Debug.php

@@ -101,13 +101,12 @@ class Debug
         if (!self::isEnabled()) {
             return;
         }
-        $backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 3);
+        $e = new \Exception();
-        $lastFrame = end($backtrace);
+        $trace = trace_from_exception($e);
-        $file = trim_path_prefix($lastFrame['file']);
+        // Drop the current frame
-        $line = $lastFrame['line'];
+        array_pop($trace);
-        $class = $lastFrame['class'] ?? '';
+        $lastFrame = $trace[array_key_last($trace)];
-        $function = $lastFrame['function'];
+        $text = sprintf('%s(%s): %s', $lastFrame['file'], $lastFrame['line'], $message);
-        $text = sprintf('%s:%s %s->%s() %s', $file, $line, $class, $function, $message);
+        Logger::debug($text);
-        Logger::info($text);
     }
 }

lib/FormatFactory.php

@@ -38,11 +38,11 @@ class FormatFactory
         if (! preg_match('/^[a-zA-Z0-9-]*$/', $name)) {
             throw new \InvalidArgumentException('Format name invalid!');
         }
-        $name = $this->sanitizeFormatName($name);
+        $sanitizedName = $this->sanitizeFormatName($name);
-        if ($name === null) {
+        if ($sanitizedName === null) {
-            throw new \InvalidArgumentException('Unknown format given!');
+            throw new \InvalidArgumentException(sprintf('Unknown format given `%s`', $name));
         }
-        $className = '\\' . $name . 'Format';
+        $className = '\\' . $sanitizedName . 'Format';
         return new $className();
     }
 

lib/Logger.php

@@ -4,6 +4,11 @@ declare(strict_types=1);
 
 final class Logger
 {
+    public static function debug(string $message, array $context = [])
+    {
+        self::log('DEBUG', $message, $context);
+    }
+
     public static function info(string $message, array $context = []): void
     {
         self::log('INFO', $message, $context);
@@ -23,22 +28,20 @@ final class Logger
     {
         if (isset($context['e'])) {
             $context['message'] = create_sane_exception_message($context['e']);
-            $context['file'] = trim_path_prefix($context['e']->getFile());
-            $context['line'] = $context['e']->getLine();
             $context['code'] = $context['e']->getCode();
             $context['url'] = get_current_url();
-            $context['trace'] = create_sane_stacktrace($context['e']);
+            $context['trace'] = trace_to_call_points(trace_from_exception($context['e']));
             unset($context['e']);
+            // Don't log these records
             $ignoredExceptions = [
-                'Exception Exception: You must specify a format!',
+                'Exception Exception: You must specify a format',
-                'Exception InvalidArgumentException: Format name invalid!',
+                'Exception InvalidArgumentException: Format name invalid',
-                'Exception InvalidArgumentException: Unknown format given!',
+                'Exception InvalidArgumentException: Unknown format given',
-                'Exception InvalidArgumentException: Bridge name invalid!',
+                'Exception InvalidArgumentException: Bridge name invalid',
                 'Exception Exception: twitter: No results for this query',
             ];
             foreach ($ignoredExceptions as $ignoredException) {
                 if (str_starts_with($context['message'], $ignoredException)) {
-                    // Don't log this record because it's usually a bot
                     return;
                 }
             }

lib/RssBridge.php

@@ -16,9 +16,9 @@ final class RssBridge
         } catch (\Throwable $e) {
             Logger::error('Exception in main', ['e' => $e]);
             http_response_code(500);
-            print render('error.html.php', [
+            print render(__DIR__ . '/../templates/error.html.php', [
-                'message' => create_sane_exception_message($e),
+                'message'   => create_sane_exception_message($e),
-                'stacktrace' => create_sane_stacktrace($e),
+                'trace'     => trace_from_exception($e),
             ]);
         }
     }
@@ -38,6 +38,7 @@ final class RssBridge
                 return false;
             }
             $text = sprintf('%s at %s line %s', $message, trim_path_prefix($file), $line);
+            // Drop the current frame
             Logger::warning($text);
             if (Debug::isEnabled()) {
                 print sprintf('<pre>%s</pre>', $text);

lib/html.php

@@ -14,6 +14,9 @@
 
 function render(string $template, array $context = []): string
 {
+    if ($template === 'base.html.php') {
+        throw new \Exception('Do not render base.html.php into itself');
+    }
     $context['page'] = render_template($template, $context);
     return render_template('base.html.php', $context);
 }

lib/utils.php

@@ -48,7 +48,7 @@ function get_current_url(): string
 function create_sane_exception_message(\Throwable $e): string
 {
     return sprintf(
-        'Exception %s: %s at %s line %s',
+        'Exception %s: %s in %s line %s',
         get_class($e),
         $e->getMessage(),
         trim_path_prefix($e->getFile()),
@@ -56,7 +56,15 @@ function create_sane_exception_message(\Throwable $e): string
     );
 }
 
-function create_sane_stacktrace(\Throwable $e): array
+/**
+ * Returns e.g. https://github.com/RSS-Bridge/rss-bridge/blob/master/bridges/AO3Bridge.php#L8
+ */
+function render_github_url(string $file, int $line, string $revision = 'master'): string
+{
+    return sprintf('https://github.com/RSS-Bridge/rss-bridge/blob/%s/%s#L%s', $revision, $file, $line);
+}
+
+function trace_from_exception(\Throwable $e): array
 {
     $frames = array_reverse($e->getTrace());
     $frames[] = [
@@ -64,19 +72,50 @@ function create_sane_stacktrace(\Throwable $e): array
         'line' => $e->getLine(),
     ];
     $trace = [];
-    foreach ($frames as $i => $frame) {
+    foreach ($frames as $frame) {
-        $file = $frame['file'] ?? '(no file)';
+        $trace[] = [
-        $line = $frame['line'] ?? '(no line)';
+            'file'      => trim_path_prefix($frame['file'] ?? ''),
-        $trace[] = sprintf(
+            'line'      => $frame['line'] ?? null,
-            '#%s %s:%s',
+            'class'     => $frame['class'] ?? null,
-            $i,
+            'type'      => $frame['type'] ?? null,
-            trim_path_prefix($file),
+            'function'  => $frame['function'] ?? null,
-            $line,
+        ];
-        );
     }
     return $trace;
 }
 
+function trace_to_call_points(array $trace): array
+{
+    return array_map(fn($frame) => frame_to_call_point($frame), $trace);
+}
+
+function frame_to_call_point(array $frame): string
+{
+    if ($frame['class']) {
+        return sprintf(
+            '%s(%s): %s%s%s()',
+            $frame['file'],
+            $frame['line'],
+            $frame['class'],
+            $frame['type'],
+            $frame['function'],
+        );
+    } elseif ($frame['function']) {
+        return sprintf(
+            '%s(%s): %s()',
+            $frame['file'],
+            $frame['line'],
+            $frame['function'],
+        );
+    } else {
+        return sprintf(
+            '%s(%s)',
+            $frame['file'],
+            $frame['line'],
+        );
+    }
+}
+
 /**
  * Trim path prefix for privacy/security reasons
  *

static/style.css

@@ -50,6 +50,12 @@ a:hover {
 	text-decoration: underline;
 }
 
+h1,h2 {
+	margin-bottom: 10px;
+}
+p {
+	margin-bottom: 10px;
+}
 /* Header */
 
 header {
@@ -328,12 +334,6 @@ h5 {
 	margin-bottom: 6px;
 }
 
-.advice {
-	margin-left: auto;
-	margin-right: auto;
-	display: table;
-}
-
 .advice > li {
 	text-align: left;
 }

templates/access-denied.html.php

@@ -0,0 +1,6 @@
+<section>
+    <h1>
+        Please authenticate in order to access this instance
+    </h1>
+</section>
+

templates/bridge-error.html.php

@@ -1,21 +1,17 @@
 <section>
     <p class="exception-message">
-        <?= e($message ?? '') ?>
+        <?= e($message) ?>
     </p>
 
-    <?php if (isset($stacktrace)): ?>
+    <?php foreach ($trace as $i => $frame) : ?>
-        <?php foreach ($stacktrace as $frame): ?>
+        #<?= $i ?> <?= e(frame_to_call_point($frame)) ?>
-            <code>
+        <br>
-                <?= e($frame) ?>
+    <?php endforeach; ?>
-            </code>
-            <br>
-        <?php endforeach; ?>
-    <?php endif; ?>
 
     <br>
 
     <p>
-        Query string: <?= e($_SERVER['QUERY_STRING'] ?? '') ?>
+        Query string: <?= e(urldecode($_SERVER['QUERY_STRING']) ?? '') ?>
     </p>
     <p>
         Version: <?= raw(Configuration::getVersion()) ?>
@@ -24,26 +20,19 @@
         OS: <?= raw(PHP_OS_FAMILY) ?>
     </p>
     <p>
-        PHP version: <?= raw(phpversion() ?: 'Unknown'()) ?>
+        PHP version: <?= raw(PHP_VERSION ?: 'Unknown') ?>
     </p>
 
-    <div class="advice">
-        <ul class="advice">
-            <li>Press Return to check your input parameters</li>
-            <li>Press F5 to retry</li>
-            <li>Check if this issue was already reported on <a href="<?= raw($searchUrl) ?>">GitHub</a> (give it a thumbs-up)</li>
-            <li>Open a <a href="<?= raw($issueUrl) ?>">GitHub Issue</a> if this error persists</li>
-        </ul>
-    </div>
-
     <a href="<?= raw($searchUrl) ?>" title="Opens GitHub to search for similar issues">
-        <button>Search GitHub Issues</button>
+        <button>Find similar bugs</button>
     </a>
 
     <a href="<?= raw($issueUrl) ?>" title="After clicking this button you can review the issue before submitting it">
-        <button>Open GitHub Issue</button>
+        <button>Create GitHub Issue</button>
     </a>
 
-    <p class="maintainer"><?= e($bridge->getMaintainer()) ?></p>
+    <p class="maintainer">
+        <?= e($maintainer) ?>
+    </p>
 </section>
 

templates/error.html.php

@@ -1,25 +1,35 @@
 <div style="width: 60%; margin: 30px auto">
 
-    <h1>
+    <h1>Something went wrong</h1>
-        <?= e($title ?? 'Something went wrong') ?>
-    </h1>
 
-    <br>
+    <p>
-    <?= e($message) ?>
+        <?= e($message) ?>
-    <br>
+    </p>
-    <br>
 
-    <?php if (isset($stacktrace)): ?>
+    <h2>Stacktrace</h2>
-        <h2>Stacktrace</h2>
+
+    <?php foreach ($trace as $i => $frame) : ?>
+        <code>
+            #<?= $i ?> <?= e(frame_to_call_point($frame)) ?>
+        </code>
         <br>
+    <?php endforeach; ?>
 
-        <?php foreach ($stacktrace as $frame) : ?>
+    <br>
-            <code>
-                <?= e($frame) ?>
-            </code>
-            <br>
-        <?php endforeach; ?>
-    <?php endif; ?>
 
+    <h2>Context</h2>
+
+    <p>
+        Query string: <?= e(urldecode($_SERVER['QUERY_STRING'] ?? '')) ?>
+    </p>
+    <p>
+        Version: <?= raw(Configuration::getVersion()) ?>
+    </p>
+    <p>
+        OS: <?= raw(PHP_OS_FAMILY) ?>
+    </p>
+    <p>
+        PHP version: <?= raw(PHP_VERSION ?: 'Unknown') ?>
+    </p>
 </div>