Access log: What options do you need?

[SimonFrings]

Our plan is to add more control over the AccessLogHandler thus giving the access log more configuration options. This way you can customize the information of your access log. The only questions now is: What should be configurable options for this and what should be defaults for each option? What information do you want to log and why?

Our current access log looks like this:

@clue and I already discussed this topic a bit and came up with a few ideas (log file, log format, etc.), we're interested to hear about your input!

[pfk84]

Something related: What about making the SapiHandler->log function available to the public as $app->log?
Obviously, this would allow us logging status messages in the same format as used by Framework X... Nothing that can't be reproduced, of course :)

[clue]

@pfk84 Interesting idea! I don't think this is related to how we would configure access logging, but I'm definitely open to the idea. Can you create a separate discussion for this? 👍

[clue]

Small progress update 1 now that PR #174 has been merged 🎉 This changeset makes the existing AccessLogHandler part of the public API. It can now be given explicitly to the App like this:

<?php

require __DIR__ . '/../vendor/autoload.php';

$app = new FrameworkX\App(
    new FrameworkX\AccessLogHandler(),
    new FrameworkX\ErrorHandler()
);

// Register routes here, see routing…

$app->run();

This is a starting point to add more options to control access logging in follow-up PRs as discussed here.

[clue]

Small progress update 2 now that PR #175 has been merged 🎉 This changeset adds support for loading the AccessLogHandler and ErrorHandler from the Container. They can now be given explicitly to the App like this:

<?php

require __DIR__ . '/../vendor/autoload.php';

$app = new FrameworkX\App(
    FrameworkX\AccessLogHandler::class,
    FrameworkX\ErrorHandler::class
);

// Register routes here, see routing…

$app->run();

On top of this, you may now configure the default handlers with an explicit DI container configuration like this:

<?php

require __DIR__ . '/../vendor/autoload.php';

$container = new FrameworkX\Container([
    FrameworkX\AccessLogHandler::class => fn () => new FrameworkX\AccessLogHandler()
]);

$app = new FrameworkX\App($container);

// Register routes here, see routing…

$app->run();

This is the next step in adding more options to control access logging and error handling in follow-up PRs as discussed here.

[clue]

At the moment, the AccessLogHandler MUST be followed by an ErrorHandler. This is done to ensure that any exceptions that appear in following handlers will be turned into a valid response before being passed back to the AccessLogHandler.

I wonder if we can relax this requirement and if so how, how should the AccessLogHandler behave if any following handler throws an exception? Should no log be written in this case? Should we write an error log instead (how is this different from what the ErrorHandler does)? Should we write a "normal" access log (what size does the response body have)?

I agree that being required to always pass an ErrorHandler after an AccessLogHandler is cumbersome to a certain degree. I have prepared a branch to relax this requirement, but I'm not sure how much sense it makes to lift this at the moment without having better answers for these questions.

[pfk84]

An access log entry with error 500 is a must I'd say. The sole responsibility for the error log should be on the ErrorHandler and if there's none, there should be no log either.

How will the response in such a case look like? Just the 500 status code with an empty body? Or Error 500: Internal Server Error? If empty, the size in the access log should be 0 as well, otherwise I'd say the length of the error message...

[clue]

An access log entry with error 500 is a must I'd say.

Completely agree and that's precisely why this is the default behavior even if you don't pass in an explicit AccessLogHandler or ErrorHandler.

The sole responsibility for the error log should be on the ErrorHandler and if there's none, there should be no log either.

I'm not sure I follow exactly what you're suggesting here, can you rephrase?

Right now, the AccessLogHandler has no special error handling logic implemented at all. It simply expects to be called before any ErrorHandler which takes care of any errors that happen in later request handlers. This is enforced by the App, so there's really no way you could use the AccessLogHandler without an ErrorHandler at the moment.

How will the response in such a case look like? Just the 500 status code with an empty body? Or Error 500: Internal Server Error? If empty, the size in the access log should be 0 as well, otherwise I'd say the length of the error message...

The ErrorHandler is responsible for turning any Exception (or Throwable) into a valid response with status code 500 Internal Server Error. By default, it renders an HTML response that is around ~1000 bytes in size that will be logged like any other normal response by the AccessLogHandler. There's ongoing discussion to configure and control the behavior of this ErrorHandler as discussed in #170.

[clue]

It would be useful if we could use a custom log format and specify custom variables to write as part of the access log.

For instance, we might be able to reuse variable names used elsewhere, e.g. nginx: http://nginx.org/en/docs/varindex.html. However, may want to provide additional variables e.g. for datetimes with millisecond or microsecond precision (only available through some hacks in nginx: https://thatsamguy.com/nginx-iso8601-time-format/)

# current default except for timestamp?
$time_iso8601_ms $remote_addr "$request" $status $body_bytes_sent $time $request_time
2023-07-21T17:30:03.725Z 127.0.0.1 "GET / HTTP/1.1" 200 13 0.000

# similar to current default, but with full URI
$time_iso8601_ms $remote_addr "$method $uri $server_protocol" $status $body_bytes_sent $time $request_time

# common
$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent

# combined
$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent"

The idea is to start with some predefined variables to cover most common use cases and allow users to pass in custom variables. For instance, #177/#172 allows overriding the $remote_addr variable for trusted proxies by passing this in as a request parameter.

[SimonFrings]

Progress update: @clue filed a pull request (#247) adding support for configuring a specific log file path. This can be achieved by passing an argument to the AccessLogHandler and choose a destination for your log messages like this:

<?php

require __DIR__ . '/../vendor/autoload.php';

$container = new FrameworkX\Container([
    'accesslog' => __DIR__ . '/../logs/access.log',
    FrameworkX\AccessLogHandler::class => fn(string $accesslog) => new FrameworkX\AccessLogHandler($accesslog)
]);

$app = new FrameworkX\App($container);

// …

This feature is the next step to introduce more options to control access logging and will be a part of the upcoming release of our first Framework X version (see https://twitter.com/x_framework/status/1762499173830778907).

If you enjoy our efforts and want to help us continue doing what we love, consider showing your support by leaving a sponsorship ❤️

I'll keep this ticket updated as we make progress with follow-up PRs 👍

[SimonFrings]

Progress update: After we added support for configuring a specific log file path in #247, we now improved the overall performance when specifically skipping the AccessLogHandler by choosing /dev/null as a destination for log messages (#248).

This can be easily reproduced by running a benchmark against any of the examples like this:

$ php public/index.php >/dev/null
$ docker run -it --rm --net=host jordi/ab -n100000 -c100 -k http://localhost:8080/

# old: 22678 requests per second
# new: 29232 requests per second

If you enjoy our efforts and want to help us continue doing what we love, consider showing your support by leaving a sponsorship ❤️