Error log improvements: Provide severity level and use Civi::log() #14222

mfb · 2019-05-10T02:11:26Z

Overview

I'm not sure if we want to deprecate CRM_Core_Error::debug_var() and stop using it, or make some improvements to it.

If the latter, then we could provide a $level argument so that we can assign a severity level to fatal errors and other usages of CRM_Core_Error::debug_var(), and in addition, various CRM_Core_Error methods could use Civi::log() internally rather than CRM_Core_Error::debug_log_message().

Note: I would say that CRM_Core_Error::debug_log_message() should also use Civi::log(), but this isn't doable as long as CRM_Core_Error_Log::log() calls CRM_Core_Error::debug_log_message().. This could be worked on in a future PR if desired.

Before

A call like CRM_Core_Error::debug_var('Fatal Error Details', ...) logs at the default severity level, and doesn't use Civi::log().

After

CRM_Core_Error::debug_var() has an optional $level arg;
Various CRM_Core_Error methods use Civi::log() internally; and
Civi::log() supports a civi.prefix context param to specify the log file prefix.

…ethods could use Civi::log() internally; prefix param support for Civi::log().

civibot · 2019-05-10T02:11:28Z

(Standard links)

If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

mattwire · 2019-05-10T09:14:15Z

@totten I think this is the right direction - could use your thoughts here?

eileenmcnaughton · 2019-05-24T02:34:11Z

CRM/Core/Error.php

@@ -39,6 +39,8 @@

 require_once 'Log.php';

+use Psr\Log\LogLevel;


eileenmcnaughton · 2019-05-24T02:34:17Z

CRM/Core/Error.php

