Realtime logging for Magento

There are a couple of things that animate me in PHP/Magento world.  The first is queuing.  I’ve written and spoken about that several times and do as much with it as possible.  The second is something that I’ve not written about nor done a lot of work in.

One of the other things that I have had in the back of my mind for the past several years is a cloud-based, completely integrated development environment.  Personally, I think that the development tooling in the PHP realm are still very young and basically come down to an IDE.  Debuggers are still not used as much as they should be.  var_dump() is our friend, right?

Ever since the Zend Developer Cloud started up it stirred in me some really interesting possibilities of what could be done.  Sadly they never happened, but the ideas remained.  If that doesn’t inspire you it’s because I’m not describing what I have in my head.  I don’t have the time to do that.

But this blog post is one part of it.  One of the things that is part of what I envision is a realtime logger that shows what is happening, as it is happening.  There is good software out there that shows what happened during a request, but it is always after the fact.  The Zend Server ZRay feature is a good example.  It’s a cool feature but doesn’t quite go as far as I have in mind.

With that in mind I spent some time last week working on a very small piece of this vision for Magento.  I wrote it really, really quickly and so don’t laugh when you look at the code and see obvious errors.  One error is the mechanism that I intended to use to shutdown logging when the watcher is not running, but sadly the pcntl code does not seem to do what I expect it to, which is odd because I copied and pasted the code from the documentation.

It is a combination of Magento extension and command line program that utilizes Redis PubSub for messaging passing.  It

• Hooks in to every Magento event and provides instrumentation for that
• Contains a log writer so that if an exception is logged or some message is logged it will pass it through to the watcher (no running through var/report again)
• Contains an SQL profiler that will provide any SQL queries in real time or a summary at the end of the request.

The logger in Magento is controlled by the watcher, which sends logging commands when it is started up.  Following is the help menu.

[kschroeder@devvm1 bin]$ php watcher.php --help
This script is used to connect to the front end of the Eschrade_PubSubLogger utility.
Note that if you are using the File cache backend you may need to clear it from /tmp if the user you are running this script under does not have permission in {magento}/var/cache.
Usage: watcher.php [ options ]
--all-events Listen for all events
--enable-blocks Enable block events (overrides all-events)
--enable-models Enable model events (overrides all-events)
--events <string> Comma-separated list of events to listen for (overides any settings)
--resolve-classes Look up the class based off of group class names
--hide-event-data Hides the event data when events are turned on
--hide-event-observers Hides the event observers when events are turned on
--delay-messages <integer> Delay messages by X milliseconds (default 75ms) - Makes it easier to follow the log
--no-color Turns off color coding of elapsed times
--show-request-id Show the unique ID for each request
--show-sql [ <string> ] Show the SQL in real time. Optionally add a preg_match() filter
--show-sql-summary Show the SQL summary at the end of the request
--help This help page

By default it just captures the URL, the request start time, the full action name and the elapsed time of the request.  Following are explanations for each option

• all-events – Turns on event monitoring.  It will provide the event name all the observers for that event and a summary of the data provided to the observers.  By default it turns off block and model events since they end up being noise most of the time.  This will only attach to configured events, not all events.  In other words, if an event has a configuration value in a config.xml it will be reported on.  If there is some event that is triggered somewhere it will not show up.
• enable-blocks – Turns on block events
• enable-models – Turns on model events
• events – provide a comma separated list of the specific events you want to watch for.
• resolve-classes – when examining event observers this flag will have it look up the class definition from the Magento config
• hide-event-data – Turns off the event data.  For example, if you are listening to controller_action_predispatch you will not see the controller action class that is passed to the observer
• hide-event-observers – Turns off printing the observers.  When done in conjunction with hide-event-data this will simply print out a list of all the observers as they are called with their elapsed execution time from the last event
• delay-messages – One of the things I noticed was that a lot of information comes in very quickly.  So I added a 75ms delay to each message.  Set to zero if you want no delay.
• no-color – If you are running it with event introspection it will color code elapsed time in events.  However those commands look like gibberish if you are piping to a file.  This turns that off
• show-request-id – The Magento extension automatically adds a unique ID to each request so you can track the source of logs or events.  However, the watcher does not turn this on by default.  This will turn it on.
• show-sql – Will show the SQL and its elapsed execution time in realtime as it happens.
• show-sql-summary – Shows a count of SQL operations, SELECT, INSERT, etc. at the end of a request.

Download it at github.