Developer Centric Logging

A few weeks ago I wrote some posts about overriding the CRON handler and I showed code about Developer Communication.   Since then I have talked to a few people and they all wanted to know what that cryptic function call did so I thought I would look into releasing it.   When I looked at the code I realized that I could not release it as it was crap.  So I took a week and rewrote it into this.  What we have here is a custom logger.  I found scant few examples of custom loggers on the internet so I hope someone finds this useful.

I think it adds all the missing pieces into SugarCRM's SugarLogger function like timers, headers, line tracing, email, and notifications.

So this is a pretty big piece of code so you will want to download it first, the link is at the bottom, and follow along locally as I will only be posting small chunks of code here on the post.

Lets start with the code that redirect some log calls to my custom code 'custom/Extension/application/Ext/Utils/sugarLogger.php'.

What is happening here is that I am telling SugarCRM to take any log call that is on the 'deprecated' level or higher (that is all the levels I actually care about) and redirect them to my custom logger class.  On my system I set my logging level to 'deprecated'.


So, if we now look at 'custom/include/SugarLogger/SugarDeveloperLogger.php' you can see how I overrode SugarLogger.  This allows me to customize how it works without breaking all existing log calls.   There are 2 configuration items at the top that you will need to define on your system


The first one is the name of the entity that will send out emails. The code gets the email address from your outgoing email configuration but I allow you to change the name so you will see a difference between standard emails and these emails in your inbox.

The second one is the GUID of the team that defines your developers.  There must be at least one user on this team and only explicitly added people will be emailed to.

The third one controls if custom log levels like 'email' and 'header' work for non-developer users.  If this is set to true, those custom functions will only work if the $current_user is in the developers team.  This keeps your log file cleaner and only sends emails and notifcations from code while you are testing.  Log events like 'fatal', 'error' and 'security' will always be logged.

This is what I added

1. Each log entry will be tagged with the file name and line number of the $GLOBALS['log'] call.  Remember this is only for the important log levels, not all of them, so it's impact on your log is not that bad.
   
2. Each custom log level can be limited down to a predefined list of users so you dont have to see your test log entries for all users, just testers.
3. Timers, you can start, stop and report on an unlimited number of timers.  Just by invoking the start_timer command and naming the timer like this
   

   $GLOBALS['log']->timer_start("timer1"); 

4. Headers, You can easily add very visible headers (Both single and multiline) to the log. Try to keep each line to less than 80 characters but it will scale it if you do not.  You can 'break' lines with <br> or '\n' characters.
   

   $GLOBALS['log']->header("This is a test"); 

   - or -

   $GLOBALS['log']->header("This is a test<br>on multiple lines"); 

5. Log Rolling, you can tell SugarCRM to roll the log at any time like this.  I use this to clear the log before a big test.  Its pretty easy to go overboard on this one, dont do it in a loop.
   

   $GLOBALS['log']->rollLog();

6. Email, You can log a message via Email for all the really important stuff like this
   

   $GLOBALS['log']->email("This is a test");

7. Notifications, you can also use SugarCRM's built in notification system like this
   

   $GLOBALS['log']->notification("This is a test");

8. The code will Email you about any SQL Query failures, no extra log call needed.  It will also email you whenever a log level of 'error' or 'secruity' is used as you should never miss those.

Timers

The timers function makes profiling new code a little easier.  If you know and use cachegrind or xhprof, those are going to provide far more accurate and in depth information.  The timers here are for quick adhoc testing.  Timers use a tiny bit of memory and they are not technically 'running' during the timed event, so they will not slow down the code.

Timers can be nested, they can start in one file and stop in another and they can be chained meaning you can start a timer, later report on its progress and then later stop it altogether.  For this functionality I use a third party library appgati located at custom/Extension/application/Ext/Utils/appgati.php.

 As I mentioned about you can start a timer with

$GLOBALS['log']->timer_start("timer1"); 

'timer1' being the unique name of the timer.  The name of the timer is optional, you can just call it without assigning a name to the timer like this

$GLOBALS['log']->timer_start(); 

and the code will name your timer for you, but that means you are limited to just this one timer, usually one is all I need though.

To get the result of a time you would call timer_stop like this

$GLOBALS['log']->timer_stop("timer1"); 

This stops the timer and gives you a full report.  If you did not name your timer then you just leave the name blank and the code will figure it out for you.  The report is going to look like this


This shows you not only the time but the memory information about the code in the timer.  It may look a little confusing at first as it is based on the output of the getrusage() command, for simplicity sake it is the second, third and fourth lines that you are most concerned with.  I usually read the fourth line as the total number of seconds between start and stop.

If you want a report but you DO NOT want to stop the timer, you can use the timer_report command like this:

$GLOBALS['log']->timer_report("timer1"); 

this will output the same report as above but the timer continues to tick.  You can report on a timer as many times as you want.

Emails and Notifications

You can also send emails and/or notifications about specific log entries.  They will be sent to the entire team that you define under $this->developerTeam. If you send out a notification and the user already has an unread notification with the same info in it, it wont send it again.  It does a lessor check on Emails that should at least prevent the same email going out over and over in the same session.

Participation

If anyone comes up with better code or something else that this code could do please share it with me and I will update this post.  I can always be reached at ken.brill@gmail.com.

The Code

The code for this project is available here