Internet Strategy Guide

Together we can defeat the internet

Tuesday, February 24, 2009

zend_log_exception ‘bad log priority’

I'm writing this post because there are a few times I've gotten this particular exception and then look at the trace and can't figure out what's wrong. More often than not, I'll get to the line in the trace and be like, "wtf! there's no priority here. It's a method call not a constant". This turns into, let's see if something is happening before this method is called and finally comes down to looking at the Zend_Log source and remember, "oh yeah, Zend_Log allows you to use log by priority name as a method in lieu of using the log method" and what I once thought of as slick when I read the documentation turns into a waste of a few minutes and added amount of aggrevation. So to save myself and others some time and aggrevation, I'm going to go into a bit of detail as to why you may be getting this exception.

Take the following for example:

// assume taht $log is a valid instance of Zend_Log
$log->addEventItem('foo','bar');

It looks like it should work, right? It won't because the correct method call would be

$log->setEventItem('foo','bar');

As I explained in the introduction, the 'bad log priority' exception will be thrown for this sort of error. This error will occur because Zend_Log overloads the __call function so that you can do

$log->priorityName('message');
// instead of logging with the log method
$log->log('message',Zend_Log::PRIORITY_NAME);

So if you're like me and get this exception but only see a method where this error is being thrown, you now know why and hopefully be less confused and aggrevated.

I wish I could provide a solution to this issue but I see no way that Zend_Log can contextually tell if you're wanting to use the priorityName shortcut or not. This only leaves the option of removing the the priorityName shortcut entirely, which will break somebody's code. The shortcut is nice because of its flexibility but definitely a case where flexibility can increase complexity or rather, flexibility leading into complications that require complex understanding. I haven't had time to read all the arguments in the comments on the flexibility/complexity issue that Federico Cargnelutti brought up recently to have an overall opinion on the matter but in regards to Zend_Log, the flexibility should've been left out. I would've preferred that Zend kept it simple and just made log the only method of logging. Or maybe I'm an edge case that logs more information than the initial event items give me.

posted by chance at 10:43 am  

Thursday, December 18, 2008

string searching, you’re doing it wrong

First off, I'm not trying to be a complete jack-ass, just a helpful one. This article, by Stefan Ashwell, popped up on my news feed and I wanted to comment on it but can't remember my login for the site and after 10 minutes of waiting the password reset email has yet to arrive. The non-arrival of the password process is irritating me and shows in this article title and my tone.

In the article, Stefan shows how strpos or stripos to locate a desired string or block of text.

The example he gives is as follows:

if ( stripos($sentence, 'string') ) {
   // yes it does
} else {
   // no it doesn't
}

The problem with this example is that it will yield a false positive. This is a common mistake made by a lot of people. If we examine the php manual entry further we see, "Returns the numeric position of the first occurrence of needle in the haystack string." The key word being numeric. This means if the string position is 0, then the expression ( stripos($sentence, 'string') ) will evaluate to false.

EDIT: Expanded explaination on why this can yield a false positive. If the string your searching for is at the beginning of the sentence, then the position returned is 0. When php reaches the statement if ( stripos($sentence, 'string') ) it interprets the return value (0) as false.

Here is a more expanded example:


$eval=(stripos('The quick brown fox jumped over the lazy dog','The'));

echo '($eval) : ';
echo ($eval) ? "pass\n" : "fail whale\n";
echo '($eval==0) : ';
echo ($eval==0) ? "pass\n" : "fail whale\n";
echo '($eval===false)';
echo ($eval===false) ? "pass\n" : "fail whale\n";
echo 'eval is '.$eval."\n";

/**
output is:

($eval) : fail whale
($eval==0) : pass
($eval===false)fail whale
eval is 0

*/

As you can see, if you want to properly search for a string using stripos or strpos, you must test for the boolean value of false ($eval===false). Alternately, you can use regex, if you're comfortable with it. I'm of the opinion that learning some basic regex doesn't ever hurt you.

