Session ID in the logger

It would be great feature to have the option of automatically prefix the session ID to log messages.

It would make the logger a lot more useful since it makes it lot easier to track down bugs and other unusual behavior in the system. 

I did take a look at the CLogger and CLogRoute.  I don't think it's necessary to prepend this to all log messages in the CLogger since it doesn't change (well, it's not a feature to track changes in the session id).

It would be possible to extend a some log route and do it there, but I think it's such a fundamental thing that it should live in the framework.

Do you mean to log the current session ID and probably other environment information (as separate messages)?

Not as a separate message, but prefix the message with the session ID.

Example:

Logging the messages:

"Used {$user->id} logged in".

"Added item $item->id to basket"

"Authorizing nuclear fusion"

would actually log:

"[0a8ffb5c77d53e43323f] tim.jones logged in".

"[0a8ffb5c77d53e43323f] Added item 7 to basket"

"[0a8ffb5c77d53e43323f] Authorizing nuclear fusion"

It makes it possible to track down what users are doing and what leads to exceptions/bugs/…  Without the session it and many users at the same time it makes log hard to follow.  It also requires to constantly log redundant information: "$user did this to $that", "$user doing this" "$user stole your beer".

It seems very redundant to me. The reason is that log messages for the same request are clustered together. So a single message showing session ID (and perhaps other information) is sufficient.

Agree it looks reduntant.  But this is the scenario:

Within a day, you get 500 users on your web.  Each page view yields 1 'cluster' of log messages.  Now one of the users e-mail you and says something is not working on the web.  Being a not very computer literate person, he is not very precise on the error message he gets or it's unclear what really happened (we service a lot of people like that)

Now, grepping the logfile by his session it gives you the history of what he's been trying to do.  The reason for his problems might have been in previous action (another 'cluster').

My description of this is a “light” version of Nested Diagnostic Contexts, described here: http://logging.apach…1.2/manual.html

A full blown NDC let's you put arbitrary prefixes (or contexts) with your log messages with pop() and push().

I just added CLogRoute::filter and CLogFilter. By setting CLogRoute::filter='CLogFilter' in app config, you may see dump of variables like $_GET, $_POST, etc. You can also configure CLogFilter so that each message is prefixed session ID, user name/ID.

I wasn't expecting you stay up all night to implement this!

This is excellent and have no doubts it will make the logger much more useful.

I found 1 bug

1. If exception occours in your code and error_handler takes over, neither session or user info is prepended.  Reason is that $_SESSION is not set, even if session_id() returns session id.

Btw, Shouldn't there be a space between the prefix and the actual log message?

Accidentally hit post on prev. message.  (ctrl-s does!)

This would address those 2 points in prev. message, but removing $_SESSION from the condition might introduce other problems ?

Index: CLogFilter.php


===================================================================


--- CLogFilter.php      (revision 1092)


+++ CLogFilter.php      (working copy)


@@ -70,14 +70,14 @@


        protected function format(&$logs)


        {


                $prefix='';


-               if($this->prefixSession && isset($_SESSION) && ($id=session_id())!=='')


+               if($this->prefixSession && ($id=session_id())!=='')


                        $prefix.="[$id]";


                if($this->prefixUser && ($user=Yii::app()->getComponent('user',false))!==null)


                        $prefix.='['.$user->getName().']['.$user->getId().']';


                if($prefix!=='')


                {


                        foreach($logs as &$log)


-                               $log[0]=$prefix.$log[0];


+                               $log[0]=$prefix.' '.$log[0];


                }


        }

I think this enhancement should be very useful and practical, so I rush to implement it. BTW, it’s my daytime.

In general, we don't want to start a session in the log filter. I think dropping off the check for $_SESSION should be fine since calling session_id() won't start a session. Thanks.

I got confused while testing last time.

Removing the $_SESSION from the condition doesn't resolve the problem.  Which makes sense, since the session hasn't been started.

It's not possible to start the session there, since headers have already been sent.

I thought i could set the session to autoStart, but that doens't seem to work - it hasn't started when my controller throws exception.

I did put an

'session' => array('class' => 'CHttpSession', 'autoStart' => true)

in the configuration file.

But the log file shows that it's not loaded …

Since i'd rather very much have the session ID on unhandled excepitons, can you see any idea how that would be possible with this implementation ?

The log (lot of sql code removed)

Loading "log" application component


Loading "request" application component


Loading "urlManager" application component


Loading "db" application component


Opening DB connection


Contact.findByAttributes()


Querying SQL: SELECT * FROM "Contact" WHERE "Contact"."email"=:yp0 LIMIT 1


Domain.findByPk()


Querying SQL: SELECT * FROM "Domain" WHERE "Domain"."ID"=32 LIMIT 1


EMailTemplate.findByAttributes()


Evaluting dynamic variable with 'return $recipient->name;'


Evaluting dynamic variable with 'return $domain->IDN;'


Trying to get property of non-object (/web.dev/app/models/EMailTemplate.php(193) : eval()'d code:1)


Loading "errorHandler" application component

If you didn't try to access $_SESSION or Yii::app()->user, most likely the session is not started. You may force it to start by listing the 'session' component in 'preload' property in app config.