php-http / logger-plugin Goto Github PK

Currently the request log is duplicated in the response log.

It is overhead in terms of logsize, neither do you know which request log really belongs to a response log in case of identical requests.

What about using a shared log context ID, that is unique per request. Solving both issues at once :)

PHP version: 8.0.3

Description
Request and response in context always empty.

How to reproduce
Enable plugin and do eny request.

Additional context

{"request":{"GuzzleHttp\\Psr7\\Request":[]},"response":{"GuzzleHttp\\Psr7\\Response":[]},"milliseconds":1185}

FullHttpMessageFormatter can add a request and a response to a log message, but they are still empty in context.

Actual Behavior

When you create a socket client with a logger plugin and make multiple requests, the opened files number is contently increasing.

Expected Behavior

The opened files should be stable, as it is without the logger plugin

Steps to Reproduce

Here is the test file:

I did a test on my Symfony project setup. Here is the test file:

use Docker\API\Model\ContainerConfig;
use Docker\Docker;
use Symfony\Component\Debug\Debug;

set_time_limit(0);

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

Debug::enable();
$kernel = new AppKernel('dev', true);
$kernel->boot();

$docker = $kernel->getContainer()->get(Docker::class);

$containerManager = $docker->getContainerManager();
$containerCreateResult = $containerManager->create(
    (new ContainerConfig())
        ->setImage('debian')
        ->setCmd(['sleep', '10'])
);
$containerId = $containerCreateResult->getId();
$containerManager->start($containerId);

while (true) {
    \usleep(500000);

    $findResponse = $containerManager->find($containerId);
    $serviceState = $findResponse->getState();
    echo "Running: ".(int) $serviceState->getRunning()."\t";
    echo "ExitCode: {$serviceState->getExitCode()}\t";
    echo "LSOF: ".exec('lsof | wc -l')."\n";
    if (!$serviceState->getRunning()) {
        $serviceResult = $serviceState->getExitCode();
        break;
    }

    // Other stuff
}

$containerManager->remove($containerId);

while (true) {
    sleep(1);
};

The httplug bundle configuration:

httplug:
  plugins:
    logger: ~
  clients:
    default:
      factory: 'httplug.factory.guzzle6'
      plugins: ['httplug.plugin.logger']
    docker:
      factory: 'httplug.factory.docker'
      plugins: ['httplug.plugin.logger']
  profiling:
    captured_body_length: 1000

The docker client special services:

httplug.factory.docker:
  class: AppBundle\Httplug\ClientFactory\CallableClientFactory
  arguments:
    $factory: [ Docker\DockerClient, 'createFromEnv' ]
Docker\Docker:
  public: true
  arguments:
    $httpClient: '@httplug.client.docker'

The CallableClientFactory class (see php-http/HttplugBundle#210 (comment)):

namespace AppBundle\Httplug\ClientFactory;

use Http\HttplugBundle\ClientFactory\ClientFactory;

final class CallableClientFactory implements ClientFactory
{
    private $factory;

    public function __construct(callable $factory)
    {
        $this->factory = $factory;
    }

    public function createClient(array $config = [])
    {
        return \call_user_func($this->factory, $config);
    }
}

And the DockerClient from the vendor: https://github.com/docker-php/docker-php/blob/1.24.0/src/DockerClient.php#L11-L34

As you can see, the Socket client is used here.

The installer httplug packages:

php-http/cache-plugin                          v1.5.0             PSR-6 Cache plugin for HTTPlug
php-http/httplug                               v1.1.0             HTTPlug, the HTTP client abstraction for PHP
php-http/httplug-bundle                        1.8.1              Symfony integration for HTTPlug
php-http/logger-plugin                         v1.0.0             PSR-3 Logger plugin for HTTPlug
php-http/stopwatch-plugin                      1.1.0              Symfony Stopwatch plugin for HTTPlug

Here is the output of the test script:

sullivan@5928a6b35210:/code$ php test.php 
Running: 1	ExitCode: 0	LSOF: 36
Running: 1	ExitCode: 0	LSOF: 39
Running: 1	ExitCode: 0	LSOF: 42
Running: 1	ExitCode: 0	LSOF: 45
Running: 1	ExitCode: 0	LSOF: 48
Running: 1	ExitCode: 0	LSOF: 51
Running: 1	ExitCode: 0	LSOF: 54
Running: 1	ExitCode: 0	LSOF: 57
Running: 1	ExitCode: 0	LSOF: 60
Running: 1	ExitCode: 0	LSOF: 63
Running: 1	ExitCode: 0	LSOF: 66
Running: 1	ExitCode: 0	LSOF: 69
Running: 1	ExitCode: 0	LSOF: 72
Running: 1	ExitCode: 0	LSOF: 75
Running: 1	ExitCode: 0	LSOF: 78
Running: 1	ExitCode: 0	LSOF: 81
Running: 1	ExitCode: 0	LSOF: 84
Running: 1	ExitCode: 0	LSOF: 87
Running: 1	ExitCode: 0	LSOF: 90
Running: 0	ExitCode: 0	LSOF: 93

The number of opened files is always increasing.

If I remove the plugins: ['httplug.plugin.logger'] line from the docker client configuration and run the script again:

sullivan@5928a6b35210:/code$ php test.php 
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 1	ExitCode: 0	LSOF: 24
Running: 0	ExitCode: 0	LSOF: 24

The number of opened fine is perfectly constant.

I opened an issue here because the only relation I found is this plugin, but I don't know if it's caused directly by this one, or the socket client or even a bad usage of this one.

What do you think?

cc @joelwurtz, maintainer of docker-php project.

The PSR logger interface specifies a context to provide extra information for the message. Since the current implementation is bounded to a predefined context it is not possible to affect this. We could use a message factory or something to generate messages in a custom way as solution.

Hi,

We have a certain flow that calls a certain API endpoint with their ID from our DB.

Because of data bookkeeping we may get a 4xx response, because their ID in our DB does not exists anymore.

The 4xx response pollutes our logs every now and then.

We do like to have default HTTP traffic logs.

In this case however, we'd like to opt-out 🙃

TLDR; what about using a special header for that? Thus X-Httplug-LoggerPlugin-Skip. It would be unset before doing the actual request.

Alternative revise the logger concept as a whole, since currently the extension point is only open to formatting. Not log context, log level, or if it should log the request even (this issue).

Actual Behavior

When a request is emitted, and then a log is received, what is actually logged looks like :

[2016-12-12 16:06:46] app.INFO: Emit request: "POST https://URL 1.1" {"request":"[object] (GuzzleHttp\\Psr7\\Request: {})"} []
[2016-12-12 16:06:47] app.INFO: Receive response: "201 Created 1.1" for request: "POST https://URL 1.1" {"request":"[object] (GuzzleHttp\\Psr7\\Request: {})","response":"[object] (GuzzleHttp\\Psr7\\Response: {})"} []

Same thing happens when an error happens :

[2016-12-12 16:06:47] app.INFO: Receive response: "500 Internal Server Error 1.1" for request: "POST https://URL 1.1" {"request":"[object] (GuzzleHttp\\Psr7\\Request: {})","response":"[object] (GuzzleHttp\\Psr7\\Response: {})"} []

The error message is not logged.

Expected Behavior

I expect the request and response contents to be logged

Steps to Reproduce

Just a send a request through php-http with LoggerPlugin enabled

Possible Solutions

I think only the request and response contents are missing.
WDYT ? Should I add these logs at another level in my app or does it make sense to update this plugin ?