I want to re-iterate that I wanted to leave this whole post as a comment but that doesn't seem possible right now since that email has yet to arrive and the article requires login for commenting.

posted by chance at 7:01 am  

Wednesday, December 17, 2008

Zend_Log quickstart

Lately, I've found that I need to create a more robust logging system for both audits and debugging. I found a great logging primer from DevShed that offers some good insight into going about making a more robust system. Other than the theory, you shouldn't really take much more away from it since, as one comment points out, the implementation is poor aka globals are bad. Caveat: my implementation probably won't be all that great either but I hope to avoid making beginner's mistakes.

That being said, the reason this particular article is centered on Zend is because I'm pretty much in love with Zend right now. The main reason for writing this article is that, while the Zend documentation on Zend_Log is thorough and easy to understand when you read it, I hate back and forth between the sections of Zend_Log to make sure I understand what I'm needing to do.

I'm assuming you have at least gone through the Zend Quickstart before reading on. For my filesystem and db configuration, I use Zend_Config to load up settings such as the logfile name and log database adapter. I could've set the path for the file but I want a certain degree of flexibility.

At this point, I have the logger configuration from zend config  and the db adapter so let's move on to some code examples. This is partially taken from my in-progress class.

making a full filepath:

$filepath=(isset($options['FilePath'])) ? $options['FilePath'] : INC_PATH."/".$this->_systemConfig->system->logfile;
$writer = new Zend_Log_Writer_Stream($filepath);

the filepath is used with the Zend_Log_Writer. Next we set a format for the writer and then instantiate Zend_Log with the writer

$formatter=new Zend_Log_Formatter_Simple($format);
// specify format
$writer->setFormatter($formatter);
$logger=new Zend_Log($writer);

Note: $format is a text string that indicates how each log entry will appear.

The important things to remember here is that Zend_Log creates an associative array with all the basic useful log information. This array can be accessed in a variety of ways. For my purposes, knowing what is accessible by the stream and database writers are important.
If you have read the documentation thoroughly, you will have found that in section 30.1.6 Zend documents this array expressly. Unfortunately, unlike some most of their other documentation, this useful bit of information is almost secreted away. I've scoured the docs a lot to find the keys created by Log so here they are as a quick reference.

  • timestamp
  • message
  • priority
  • priorityName

These little gems are pretty much the keys to the Kingdom of Zend_Log.
If you want to reference them for formatting in a stream, you can do something like:

$format = (isset($options['LogFormat'])) ? $options['LogFormat'] : '%timestamp% '
.PHP_EOL.'%priorityName% (%priority%)'
.PHP_EOL.'%message%' . PHP_EOL.PHP_EOL
.str_repeat("=",100). PHP_EOL;

or if you need to use them for your db, you can use set column mapping like so:

$columnMapping = array('lvl' => 'priority','Priority'=>'priorityName', 'msg' => 'message');
$writer = new Zend_Log_Writer_Db($db, 'log_table_name', $columnMapping);

That should cover the basics.

Pro-tip discussion: For auditing, you may want to make separate log files for access,create,and changes made to your app/system. Error logging should log everything into files, but a separate debug copy would probably out in the development environment. I usually do a tail -f on debug/log file. It seems obvious to, me that any logging/exception system you make should have a simple outside error handling function to alert you of that logging broke. I believe this can be done by setting the error handler in the constructor. Haven't played with this yet. It seems to me that any robust logging system you implement will run into a chicken vs the egg type problem

posted by chance at 10:54 am  

Friday, November 7, 2008

stupid *nix tricks

[Edit: Seems like the -u flag is on debian systems such as Ubuntu. Did a man on a FreeBSD system and saw it didn't have the flag available.]
I use the cp and mv a lot that the -r and -f flags almost always accompany them. I also now realize I've used them for so long with so little thought that I forgot that there were other flags. My newest infatuation is the -u flag.

Basically -u lets you do a merge, which came in handy when I had to manually update wordpress for the first time. I could tell you more or you could RTFM

posted by chance at 11:38 am  

Powered by WordPress