ZF-2428: Patch to make line and file information available in log events

Description

I personally find it hard to track down where log entries are originating from sometimes, so I wanted to add line and file info to my log format like this:

    $format = '%timestamp% %priorityName% (%priority%): %message% at line %line% in file %file%' . PHP_EOL;
    $formatter = new Zend_Log_Formatter_Simple($format);
    $writer->setFormatter($formatter);

However, "line" and "file" are not currently available in Zend_Log's $events array. So I wrote a patch to provide it. Hope it might be considered for inclusion.

Regards, Mark Maynereid


diff Log.php LogNew.php
106c106
<             $this->log(array_shift($params), $priority);
---
>             $this->log(array_shift($params), $priority, array_slice(debug_backtrace(), 1));
130a131,137
>         // obtain line and file from where we have been called
>         if (func_num_args() > 2) {
>             $backtrace = func_get_arg(2);
>         } else {
>             $backtrace = debug_backtrace();
>         }
>
135c142,144
<                                     'priorityName' => $this->_priorities[$priority]),
---
>                                     'priorityName' => $this->_priorities[$priority],
>                                     'line'         => $backtrace[0]['line'],
>                                     'file'         => $backtrace[0]['file']),

Comments

I've since added "class" and "function" which seems to need the index set at 1 so for in my sub-classed version I've added:


        $this->setEventItem('function', isset($backtrace[1]['function']) ? $backtrace[1]['function'] : '');
        $this->setEventItem('class', isset($backtrace[1]['class']) ? $backtrace[1]['class'] : '');

which lets me:


$format = '%timestamp% %priorityName% (%priority%) %class%::%function%: %message% at line %line% in file %file%' . PHP_EOL;

I only found out about svn diff today (as opposed to plain old diff) so here's the patch reworked to include all useful backtrace items:


Index: library/Zend/Log.php
===================================================================
--- library/Zend/Log.php        (revision 7698)
+++ library/Zend/Log.php        (working copy)
@@ -103,7 +103,7 @@
     {
         $priority = strtoupper($method);
         if (($priority = array_search($priority, $this->_priorities)) !== false) {
-            $this->log(array_shift($params), $priority);
+            $this->log(array_shift($params), $priority, array_slice(debug_backtrace(), 1));
         } else {
             throw new Zend_Log_Exception('Bad log priority');
         }
@@ -128,12 +128,26 @@
             throw new Zend_Log_Exception('Bad log priority');
         }

+        if (func_num_args() > 2) {
+            $backtrace = func_get_arg(2);
+        } else {
+            $backtrace = debug_backtrace();
+        }
+
         // pack into event required by filters and writers
-        $event = array_merge(array('timestamp'    => date('c'),
-                                    'message'      => $message,
-                                    'priority'     => $priority,
-                                    'priorityName' => $this->_priorities[$priority]),
-                              $this->_extras);
+        $event = array_merge(
+            array(
+                'class'         => isset($backtrace[1]['class']) ? $backtrace[1]['class'] : '',
+                'file'          => $backtrace[0]['file'],
+                'function'      => isset($backtrace[1]['function']) ? $backtrace[1]['function'] : '',
+                'line'          => $backtrace[0]['line'],
+                'message'       => $message,
+                'priority'      => $priority,
+                'priorityName'  => $this->_priorities[$priority],
+                'timestamp'     => date('c'),
+            ),
+            $this->_extras
+        );

         // abort if rejected by the global filters
         foreach ($this->_filters as $filter) {

One note about the backtrace stack. You'll need to detect which trace in the stack to use. Because if someone calls the "priority magic function" ex: $log->info('test'); it will add another trace in the stack from the logger. I've worked around it by detecting the class name, ex:


// Detect what trace to use
foreach ($backtrace as $number => $trace) {
    if (!isset($trace['class']) || $trace['class'] != 'Zend_Log') {
        break;
    }
}

// Find the file and line from previous trace
$line = $backtrace[$number - 1]['line'];
$file = $backtrace[$number - 1]['file'];

// Find the calling info
$function = $backtrace[$number]['function'];
// etc...

Ignore my previous comment. I noticed that the backtrace stack is passed from __call() as well which is another solution.

Is any of the other backtrace info usefull? Ex: type, args

I've just started messing with Zend_Log and I think that trace information would be a very valuable addition. (My ideal is Java's Logger class.)

I'd suggest that in addition to timestamp, priority name, message, etc:

  • Filename
  • Line Number
  • Method name (if applicable)
  • Class name (if applicable)
  • Full trace data (arrays) that a custom formatter can access

Function arguments? Probably not: If those were important I would expect that to be part of the log message the developer chooses.

Lastly, there needs to be a way to turn this on or off for performance purposes (debug_backtrace can be expensive) and possibly on or off depending on the priority level.

It seems the recent Zend_Log_Writer_Firebug class supports it's own tracing, but that's done in the Zend_Wildfire stuff rather than Zend_Log. I'll mess around and see if I can come up with something.

