feat: improve logging and error handling (#2994)

* feat: improve logging and error handling

* trim absolute path from file name

* fix: suppress php errors from xml parsing

* fix: respect the error reporting level in the custom error handler

* feat: dont log error which is produced by bots

* ignore error about invalid bridge name

* upgrade bridge exception from warning to error

* remove remnants of using phps builin error handler

* move responsibility of printing php error from logger to error handler

* feat: include url in log record context

* fix: always include url in log record contect

Also ignore more non-interesting exceptions.

* more verbose httpexception

* fix

* fix

actions/DisplayAction.php

@@ -35,6 +35,9 @@ class DisplayAction implements ActionInterface
             throw new \Exception('This bridge is not whitelisted');
         }
 
+        $formatFactory = new FormatFactory();
+        $format = $formatFactory->create($format);
+
         $bridge = $bridgeFactory->create($bridgeClassName);
         $bridge->loadConfiguration();
 
@@ -150,8 +153,7 @@ class DisplayAction implements ActionInterface
                     'icon' => $bridge->getIcon()
                 ];
             } catch (\Throwable $e) {
-                error_log($e);
+                Logger::error(sprintf('Exception in %s', $bridgeClassName), ['e' => $e]);
-
                 $errorCount = logBridgeError($bridge::NAME, $e->getCode());
 
                 if ($errorCount >= Configuration::getConfig('error', 'report_limit')) {
@@ -163,23 +165,10 @@ class DisplayAction implements ActionInterface
 
                         $message = sprintf('Bridge returned error %s! (%s)', $e->getCode(), $request['_error_time']);
                         $item->setTitle($message);
-
+                        $item->setURI(get_current_url());
-                        $item->setURI(
-                            (isset($_SERVER['REQUEST_URI']) ? parse_url($_SERVER['REQUEST_URI'], PHP_URL_PATH) : '')
-                            . '?'
-                            . http_build_query($request)
-                        );
-
                         $item->setTimestamp(time());
 
-                        $message = sprintf(
+                        $message = create_sane_exception_message($e);
-                            'Uncaught Exception %s: %s at %s line %s',
-                            get_class($e),
-                            $e->getMessage(),
-                            trim_path_prefix($e->getFile()),
-                            $e->getLine()
-                        );
-
                         $content = render_template('bridge-error.html.php', [
                             'message' => $message,
                             'stacktrace' => create_sane_stacktrace($e),
@@ -204,8 +193,6 @@ class DisplayAction implements ActionInterface
             ]);
         }
 
-        $formatFactory = new FormatFactory();
-        $format = $formatFactory->create($format);
         $format->setItems($items);
         $format->setExtraInfos($infos);
         $lastModified = $cache->getTime();

formats/AtomFormat.php

@@ -18,12 +18,7 @@ class AtomFormat extends FormatAbstract
 
     public function stringify()
     {
-        $https = $_SERVER['HTTPS'] ?? null;
+        $feedUrl = get_current_url();
-        $urlPrefix = $https === 'on' ? 'https://' : 'http://';
-        $urlHost = $_SERVER['HTTP_HOST'] ?? '';
-        $urlRequest = $_SERVER['REQUEST_URI'] ?? '';
-
-        $feedUrl = $urlPrefix . $urlHost . $urlRequest;
 
         $extraInfos = $this->getExtraInfos();
         if (empty($extraInfos['uri'])) {

formats/JsonFormat.php

@@ -25,18 +25,13 @@ class JsonFormat extends FormatAbstract
 
     public function stringify()
     {
-        $https = $_SERVER['HTTPS'] ?? null;
+        $host = $_SERVER['HTTP_HOST'] ?? '';
-        $urlPrefix = $https === 'on' ? 'https://' : 'http://';
-        $urlHost = $_SERVER['HTTP_HOST'] ?? '';
-        $urlRequest = $_SERVER['REQUEST_URI'] ?? '';
-
         $extraInfos = $this->getExtraInfos();
-
         $data = [
             'version' => 'https://jsonfeed.org/version/1',
-            'title' => (!empty($extraInfos['name'])) ? $extraInfos['name'] : $urlHost,
+            'title' => empty($extraInfos['name']) ? $host : $extraInfos['name'],
-            'home_page_url' => (!empty($extraInfos['uri'])) ? $extraInfos['uri'] : REPOSITORY,
+            'home_page_url' => empty($extraInfos['uri']) ? REPOSITORY : $extraInfos['uri'],
-            'feed_url' => $urlPrefix . $urlHost . $urlRequest
+            'feed_url' => get_current_url(),
         ];
 
         if (!empty($extraInfos['icon'])) {

formats/MrssFormat.php

@@ -40,13 +40,7 @@ class MrssFormat extends FormatAbstract
 
     public function stringify()
     {
-        $https = $_SERVER['HTTPS'] ?? null;
+        $feedUrl = get_current_url();
-        $urlPrefix = $https == 'on' ? 'https://' : 'http://';
-        $urlHost = $_SERVER['HTTP_HOST'] ?? '';
-        $urlRequest = $_SERVER['REQUEST_URI'] ?? '';
-
-        $feedUrl = $urlPrefix . $urlHost . $urlRequest;
-
         $extraInfos = $this->getExtraInfos();
         if (empty($extraInfos['uri'])) {
             $uri = REPOSITORY;

lib/Debug.php

@@ -73,9 +73,6 @@ class Debug
             );
 
             if (self::$enabled) {
-                ini_set('display_errors', '1');
-                error_reporting(E_ALL);
-
                 self::$secure = !empty($debug_whitelist);
             }
 
@@ -99,25 +96,18 @@ class Debug
         return self::$secure;
     }
 
-    /**
+    public static function log($message)
-     * Adds a debug message to error_log if debug mode is enabled
-     *
-     * @param string $text The message to add to error_log
-     */
-    public static function log($text)
     {
         if (!self::isEnabled()) {
             return;
         }
-
         $backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 3);
-        $calling = end($backtrace);
+        $lastFrame = end($backtrace);
-        $message = $calling['file'] . ':'
+        $file = trim_path_prefix($lastFrame['file']);
-            . $calling['line'] . ' class '
+        $line = $lastFrame['line'];
-            . ($calling['class'] ?? '<no-class>') . '->'
+        $class = $lastFrame['class'] ?? '';
-            . $calling['function'] . ' - '
+        $function = $lastFrame['function'];
-            . $text;
+        $text = sprintf('%s:%s %s->%s() %s', $file, $line, $class, $function, $message);
-
+        Logger::info($text);
-        error_log($message);
     }
 }

lib/FeedExpander.php

@@ -101,8 +101,8 @@ abstract class FeedExpander extends BridgeAbstract
         ];
         $httpHeaders = ['Accept: ' . implode(', ', $mimeTypes)];
         $content = getContents($url, $httpHeaders);
-        $rssContent = simplexml_load_string(trim($content));
+        // Suppress php errors. We will check return value for success.
-
+        $rssContent = @simplexml_load_string(trim($content));
         if ($rssContent === false) {
             throw new \Exception(sprintf('Unable to parse xml from "%s"', $url));
         }

lib/FeedItem.php

@@ -164,7 +164,7 @@ class FeedItem
                 FILTER_FLAG_PATH_REQUIRED
             )
         ) {
-            Debug::log('URI must include a scheme, host and path!');
+            Debug::log(sprintf('Not a valid url: "%s"', $uri));
         } else {
             $scheme = parse_url($uri, PHP_URL_SCHEME);
 

lib/Logger.php

@@ -0,0 +1,54 @@
+<?php
+
+declare(strict_types=1);
+
+final class Logger
+{
+    public static function info(string $message, array $context = []): void
+    {
+        self::log('INFO', $message, $context);
+    }
+
+    public static function warning(string $message, array $context = []): void
+    {
+        self::log('WARNING', $message, $context);
+    }
+
+    public static function error(string $message, array $context = []): void
+    {
+        self::log('ERROR', $message, $context);
+    }
+
+    private static function log(string $level, string $message, array $context = []): void
+    {
+        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']);
+            unset($context['e']);
+            $ignoredExceptions = [
+                'Exception Exception: You must specify a format!',
+                'Exception InvalidArgumentException: Format name invalid!',
+                'Exception InvalidArgumentException: Unknown format given!',
+                'Exception InvalidArgumentException: Bridge name invalid!',
+            ];
+            foreach ($ignoredExceptions as $ignoredException) {
+                if (str_starts_with($context['message'], $ignoredException)) {
+                    // Don't log this record because it's usually a bot
+                    return;
+                }
+            }
+        }
+        $text = sprintf(
+            "[%s] rssbridge.%s %s %s\n",
+            now()->format('Y-m-d H:i:s'),
+            $level,
+            $message,
+            $context ? Json::encode($context) : ''
+        );
+        error_log($text);
+    }
+}

