Logging errors in Zend Expressive 3
Some background info on PHP error handling
In PHP error handling is split into exceptions (or to be more generic: throwables) and the good old PHP errors like E_NOTICE, E_WARNING, E_ERROR etc.
While throwables are easy to handle with try-catch (or using an exception handler) the latter are a bit of a left over from the pre-exception area in PHP. In Expressive as well as in many other frameworks these errors get converted to exceptions using an error handler.
After setting up this special error handler, all errors are then thrown as exceptions and can be easily catched.
Current situation in Expressive
The current situation is that there is no error logging at all.
This isn’t a good or bad thing by itself, it simply means that developers SHOULD take care of it and if they are serious about software development it’s an absolute MUST.
The question is how to get there and what Zend Expressive offers to help building proper error logging.
ErrorHandler middleware
Error handling in Expressive by default starts rather late with the first middleware in the middleware pipeline called ErrorHandler middleware. This middleware sets up the special error handler, then wraps the call to the next middleware into a try-catch block and restores the original error handler after the last middleware of the pipeline returns.
This plays well with the middleware concept and allows catching any \Exception or \Throwable that gets thrown all the way down in the middleware pipeline. The ErrorHandler is also responsible for displaying a nice error page and let’s you register listeners to further process the error. These listeners can be used for logging just by addding an ErrorHandler delegator factory that adds listener callbacks as required.
Unfortunately this leaves everything before (bootstrapping) and after (response emitting) the middleware uncovered.
Bootstrapping
The bootstrapping phase mainly consists of merging configs, setting up the container and calling Application’s run method.
@mwop told me that “if you have errors there [in the bootstrapping], the code should never make it to production. If you have errors there, the PHP logs are your friend”.
I don’t completely agree with him for the following reasons:
- Bootstrapping code get’s more complex with every component added. While the bootstrapping code should be straight forward without too much nested conditions (that might differ depending on the environment/request) it still is code that can fail and leaving the user with either a blank page[1] or an internal server error is not a good idea.
- PHP logs (
error_logfrom php.ini) are not set most of the time. It’s sometimes enabled in FPM pools config. If using nginx with FPM these errors go to the error.log from nginx which may be out of reach from a normal developer or it is simply not monitored.
Doing error handling in the bootstrapping phase is a bit trickier because if an error occurs at an early stage you might end up with no loggers available, but you still can cover at least everything after initialization of the container (and your loggers).
Response emitting
After the middleware pipeline has been run, the response is emitted which basically consists of sending headers and echoing the response body.
At first view it seems very unlikely that errors occur at this stage but there’s some chance you’ll run into assertNoPreviousOutput(). This assertion checks whether output has already been made and thus headers can’t be set afterwards. If it’s like that it throws an exception which results in either a blank page[1] or an internal server error page (from your webserver).
This happens whenever you use echo, var_dump, print_r or whatever generates output in your middleware. The middleware doesn’t care about the output (and there’s no output buffering by default) but it is triggering an unhandled exception while emitting a response.
Even in cases where you would expect a proper error page from the ErrorHandler because of an exception in the middleware pipeline, this assertion will result in not displaying anything if there was some output somewhere.
RequestHandlerRunner
A special case is the request handler runner which creates a new ServerRequest using the ServerRequestFactory and starts the pipeline using this request.
It wraps the creation of the ServerRequest in a try-catch block and instantly emits an error pages if something goes wrong. There’s no chance to handle the exception for logging and as it is catched it will never ever make it to any log. Of course, creation of the ServerRequest is not too error prone under normal circumstances but in case someone sends badly crafted HTTP requests the ServerRequestFactory will trigger an exception.
What can be done?
There are currently four places (bootstrapping, RequestHandlerRunner, ErrorHandler middleware and Response emitting) where errors can occur and we should be able to log them all without too much of a hassle.
Global try-catch
The easiest way would be to wrap most of the code in index.php in a “global” try-catch block and handle any throwable that might occur in the same way with proper logging and a nice error page.
This also includes setting up an error handler (as early as possible) that converts PHP errors to exceptions.
While this approach is easy to implement you would loose the most valuable context information, the ServerRequest which may be crucial to track down a bug. The ServerRequest instance is created within the RequestHandlerRunner and is only available there and in the middleware.
Global try-catch and ErrorHandler
A better approach would be the try-catch block just discussed plus an additional error handling in the ErrorHandler middleware. That way you could catch errors from middleware with the ServerRequest available as context and everything else is catched in the outer try-catch block defined in index.php.
However this still leaves exceptions from the Response emitting stage without the ServerRequest that was responsible for the generated response in first place.
Global try-catch with logger context
The problem with missing context for exceptions that are thrown from the Response emitting stage could be addressed by saving the ServerRequest instance somewhere where it can be accessed later in the global try-catch block, if available. This “somewhere” could be the logger that is being used to log the exception.
So instead of using the ErrorHandler middleware, we only need an middleware that consumes a logger and binds the ServerRequest to that logger i.e. using a processor (Zend\Log\Processor\ProcessorInterface) for that logger.
Emitting error pages
While the assertNoPreviousOutput() assertion is important for normal operation (we don’t what to see debug output in front of a zip file that gets streamed to output from your action handler) it seems a bit to strict for outputting an error page that should reach the customer by all means even if we have output above that page.
So I think we need some “force output” switch here or a response that additionally implements some kind of EmergencyResponseInterface interface.
Comments are welcome!
I’m currently learning how Zend Expressive works and how my colleagues and I might use it. And yes, logging is very important in my eyes which is why I wrote down this document.
Although logging is specific to the application or to your organization I still feel Zend Expressive should come with basic logging functionality included. At least it should be easy to add logging.
[1] I’m assuming display_errors is off which should be the default in a production environment.
