The error log is a standard development support tool. It will help you find problems with your application. When developing, I take extra care to make sure that the error log is clean – this includes warnings and notices as well. When your application gets deployed, you can then depend on the error logs to accurately report any issues.
You’d be surprised how many systems I encountered with warnings and notices wildly scrolling by as developers say “oh, just ignore those”. What? I’m kind of a jerk, so I’ll yell at people about it. Actually, I’m a jerk enough to go way out of my way to have ways to yell at people about their poor code practices. Things like “it works on my machine!” are super annoying, srsly. But going along with the logging of your application, I really love to be able to see how the underlying database access performs in the application. This is where we can have a philosophical discussion about the difference between an error and a bug, but long story short, a query that performs poorly because you forgot something obvious like an index is almost an error.
On a recent project, my coworker Matt Purdon wrote a pretty awesome debug console that leverages FirePHP support in Zend Framework to log a lot of information about what the application is doing directly to the Firebug console. Take a look at his implementation here (this is the most important link you’ll click on in this blog post).
The project we used it was structured in a way that separates server-side developers (any PHP and database stuff) and client-side developers (any JavaScript magic and HTML). We’ve used the console to help track which ZF controller actions are called (and hence, which views are rendered), which drastically smoothed out the process of working together between the two teams. In addition, this console also tracks:
- all variables stored in session
- memcached usage information
- all queries that are executed on the request – including their explain plans!
The beauty about the session, memcached and query tracking together is that we can easily say whether we’re correctly caching results that could/should be cached and whether the results are or need to be stored in session. For the queries that are not cached, we can see the entire explain plan and how long it took for the query to run. This is great because you don’t have to extract the queries outside of your code and run them outside of the application, never being really sure whether that’s how the application will use them.
As a result, we’ve got a lot more accountability across the development team. In addition to still paying attention to basic things like clean error logs, all developers now have a tool that does not allow them to make simple mistakes (like queries in loops! good God!) It’s really easy to conduct code reviews as well. And if you’re the type of person who always runs “svn blame” instead of “svn praise” (both aliases for “svn annotate”), you will now have a lot of material for, erghm, discussion among your fellow developers.
Brandon Savage
on Dec 17th, 2008
@ 12:39 pm:
For me, any application that emits any sort of error message is broken. All errors – including notices – should be gone before code is released. It’s one thing if your app logs warnings and notices due to some actual failure, but it’s just bad coding if you accept warnings and notices as “standard.”
Lukas
on Dec 17th, 2008
@ 3:34 pm:
We have something similar in our system and we are quite happy with it. We dont log quite as much information though. By default I only log some basics along with failed queries. I will probably add at least some information about how many queries were executed for a total of how long. In debug mode we log a lot more.
This is all fine and dandy, but I see two annoyances at this point:
1) if you do not look at your console for a while, on the next glimpse you will see pages of debug content fly up as the display picks up of all the message you did not look at yet
2) no firephp on MSIE .. well there is firebug-lite and i guess with a bit of hackery, one could define a hidden place in the DOM/JSON response that could then be picked up by a firephp-lite and passed to firebug-lite ..
Brian DeShong
on Dec 17th, 2008
@ 5:09 pm:
On a related note, I plan to craft up a Zend_Cache_Profiler proposal very soon that will allow for out-of-the-box Memcached logging to FirePHP, just like Zend_Db_Profiler_Firebug.
We’ve built something similar for another Schematic project, so I’m making it a point to propose these things up as Zend Framework proposals.
Three cheers for ZF and its CLA!
AppBeacon
on Dec 19th, 2008
@ 2:19 pm:
FirePHP is a great tool. The developer, Christoph Dorn, is very easy to communicate with and fixes any bugs pretty quickly.
I would just point out that you must be very careful about preventing output to FirePHP when you deploy the final product. Imagine the fun people could have with your site if you exposed the underlying database info via a query that was sent to the console.
Matthew Purdon
on Dec 22nd, 2008
@ 11:21 am:
@Brandon Savage: I completely agree that in production your code should not have any warnings or notices (I always run Strict reporting anyway) But the point of this debug console is not to “log” things, but more to give you insight into what the application is doing. For example, 10 of us work on our little parts and we each do two db queries. It seems like we are writing good code, but when taken together we see in the firebug console that we are actually running 20 queries to build the page. Not cool. Firebug gives us insight into what our app is doing as a whole, in real time. As for logging errors, I don’t know anyone that writes all of their code perfectly on the first attempt. I personally hate having to go in and disable images or view source to try to find the error message or try to pretty-print it. With Firebug you get to easily see the error and the stack trace in a pretty little window.
@Lucas: I totally agree that the building of messages in the console is annoying. There should be an option in FireBug to reset after each request. *shrug*
@AppBeacon: Absolutely, we have a DEBUG=true flag in our dev config and it’s false in the production config. The nice part about the way I did it is that the Firebug writer isn’t even loaded in Production, so it’s very unlikely that you will be sending secret infos to the browser in production.