lib/RssBridge.php

@@ -14,17 +14,10 @@ final class RssBridge
         try {
             $this->run($request);
         } catch (\Throwable $e) {
-            error_log($e);
+            Logger::error('Exception in main', ['e' => $e]);
-            $message = sprintf(
-                'Uncaught Exception %s: %s at %s line %s',
-                get_class($e),
-                $e->getMessage(),
-                trim_path_prefix($e->getFile()),
-                $e->getLine()
-            );
             http_response_code(500);
             print render('error.html.php', [
-                'message' => $message,
+                'message' => create_sane_exception_message($e),
                 'stacktrace' => create_sane_stacktrace($e),
             ]);
         }
@@ -40,6 +33,17 @@ final class RssBridge
         }
         Configuration::loadConfiguration($customConfig, getenv());
 
+        set_error_handler(function ($code, $message, $file, $line) {
+            if ((error_reporting() & $code) === 0) {
+                return false;
+            }
+            $text = sprintf('%s at %s line %s', $message, trim_path_prefix($file), $line);
+            Logger::warning($text);
+            if (Debug::isEnabled()) {
+                print sprintf('<pre>%s</pre>', $text);
+            }
+        });
+
         date_default_timezone_set(Configuration::getConfig('system', 'timezone'));
 
         $authenticationMiddleware = new AuthenticationMiddleware();

