Logging errors in Zend Expressive 3

expressive

#1

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_log from 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.


#2

You’ve obviously put a lot of thought into this, and I can see some of your points, particularly around malformed requests. I’m not familiar with that code, so will have to have a dig.

But I’ve never run into the problems you describe. In my setup, everything goes to the web server’s error log.

In my docker dev environment that spews out in the docker output, along with access logs, mail logs and whatever else is going on. Doing it that way means there’s only one place to look, whether it’s a child segfaulting or an application exception.

In production it’s basically the same. The distro takes care of rotating things and the admins (hopefully) know where the corpses are buried.

I guess my point is: does this need changes to expressive, or should there be some kind of cookbook for a recommended setup?


#3

Hi kynx,

of course, everything that makes PHP explode (segfaults or just unhandled exceptions/errors) goes into the webserver’s log which is a “last resort” logging.

But that also means that for every single error you see in that error log a user got an “internal server error” message, most likely a blank page or (if mis-configured) some kind of “Fatal error…”.

This is not the kind of error handling I expect from a good piece of software. As a user I expect to see a friendly error page and as a developer I’d like to have this error in my project’s error log with additional context information (a stack trace, the URL, IP, user agent and some request infos like GET or POST parameters).

I think some kind of cookbook would be nice to have but to get all this working we need some minor changes to some expressive components, which shouldn’t break anything.


#4

There are manuals out there that show you where log files are saved or how to change that to your liking.

You quoted @mwop earlier and that applies to exactly this. This code should never make it to production. There are various tools out there which you can use in your CI or if you use an IDE like PhpStorm, it has inspections and show you warnings before you commit your code. You can even use a githook that detects var_dumps and more.
I assume that after you pushed code to the server you check it on the live site for correct behavior, at least for the parts you changed? So if there is a blank page, caused by a left over var_dump or echo, you catch it manually, fix it and push the fix.

If I remember correctly, only the ServerRequestFactory can throw errors if there are wrong HTTP protocol versions or un uploaded file is wrong. The first occurs when a users messed with it and changed the header to an invalid version or something. The uploaded file exception happens when there is no value for tmp_name. I don’t know what can cause this.
What I am saying here is that if there is an invalid request made, most likely by user manipulation, it’s allowed to fail.

Well, an user shouldn’t see more than an “internal server error” page. Everything more than that could be a security risk by exposing sensitive data.
In case of mis-configuration: If you have tests in place then this shouldn’t happen. Well maybe once in a while for forgetting a new local config setting after an update. But that is something you can catch and fix when testing the live server after pushing the new code.

So what can be done?

Configure the php error log correctly and check it regularly or even set it up in such way that exceptions are mailed to you or send to your corporate slack account.

You are right that users shouldn’t see a blank page. But if bootstrapping fails under whatever circumstance, you shouldn’t rely on that same failed system to display a nice error page. How about letting apache or nginx display a nicely formatted 500 page?


#5

Hi xtreamwayz,

thanks for sharing your thoughts.

You’re basically saying “we don’t do bugs, we can clean up everything before going to production”.
I’m – like you – developing software for >25 years now and I still see new weird things, even though we all use new cool tools and IDEs. Not all people are as experienced as you or Matthew or most of the core Zend framework developers.
Ask an average developer how he/she is doing logging. Non-existant probably :slight_smile:

So what can be done?

Configure the php error log correctly and check it regularly or even set it up in such way that exceptions are mailed to you or send to your corporate slack account.

Of course I configure my FPM pools to have a proper php.ini error_log set up. But this is nearly always empty because I catch the errors myself with much more context as would be available in error_log logging. Not sure on what projects you are working but leaving logging to PHP is just a last resort for me.

An example: Produce a PHP notice or warning within the bootstrapping phase or after your pipeline (for example coming from your Response stream reading/seeking). This PHP error is NOT converted to an exception. If display_errors is OFF it is just going nowhere. No log, no output, no problem?
If display_errors is ON (for whatever reason) the error is printed to stdout which results in Fatal error: Uncaught Zend\HttpHandlerRunner\Exception\EmitterException: Output has been emitted previously.....
This one (if not catched) goes to your PHP log. At least you know that something SOMEWHERE went wrong but you have exactly no clue where and what happened.

What I simply want is to have better error handling capabilities in Zend Expressive without too many workarounds. Not to leave it to PHP.
What if you want to log to some distributed logging system and not to the file system? Of course you could write to file which then get’s processed by a daemon…

What I am saying here is that if there is an invalid request made, most likely by user manipulation, it’s allowed to fail.

Of course! But wouldn’t it be nice it in a log somewhere? There are people installing WAFs to see weird stuff and Expressive decides to just drop that information? I don’t think WAFs are a solution nor helpful but not being able to track these errors isn’t helpful either.

You are right that users shouldn’t see a blank page. But if bootstrapping fails under whatever circumstance, you shouldn’t rely on that same failed system to display a nice error page. How about letting apache or nginx display a nicely formatted 500 page?

I could do that and some projects have just this config in place, but this is also some kind of last resort error page handling. Under “normal” conditions I would try emit an error page that has the normal header/footer with maybe the logged in status etc. A webserver 500 error page is just static.


#6

Well, that’s what we try don’t we? And I’m pretty sure that everyone pushed debug code to a live server in his life… several times. And there are always bugs in some way.

As it should be, at least during bootstrapping. You don’t know what failed and if what you need is available. Trying to access services for generating url’s, accessing user data, etc, that all may fail again and resulting in another exception while trying to recover from the current one. What if an invalid config setting causes bootstrapping the container to fail? Nothing is working in that case.


#7

Not exactly. I’m distinguishing between exeptions that occur due to broken input in forms, broken data coming from other systems, APIs not being available. These will be catched using the ErrorHandler and are safe for displaying a perfect non-static error page.

And then we have all these things that normally don’t break (aka bootstrapping and emitting), where we might even not have a ServerRequest instance at hand. These are fine to have a more static kind of error page and COULD potentially be handled by PHP error log + webserver magic. Expressive also distinguishes between these kinds with ErrorResponseGenerator and ServerRequestErrorResponseGenerator.
BUT this still leaves me with error logs without context information and I don’t see a reason why I should want this.

As said, I’m trying to catch as many exceptions as possible myself and only leave a small range of exceptions to PHP (like those in early bootstrapping, while setting up the container or if log files can’t be opened etc.).