LSlog: log PHP error suppressed with the @-operator at TRACE level and add a prefix to signal it

doc/src/conf/global/LSlog.md

@@ -6,6 +6,9 @@ Cette section décrit le tableau de configuration de la journalisation de l'appl
 $GLOBALS['LSlog'] = array(
   'enable' => [booléen],
   'level' => '[niveau]',
+  'log_errors_context' => [booléen],
+  'log_errors_context_with_args' => [booléen],
+  'log_errors_context_args_max_length' => [entier],
   'handlers' => array(
     '[handler 1]',
     array (
@@ -53,6 +56,23 @@ $GLOBALS['LSlog'] = array(
   - `ERROR`
   - `FATAL`
 
+- `log_errors_context`
+
+  Booléen permatant de définir si le contexte _(=backtrace)_ doit être inclus lors de la
+  journalisation d'une erreurs.
+
+- `log_errors_context_with_args`
+
+  Booléen permatant de définir si les arguments des méthodes/fonctions appelées doivent être
+  inclus lors de la journalisation du contexte des erreurs.
+  __Note :__ ce paramètre n'as aucun effet si le paramètre `log_errors_context` n'est pas activé.
+
+- `log_errors_context_args_max_length`
+
+  Ce paramètre permet de définir à partir de quelle longueur les arguments des méthodes/fonctions
+  appelées et journalisés seront tronqués (par défaut : `1000`). __Note :__ pour désactiver le
+  troncage, mettre ce paramètre à zéro.
+
 - `handlers`
 
   Tableau permettant de configurer les *handlers* de la journalisation. Chaque *handler* gère les

src/conf/config.inc.php

@@ -204,60 +204,80 @@ define('LS_CSS_DIR', 'css');
 define('LSdebug',false);
 
 // Logging
-$GLOBALS['LSlog']['handlers'] = array (
+$GLOBALS['LSlog'] = array (
-  array (
+  // Enable/disable logs
-    'handler' => 'file',
+  'enable' => true,
-    'path' => 'tmp/LS.log',
+
-    //'level' => 'DEBUG',
+  // Global logs level (TRACE, DEBUG, INFO, WARNING, ERROR, FATAL)
-    //'enabled' => false, // Uncomment to disable this handler
+  'level' => 'INFO',
-    // Filter on specific loggers
+
-    //'loggers' => array('LSurl', 'LSlang'),
+  // Log errors's context (=backtrace, default: false)
-    'excluded_loggers' => array('generate_lang_file', 'generate_ldapsaisie_pot'),
+  'log_errors_context' => true,
-    // Default formats
+
-    //'format' => '%{requesturi} - %{remoteaddr} - %{ldapservername} - %{authuser} - %{level} - %{message}',
+  // Log errors's context with arguments of called method/functions (default: false)
-    //'cli_format' => '%{clibinpath} - %{level} - %{message}',
+  // 'log_errors_context_with_args' => false,
-    //'datetime_prefix' => true,            // Prefix message with datetime ?
+
-    //'datetime_format' => 'Y/m/d H:i:s',   // Datetime prefix format (see php date() function)
+  // Truncate logged arguments in errors's context (default: 1000)
+  // 'log_errors_context_args_max_length' => 1000,
+
+  /**
+   * Logs handlers are components that logged message emitted by the application.
+   * Each handlers handle emitted message as its own way (storing it in file/database, send it via
+   * email or to an external backend, ...).
+   */
+  'handlers' => array (
+    array(
+      'handler' => 'file',
+      'path' => 'tmp/LS.log',
+      //'level' => 'DEBUG',
+      //'enabled' => false, // Uncomment to disable this handler
+      // Filter on specific loggers
+      //'loggers' => array('LSurl', 'LSlang'),
+      'excluded_loggers' => array('generate_lang_file', 'generate_ldapsaisie_pot'),
+      // Default formats
+      //'format' => '%{requesturi} - %{remoteaddr} - %{ldapservername} - %{authuser} - %{level} - %{message}',
+      //'cli_format' => '%{clibinpath} - %{level} - %{message}',
+      //'datetime_prefix' => true,            // Prefix message with datetime ?
+      //'datetime_format' => 'Y/m/d H:i:s',   // Datetime prefix format (see php date() function)
+    ),
+    array (
+      'handler' => 'email', // Email handler (each logged message generated an email)
+      'level' => 'FATAL',
+      'recipient' => 'root@localhost', // Email recipient
+    ),
+    /*
+    array (
+      'handler' => 'syslog', // Syslog handler
+      //'priority' => 'WARNING', // Force priority : EMERG, ALERT, CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG
+    ),
+    */
+    /*
+    array (
+      'handler' => 'system', // System logging (using PHP error_log)
+      'level' => 'ERROR',
+    ),
+    */
   ),
-  array (
-    'handler' => 'email', // Email handler (each logged message generated an email)
-    'level' => 'FATAL',
-    'recipient' => 'root@localhost', // Email recipient
-  ),
-  /*
-  array (
-    'handler' => 'syslog', // Syslog handler
-    //'priority' => 'WARNING', // Force priority : EMERG, ALERT, CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG
-  ),
-  */
-  /*
-  array (
-    'handler' => 'system', // System logging (using PHP error_log)
-    'level' => 'ERROR',
-  ),
-  */
-);
-$GLOBALS['LSlog']['loggers'] = array (
   /**
    * Loggers permit to define different log parameters for specific components
    * of LdapSaisie (a class, an addon, ...). You could :
    *   - Enabled/disabled logs for this component with 'enabled' parameter
    *   - Set a specific log level for this component with 'enabled' parameter
    **/
-  /*
+  "loggers" => array(
-  'LSurl' => array (
+    /*
-    'level' => 'DEBUG',
+    'LSurl' => array (
+      'level' => 'DEBUG',
+    ),
+    'LSldap' => array (
+      'level' => 'DEBUG',
+    ),
+    'LSlang' => array (
+      'enabled' => false,
+    ),
+    */
   ),
-  'LSldap' => array (
-    'level' => 'DEBUG',
-  ),
-  'LSlang' => array (
-    'enabled' => false,
-  ),
-  */
 );
-$GLOBALS['LSlog']['level'] = 'INFO';  // TRACE, DEBUG, INFO, WARNING, ERROR, FATAL
-$GLOBALS['LSlog']['enable'] = true;
 
 define('NB_LSOBJECT_LIST',30);
 define('NB_LSOBJECT_LIST_SELECT',20);

src/includes/class/class.LSlog.php

@@ -33,6 +33,24 @@ class LSlog {
    */
   private static $enabled = false;
 
+  /**
+   * Log errors context
+   * @var bool
+   */
+  private static $log_errors_context = false;
+
+  /**
+   * Log errors context with arguments
+   * @var bool
+   */
+  private static $log_errors_context_with_args = false;
+
+  /**
+   * Log errors context with arguments
+   * @var int
+   */
+  private static $log_errors_context_args_max_length = 1000;
+
   /**
    * Configured handlers
    * @see self::start()
@@ -91,6 +109,9 @@ class LSlog {
   public static function start() {
     // Load configuration
     self :: $enabled = self :: getConfig('enable', false, 'bool');
+    self :: $log_errors_context = self :: getConfig('log_errors_context', false, 'bool');
+    self :: $log_errors_context_with_args = self :: getConfig('log_errors_context_with_args', false, 'bool');
+    self :: $log_errors_context_args_max_length = self :: getConfig('log_errors_context_args_max_length', 1000, 'int');
     self :: setLevel();
 
     // Load default handlers class
@@ -232,10 +253,11 @@ class LSlog {
    * @param string $level The message level
    * @param string $message The message
    * @param string|null $logger The logger name (optional, default: null)
+   * @param bool $do_not_include_context Set to true to disable context inclusion (optional, default: false)
    *
    * @return void
    **/
-  public static function logging($level, $message, $logger=null) {
+  public static function logging($level, $message, $logger=null, $do_not_include_context=false) {
     // Check LSlog is enabled
     if (!self :: $enabled)
       return;
@@ -252,6 +274,19 @@ class LSlog {
         $message = varDump($message);
     }
 
+    // Append context to message (if enabled)
+    $context = "";
+    if (
+      !$do_not_include_context
+      && self :: $log_errors_context
+      && self :: checkLevel($level, "ERROR")
+    )
+      $context = "\n  ".self :: get_debug_backtrace_context(
+        self :: $log_errors_context_with_args,
+        2,
+        "  "
+      );
+
     foreach (self :: $handlers as $handler) {
       // Check handler level
       if (!$handler -> checkLevel($level))
@@ -261,12 +296,12 @@ class LSlog {
         continue;
 
       // Logging on this handler
-      call_user_func(array($handler, 'logging'), $level, $message, $logger);
+      call_user_func(array($handler, 'logging'), $level, $message.$context, $logger);
     }
 
     if ($level == 'FATAL') {
       if (php_sapi_name() == "cli")
-        die($message);
+        die($message.$context);
       elseif (class_exists('LStemplate'))
         LStemplate :: fatal_error($message);
       else
@@ -310,29 +345,46 @@ class LSlog {
 
   /**
    * Generate current context backtrace
-   *
+   * @param bool $with_args Add args (optional, default: false)
+   * @param int|null $ignore_last_frames Ignore last frames (optional, default: 1)
+   * @param string|null $prefix Prefix to append at the beginning of each return lines (optional,
+   *                            default: no prefix)
    * @return string Current context backtrace
    **/
-  public static function get_debug_backtrace_context() {
+  public static function get_debug_backtrace_context($with_args=false, $ignore_last_frames=null, $prefix=null) {
+    $ignore_last_frames = is_int($ignore_last_frames)?$ignore_last_frames:1;
+    $prefix = is_string($prefix)?$prefix:"";
     $traces = debug_backtrace();
-    if (!is_array($traces) || count($traces) < 2)
+    if (!is_array($traces) || count($traces) < ($ignore_last_frames + 1))
       return "unknown context";
 
     $msg = array();
     $j=0;
-    for ($i=count($traces)-1; $i >= 1; $i--) {
+    for ($i=count($traces)-1; $i >= (is_int($ignore_last_frames)?$ignore_last_frames:1); $i--) {
       $j += 1;
       $trace = array("#$j");
       if (isset($traces[$i]['file']))
         $trace[] = $traces[$i]['file'].(isset($traces[$i]['line'])?":".$traces[$i]['line']:"");
+      $args = (
+        $with_args && isset($traces[$i]["args"])?
+        format_callable_args(
+          $traces[$i]["args"],
+          $prefix,
+          self :: $log_errors_context_args_max_length
+        ):
+        ""
+      );
       if (isset($traces[$i]['class']) && isset($traces[$i]['function']))
-        $trace[] = $traces[$i]['class'] . " " . $traces[$i]['type'] . " " . $traces[$i]['function']. "()";
+        $trace[] = sprintf(
+          "%s %s %s(%s)",
+          $traces[$i]['class'], $traces[$i]['type'], $traces[$i]['function'], $args
+        );
       elseif (isset($traces[$i]['function']))
-        $trace[] = $traces[$i]['function']. "()";
+        $trace[] = sprintf("%s(%s)", $traces[$i]['function'], $args);
       $msg[] = implode(" - ", $trace);
     }
 
-    return implode("\n", $msg);
+    return implode("\n$prefix", $msg);
   }
 
   /**
@@ -351,12 +403,23 @@ class LSlog {
   public static function exception($exception, $prefix=null, $fatal=true, $logger=null) {
     $message =
       ($prefix?"$prefix :\n":"An exception occured :\n").
-      self :: get_debug_backtrace_context(). "\n" .
+      implode(
-      "## ".$exception->getFile().":".$exception->getLine(). " : ". $exception->getMessage();
+        "\n",
-    if (is_null($logger))
+        array_map(
-      self :: logging(($fatal?'FATAL':'ERROR'), $message);
+          function($line) { return "  $line"; },
-    else
+          array_slice(
-      self :: logging(($fatal?'FATAL':'ERROR'), $message, $logger);
+            array_reverse(
+              explode(
+                "\n",
+                $exception->getTraceAsString()
+              ),
+              1
+            ),
+            1
+          )
+        )
+      )."\n    => ". $exception->getMessage();
+    self :: logging(($fatal?'FATAL':'ERROR'), $message, $logger, true);
   }
 
   /**
@@ -405,7 +468,18 @@ class LSlog {
     );
     $error = (isset($errnos2error[$errno])?$errnos2error[$errno]:'UNKNOWN');
     $level = (isset($errors2level[$error])?$errors2level[$error]:'ERROR');
-    self :: logging($level, "A PHP $error occured (#$errno) : $errstr [$errfile:$errline]");
+
+    // Log error suppressed with the @-operator at TRACE level and add a prefix to signal it
+    $prefix = "";
+    $error_reporting = error_reporting();
+    if ( !($error_reporting & $errno) ) {
+      $level = "TRACE";
+      $prefix = "[IGNORE BY @ OPERATOR] ";
+    }
+    self :: logging(
+      $level,
+      "{$prefix}A PHP $error occured (#$errno) : $errstr [$errfile:$errline]"
+    );
     return False;
   }
 

src/includes/class/class.LSurl.php

@@ -192,13 +192,24 @@ class LSurl extends LSlog_staticLoggerClass {
     $public_root_url = LSconfig :: get('public_root_url', '/', 'string');
 
     if ($absolute && $public_root_url[0] == '/') {
-      self :: log_debug("LSurl :: public_root_url(absolute=true): configured public root URL is relative ($public_root_url) => try to detect it from current request infos.");
+      self :: log_debug(
-      $public_root_url = 'http'.(isset($_SERVER['HTTPS']) && $_SERVER['HTTPS'] == 'on'?'s':'').'://'.$_SERVER['HTTP_HOST'].$public_root_url;
+        "LSurl :: public_root_url(absolute=true): configured public root URL is relative ".
-      self :: log_debug("LSurl :: public_root_url(absolute=true): detected public absolute root URL: $public_root_url");
+        "($public_root_url) => try to detect it from current request infos."
+      );
+      $public_root_url = sprintf(
+        "http%s://%s%s",
+        isset($_SERVER['HTTPS']) && $_SERVER['HTTPS'] == 'on'?'s':'',
+        $_SERVER['HTTP_HOST'],
+        $public_root_url
+      );
+      self :: log_debug(
+        "LSurl :: public_root_url(absolute=true): detected public absolute root URL: ".
+        $public_root_url
+      );
     }
 
     if ($relative_url) {
-      if ($public_root_url[0] == '/') $public_root_url .= "/";
+      if ($public_root_url[-1] != '/') $public_root_url .= "/";
       return $public_root_url.$relative_url;
     }
 

src/includes/functions.php

@@ -746,20 +746,76 @@ function dumpFile($file_path, $mime_type=null, $max_age=3600, $force_download=fa
 
 /**
  * Format a callable object for logging
- * @param  callable $callable The callable object
+ * @param  string|array|\ReflectionMethod|\ReflectionFunction $callable The callable object
+ * @param  null|array<int,mixed> $args Optional argument(s)
  * @return string The callable object string representation
  */
-function format_callable($callable) {
+function format_callable($callable, $args=null) {
+  $formatted_args = format_callable_args($args);
   if (is_string($callable))
-    return $callable."()";
+      return $callable."($formatted_args)";
-  if (is_array($callable) && count($callable)==2)
+  if (is_array($callable))
-    if (is_string($callable[0]))
+      if (is_string($callable[0]))
-      return $callable[0]."::".$callable[1]."()";
+          return $callable[0]."::".$callable[1]."($formatted_args)";
-    elseif (is_object($callable[0]))
+      elseif (is_object($callable[0]))
-      return get_class($callable[0])."->".$callable[1]."()";
+          return get_class($callable[0])."->".$callable[1]."($formatted_args)";
-    else
+      else
-      return "Unkown->".$callable[1]."()";
+          return "Unknown->".$callable[1]."($formatted_args)";
-  return varDump($callable);
+  if ($callable instanceof \ReflectionFunction)
+      return sprintf("%s(%s)", $callable->name, $formatted_args);
+  if ($callable instanceof \ReflectionMethod)
+      return sprintf(
+          "%s::%s(%s)",
+          $callable->class,
+          $callable->name,
+          $formatted_args
+      );
+  return sprintf("%s(%s)", varDump($callable), $formatted_args);
+}
+
+/**
+ * Format callable arguments for logging
+ * @param array<mixed> $args Arguments
+ * @param string|null $prefix Prefix to append at the beginning of each return lines (optional,
+ *                            default: no prefix)
+ * @param int $arg_max_length Argument export max length: above, it will be truncated (optional,
+ *                            default: do not truncate)
+ * @return string
+ */
+function format_callable_args($args, $prefix=null, $arg_max_length=null) {
+  if (!is_array($args) || empty($args))
+    return "";
+  $prefix = is_string($prefix)?$prefix:"";
+  $formatted_args = [];
+  $new_line = false;
+  foreach($args as $arg) {
+    try {
+      $formatted = preg_replace(
+        "/\s=>\s+(array|\\\\)/m",
+        " => $1",
+        @var_export($arg, true)
+      );
+      if ($arg_max_length && mb_strlen($formatted) > $arg_max_length) {
+        $formatted = rtrim(substr($formatted, 0, $arg_max_length));
+        $formatted .= strpos($formatted, "\n")?"\n[...]":"[...]";
+      }
+      $formatted_args[] = $formatted;
+      $new_line = $new_line || (strpos($formatted, "\n") !== false);
+    }
+    catch (Exception $e) {
+      $formatted_args[] = "<".gettype($arg).">";
+    }
+  }
+  if ($new_line) {
+    for($i=0; $i < count($formatted_args); $i++) {
+      $formatted_args[$i] = implode(
+        "\n$prefix  ",
+        explode("\n", $formatted_args[$i])
+      );
+    }
+    return "\n$prefix  ".implode(",\n$prefix  ", $formatted_args)."\n$prefix";
+  }
+  return implode(", ", $formatted_args);
 }
 
 function is_empty($val) {