lib/contents.php

@@ -12,6 +12,7 @@ const RSSBRIDGE_HTTP_STATUS_CODES = [
     '205' => 'Reset Content',
     '206' => 'Partial Content',
     '300' => 'Multiple Choices',
+    '301' => 'Moved Permanently',
     '302' => 'Found',
     '303' => 'See Other',
     '304' => 'Not Modified',
@@ -136,7 +137,8 @@ function getContents(
         default:
             throw new HttpException(
                 sprintf(
-                    '%s %s',
+                    '%s resulted in `%s %s`',
+                    $url,
                     $result['code'],
                     RSSBRIDGE_HTTP_STATUS_CODES[$result['code']] ?? ''
                 ),
@@ -231,7 +233,13 @@ function _http_request(string $url, array $config = []): array
         }
         if ($attempts > $config['retries']) {
             // Finally give up
-            throw new HttpException(sprintf('%s (%s)', curl_error($ch), curl_errno($ch)));
+            throw new HttpException(sprintf(
+                'cURL error %s: %s (%s) for %s',
+                curl_error($ch),
+                curl_errno($ch),
+                'https://curl.haxx.se/libcurl/c/libcurl-errors.html',
+                $url
+            ));
         }
     }
 

lib/utils.php

@@ -19,13 +19,13 @@ final class Json
 }
 
 /**
- * Returns e.g. 'https://example.com/' or 'https://example.com/bridge/'
+ * Get the home page url of rss-bridge e.g. 'https://example.com/' or 'https://example.com/bridge/'
  */
 function get_home_page_url(): string
 {
-    $https = $_SERVER['HTTPS'] ?? null;
+    $https = $_SERVER['HTTPS'] ?? '';
-    $host = $_SERVER['HTTP_HOST'] ?? null;
+    $host = $_SERVER['HTTP_HOST'] ?? '';
-    $uri = $_SERVER['REQUEST_URI'] ?? null;
+    $uri = $_SERVER['REQUEST_URI'] ?? '';
     if (($pos = strpos($uri, '?')) !== false) {
         $uri = substr($uri, 0, $pos);
     }
@@ -33,6 +33,29 @@ function get_home_page_url(): string
     return "$scheme://$host$uri";
 }
 
+/**
+ * Get the full current url e.g. 'http://example.com/?action=display&bridge=FooBridge'
+ */
+function get_current_url(): string
+{
+    $https = $_SERVER['HTTPS'] ?? '';
+    $host = $_SERVER['HTTP_HOST'] ?? '';
+    $uri = $_SERVER['REQUEST_URI'] ?? '';
+    $scheme = $https === 'on' ? 'https' : 'http';
+    return "$scheme://$host$uri";
+}
+
+function create_sane_exception_message(\Throwable $e): string
+{
+    return sprintf(
+        'Exception %s: %s at %s line %s',
+        get_class($e),
+        $e->getMessage(),
+        trim_path_prefix($e->getFile()),
+        $e->getLine()
+    );
+}
+
 function create_sane_stacktrace(\Throwable $e): array
 {
     $frames = array_reverse($e->getTrace());
@@ -40,18 +63,18 @@ function create_sane_stacktrace(\Throwable $e): array
         'file' => $e->getFile(),
         'line' => $e->getLine(),
     ];
-    $stackTrace = [];
+    $trace = [];
     foreach ($frames as $i => $frame) {
         $file = $frame['file'] ?? '(no file)';
         $line = $frame['line'] ?? '(no line)';
-        $stackTrace[] = sprintf(
+        $trace[] = sprintf(
             '#%s %s:%s',
             $i,
             trim_path_prefix($file),
             $line,
         );
     }
-    return $stackTrace;
+    return $trace;
 }
 
 /**
@@ -151,3 +174,8 @@ function format_bytes(int $bytes, $precision = 2)
 
     return round($bytes, $precision) . ' ' . $units[$pow];
 }
+
+function now(): \DateTimeImmutable
+{
+    return new \DateTimeImmutable();
+}