@@ -232,7 +234,7 @@ public static function handle($pearError) {
    $errorDetails = CRM_Core_Error::debug('', $error, FALSE);
    $template->assign_by_ref('errorDetails', $errorDetails);

-    CRM_Core_Error::debug_var('Fatal Error Details', $error);
+    CRM_Core_Error::debug_var('Fatal Error Details', $error, TRUE, TRUE, '', LogLevel::ERROR);


eileenmcnaughton · 2019-05-24T02:34:30Z

CRM/Core/Error.php

@@ -339,7 +341,7 @@ public static function fatal($message = NULL, $code = NULL, $email = NULL) {

    if (self::$modeException) {
      // CRM-11043
-      CRM_Core_Error::debug_var('Fatal Error Details', $vars);
+      CRM_Core_Error::debug_var('Fatal Error Details', $vars, TRUE, TRUE, '', LogLevel::ERROR);


eileenmcnaughton · 2019-05-24T02:34:36Z

CRM/Core/Error.php

@@ -381,7 +383,7 @@ function_exists($config->fatalErrorHandler)
      self::backtrace();
    }

-    CRM_Core_Error::debug_var('Fatal Error Details', $vars);
+    CRM_Core_Error::debug_var('Fatal Error Details', $vars, TRUE, TRUE, '', LogLevel::ERROR);


eileenmcnaughton · 2019-05-24T02:34:53Z

CRM/Core/Error.php

@@ -421,7 +423,7 @@ public static function handleUnhandledException($exception) {
    }
    catch (Exception $other) {
      // if the exception-handler generates an exception, then that sucks! oh, well. carry on.
-      CRM_Core_Error::debug_var('handleUnhandledException_nestedException', self::formatTextException($other));
+      CRM_Core_Error::debug_var('handleUnhandledException_nestedException', self::formatTextException($other), TRUE, TRUE, '', LogLevel::ERROR);


eileenmcnaughton · 2019-05-24T02:35:01Z

CRM/Core/Error.php

@@ -459,7 +461,7 @@ function_exists($config->fatalErrorHandler)
    // Case C: Default error handler

    // log to file
-    CRM_Core_Error::debug_var('Fatal Error Details', $vars, FALSE);
+    CRM_Core_Error::debug_var('Fatal Error Details', $vars, FALSE, TRUE, '', LogLevel::ERROR);


eileenmcnaughton · 2019-05-24T02:35:12Z

CRM/Core/Error.php

   *
   * @return string
   *   The generated output
   *
   * @see CRM_Core_Error::debug()
   * @see CRM_Core_Error::debug_log_message()
   */
-  public static function debug_var($variable_name, $variable, $print = TRUE, $log = TRUE, $prefix = '') {
+  public static function debug_var($variable_name, $variable, $print = TRUE, $log = TRUE, $prefix = '', $level = LogLevel::INFO) {


eileenmcnaughton · 2019-05-24T02:37:59Z

CRM/Core/Error.php

@@ -574,7 +578,15 @@ public static function debug_var($variable_name, $variable, $print = TRUE, $log
        reset($variable);
      }
    }
-    return self::debug_log_message($out, FALSE, $prefix);
+    Civi::log()->log($level, $out, ['civi.prefix' => $prefix]);


So this is the biggest change in here - however it seems that Civi::log winds up calling CRM_Core_Error_Log::log

which itself calls CRM_Core_Error::debug_log_message($message, FALSE, '', $this->map[$level]);

So it would be functionally equivalent except that the param $out is not passed through or echo'd. I think this function might need to echo $out itself to retain that behaviour

/** * Logs with an arbitrary level. * * @param mixed $level * @param string $message * @param array $context */ public function log($level, $message, array $context = []) { // FIXME: This flattens a $context a bit prematurely. When integrating // with external/CMS logs, we should pass through $context. if (!empty($context)) { if (isset($context['exception'])) { $context['exception'] = CRM_Core_Error::formatTextException($context['exception']); } $message .= "\n" . print_r($context, 1); if (CRM_Utils_System::isDevelopment() && CRM_Utils_Array::value('civi.tag', $context) === 'deprecated') { trigger_error($message, E_USER_DEPRECATED); } } CRM_Core_Error::debug_log_message($message, FALSE, '', $this->map[$level]); }

eileenmcnaughton · 2019-05-24T02:38:06Z

CRM/Core/Error.php

+  /**
+   * Generates debug HTML output.
+   */
+  public static function debugOutput($message) {


eileenmcnaughton · 2019-05-24T02:38:12Z

CRM/Core/Error.php

@@ -600,7 +612,7 @@ public static function debug_log_message($message, $out = FALSE, $prefix = '', $
    $file_log = self::createDebugLogger($prefix);
    $file_log->log("$message\n", $priority);

-    $str = '<p/><code>' . htmlspecialchars($message) . '</code>';
+    $str = self::debugOutput($message);


eileenmcnaughton · 2019-05-24T02:39:25Z

CRM/Core/Error.php

@@ -962,7 +974,7 @@ public static function exceptionHandler($pearError) {
   *   $obj
   */
  public static function nullHandler($obj) {
-    CRM_Core_Error::debug_log_message("Ignoring exception thrown by nullHandler: {$obj->code}, {$obj->message}");
+    Civi::log()->error("Ignoring exception thrown by nullHandler: {$obj->code}, {$obj->message}");


ok - in the absense of $out - this is the same

eileenmcnaughton · 2019-05-24T02:42:17Z

This looks good to me - but I have a concern with might be losing the output (not passing $out & not echoing to compensate)

eileenmcnaughton · 2019-07-01T06:40:39Z

@mfb did you have a response on ^^

mfb · 2019-07-01T12:37:48Z

This looks good to me - but I have a concern with might be losing the output (not passing $out & not echoing to compensate)

debug_var() echos the output itself, and then when calling debug_log_message() always sets $out (the second parameter) to FALSE so no echoing happens there; just logging.

eileenmcnaughton · 2019-08-08T03:22:51Z

Looks like there is an answer to the question I raised - this is fairly low risk / easily fixable if we do lose a bit of 'noise' - merging

Revert #14222 on RC branch

CRM_Core_Error::debug_var() should have a level arg; CRM_Core_Error m…

3ac984a

…ethods could use Civi::log() internally; prefix param support for Civi::log().

civibot bot added the master label May 10, 2019

eileenmcnaughton reviewed May 24, 2019

View reviewed changes

CRM/Core/Error.php

@@ -39,6 +39,8 @@

require_once 'Log.php';

use Psr\Log\LogLevel;

Copy link

Contributor

eileenmcnaughton May 24, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok

eileenmcnaughton reviewed May 24, 2019

View reviewed changes

CRM/Core/Error.php

/**

* Generates debug HTML output.

*/

public static function debugOutput($message) {

Copy link

Contributor

eileenmcnaughton May 24, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok

eileenmcnaughton reviewed May 24, 2019

View reviewed changes

eileenmcnaughton merged commit 79ccdcd into civicrm:master Aug 8, 2019

mfb added a commit to mfb/civicrm-core that referenced this pull request Aug 8, 2019

Followup for civicrm#14222: Do not print prefix in the log.

9e01e80

This was referenced Aug 8, 2019

Error log improvements: Provide priority level #14995

Merged

Revert #14222 on RC branch #14996

Merged

eileenmcnaughton added a commit that referenced this pull request Aug 8, 2019

Merge pull request #14996 from mfb/revert-14222

9132fee

Revert #14222 on RC branch

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error log improvements: Provide severity level and use Civi::log() #14222

Error log improvements: Provide severity level and use Civi::log() #14222

mfb commented May 10, 2019

civibot bot commented May 10, 2019

mattwire commented May 10, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton May 24, 2019

eileenmcnaughton commented May 24, 2019

eileenmcnaughton commented Jul 1, 2019

mfb commented Jul 1, 2019

eileenmcnaughton commented Aug 8, 2019

		@@ -39,6 +39,8 @@

		require_once 'Log.php';

		use Psr\Log\LogLevel;

Error log improvements: Provide severity level and use Civi::log() #14222

Error log improvements: Provide severity level and use Civi::log() #14222

Conversation

mfb commented May 10, 2019

Overview

Before

After

civibot bot commented May 10, 2019

mattwire commented May 10, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eileenmcnaughton commented May 24, 2019

eileenmcnaughton commented Jul 1, 2019

mfb commented Jul 1, 2019

eileenmcnaughton commented Aug 8, 2019