How to implement a NCSA Common Line Format (CLF) logger middleware?

[shouze]

I've tried to procude NCSA CLF compatible logs for some REST Http server managed by aerys, here's the current state of my work:

class NcsaClfLogger implements Aerys\Bootable
{
    private $logger;

    function boot(Aerys\Server $server, Psr\Log\LoggerInterface $logger)
    {
        $this->logger = $logger;
    }

    function __invoke(Aerys\Request $request, Aerys\Response $response)
    {
        // We should probably return and/or partialy collect info until the response is in ended state?
        // NCSA / CLF log line format
        // @see https://en.wikipedia.org/wiki/Common_Log_Format
        $logLine = sprintf(
            '%s %s %s [%s] "%s %s HTTP/%s" %s %s',
            $request->getHeader('X-Forwarded-For') ?? $request->getConnectionInfo()['client_addr'],
            '-',
            '-',
            date('d/M/Y:H:i:s O'),
            $request->getMethod(),
            $request->getUri(),
            $request->getProtocolVersion(),
            $response->__debugInfo()[':status'], // no other way to get the response status + we should ensure it's the final status
            0 // how to get response size? We should probable get it when response is in ended state but how?
        );
        $this->logger->info($logLine);
    }
}

And here's the result in aerys logs:

aerys -c bin/server
[2017-10-26 13:57:01] warning 203.0.113.195, 70.41.3.18, 150.172.238.178 - - [26/Oct/2017:13:57:01 +0000] "GET /health HTTP/1.1" 200 0
[2017-10-26 13:57:04] warning 172.17.0.1 - - [26/Oct/2017:13:57:04 +0000] "GET /health HTTP/1.1" 200 0
[2017-10-26 13:57:06] warning 203.0.113.195, 70.41.3.18, 150.172.238.178 - - [26/Oct/2017:13:57:06 +0000] "GET /health HTTP/1.1" 200 0
[2017-10-26 13:57:07] warning 172.17.0.1 - - [26/Oct/2017:13:57:07 +0000] "GET /health HTTP/1.1" 200 0

I have few questions:

• How to get & return the response size ? Response always seem to be in state NONE in the middleware.
• Is there a better way to get the response status and to ensure that's the correct one? Here in my implementation it will always return 200. (also related to response state of course).
• How can I avoid aerys to prefix log lines by itself? Where can I override the default log line format/handler?

[kelunik]

I've implemented such a logger for PHP-PM, you can find it here.

You need to calculate the response size yourself. The first yield gives your the headers, all further yields give you the response body.

You can override the magic $logger variable in the config. Yes, it's not perfect, but it works for now.

[shouze]

@kelunik ok thank you very nice! Last question: with this middleware design, do you think it would be possible to also grab request execution time? As the middleware as not the true workload responsibility... I'm still trying to find out how to do that.

[shouze]

After looking at the documentation I guess I can maybe use local vars to pass this kind of information, I will give it a try!

[kelunik]

You don't have to. Just assign $start = microtime(true); before the first yield and calculate the time after the last yield.

[shouze]

@kelunik thank you, it works perfectly 👍 . Just one thing: we're agree that I would have to put the log level to warning to have it logged in prod env by default... I wonder why minimum log level shouldn't be info or notice?

Also, ATM if I want to replace the Aerys logger by another PSR compliant one, I guess it's impossible no? I would have to create my own custom aerys bin as in config we can of course replace later the logger by another one but the initial one could already have logged things.

https://github.com/amphp/aerys/blob/74ee552ef7e2d11fe7c3ab4b686c904d67e954c1/bin/aerys#L125-L132

[kelunik]

I have actually no idea why it suggests warning for production. I guess the logger originally was only supposed to log server things, not for application logs.

Suggestions for the logger configuration are always welcome. 👍

[shouze]

I've made some progress, I use a symfony app with monolog (which objectively brings some cools things about context serialization for example, and so on...).

So, very early in the Aerys config I replace the current $logger var by a Psr proxy one which is basically a monolog logger with modified formatter to avoid duplicating some informations already in the Aerys logger.

This is looking like that:

final class FormattedPsrHandler extends Monolog\Handler\AbstractProcessingHandler
{
    private $logger;

    public function __construct(LoggerInterface $logger, $level = Logger::DEBUG, $bubble = true)
    {
        parent::__construct($level, $bubble);
        $this->logger = $logger;
    }

    public function write(array $record)
    {
        if (!$this->isHandling($record)) {
            return false;
        }
        $this->logger->log(
            strtolower($record['level_name']),
            $record['formatted'] ?? $record['message'],
            $record['context']
        );
        return false === $this->bubble;
    }
}

$psrHandler = new FormattedPsrHandler($logger, Monolog\Logger::DEBUG, true);
$psrHandler->setFormatter(
    new Monolog\Formatter\LineFormatter('%message% %context%')
);
$logger = new Monolog\Logger('app', [$psrHandler]);

$symfonyKernel = new WebKernel($env, $debug);
$symfonyKernel->boot();
$symfonyKernel->getContainer()->set('logger', $logger);

Ok so I suggest:

1. to remove or change this warning for production.
2. to add a setFormat method on the Aerys logger and to start logging only when the configuration setup is done, thus avoiding to have various log formats when it comes to customize the logging part.

For the 1st point I can make a quick PR, no problem.
About the 2nd one, looking at the code the implementation don't look that trivial ATM so I guess we should have a discussion about the way to do things.

[kelunik]

Maybe we should just recommend to use a custom bin/aerys file.

[shouze]

yes custom bin/aerys is a solution. I've managed to still use bin/aerys BTW and I have a decent SymfonyBridge with a pleasant monolog adapter now.

Closing this one and have opened https://github.com/amphp/aerys/pull/201 about the log warning.

[bwoebi]

For the second point, if I see that correctly, the only logger output before config file inclusion is:
https://github.com/amphp/aerys/blob/74ee552ef7e2d11fe7c3ab4b686c904d67e954c1/lib/Internal/functions.php#L92

We could move that a few lines down as stacktraces anyway will include the config file at that point. (so all necessary information still present if it throws)

[shouze]

@bwoebi would be great indeed!