This is a diff against the 1.5.3 release tag.

It adds support for toggling "tracing" for various priority levels. When enabled on a certain level, all messages in that level are accompanied by call-stack information.

Patch attached. OOPS! Leftover var_dump() call in there on line 203, my fault.

Had to modify Zend_Log_Formatter_Simple to keep it from choking on non-string data.

Added Zend_Log_Formatter_Tracer to allow formatting trace output as text.

Tracing on a given level is off by default.

No "getTracing()' function at the moment.

Revised version

I may have an off-by-one error in there, will test some more.

But I realize there's a conceptual problem:

(A) In this patch, backtraces are made at the instant that the log message is generated, but suppose they're all filtered out later? That could be a big way to lose performance in a high-log environment, with some time-consuming operations (debug_backtrace()) that you can't bypass it with a filter.

(B) On the other side, what if you want to make a filter which filters based on the stack trace or a file whitelist/blacklist?

I think (A) is more likely, myself.

I would agree that (A) is more likely and the trace should be more informational than anything. What if the filter is applied at time of event creation? I know it could be changed during runtime but that would be an option.

I'm afraid I don't have access to the code anymore, but I did successfully test a version where the backtracing was done immediately after logger-level filters were applied. (Before writer-level filtering.)

The idea of using the backtrace is genious i have to say.

What i personally think of this patch, how much performance impact does debug_backtrace() have? its a debug function and many people use the logger on production systems, so its an important question how performance is impacted by say 100-1000 debug_backtrace calls.

So i wrote a little performance checking script, looping 100000 times and doing syslog in the one case and syslog + debug_backtrace in the other case. there was no huge impact in performance, so i guess this should be added in the future.

Performance is surely a potential concern here.

Perhaps the best answer is to have this additional information functionality enabled/disabled by a flag on construction? That way in development one could typically have it on and in live mode off, but could override either as required. And it would be off by default.

This is a great feature that I think many would find useful. We (the ZF team at Zend) also have concerns about performance, but we can also mention features like this that may affect performance in the performance guide. The one change we suggest is moving this functionality over to Zend_Debug, where not only people can use it for Zend_Log and any other component/applicaiton code, but it also fills out our relatively weak Zend_Debug component with functionality that would be useful in any PHP 5 application.

I'm postponing this since we don't have the resources to implement it in the next few weeks. Any community member can volunteer to implement this (if the code above is used, the author must sign a CLA) and provide appropriate unit tests. If a community member commits to implementing this, I will re-assign the issue to him/her.

I see Benjamin above has done some speed testing suggesting there is no huge impact (apols I missed the post before). That's encouraging :)

I am hopefully still on record as having signed the CLA if anyone wants to push this patch forward. Am still a novice at SVN and unit testing and a community contribution virgin. If I can get time to get up to speed more safely I'll return to this and have a crack at Will's invitation, but anyone more capable is welcome to advance it in the meantime as far as I'm concerned.

I note the mention of backtrace args above. I deliberately thought to exclude them from the patch as it struck me as mission creep and personally that kind of (core dump like stuff) seems more to do with Zend_Debug to me. In fact I wonder if Zend_Debug ought to become a singleton issuing unique IDs in managing PHP var dumps (like 'core dumps' to disk). Perhaps Zend_Log and Zend_Debug could plug into each other in some way but keep their roles nicely separated? eg. log message "Critical error blah bla in file:class:function:line blah blah, var core dump ID: (MD5 hash of file:class:function)". I like that because it seems to me it could facilitate automated bug logging/recurrance counts with vardumps dumped tidily to disk, a third party bugs DB entry made/updated and a lovely message to the user "Sorry but an unrecoverable error has occurred. This error is caused by a (new|known) bug and is logged for attention of the The Support Team. Please accept our apologies for the inconvenience rhubarb rhubarb.."

Well returning to the patch, as a stopgap and if anyone finds it useful, here's my own sub-classing version:


<?php

class Mm_Log extends Zend_Log
{
    public function log($message, $priority)
    {
        if (func_num_args() > 2) {
            $backtrace = func_get_arg(2);
        } else {
            $backtrace = debug_backtrace();
        }
        $this->setEventItem('function', isset($backtrace[1]['function']) ? $backtrace[1]['function'] : '');
        $this->setEventItem('class', isset($backtrace[1]['class']) ? $backtrace[1]['class'] : '');
        $this->setEventItem('line', $backtrace[0]['line']);
        $this->setEventItem('file', $backtrace[0]['file']);

        parent::log($message, $priority);
    }

    public function __call($method, $params)
    {
        $priority = strtoupper($method);
        if (($priority = array_search($priority, $this->_priorities)) !== false) {
            $this->log(array_shift($params), $priority, array_slice(debug_backtrace(), 1));
        } else {
            throw new Zend_Log_Exception('Bad log priority');
        }
    }

}