Sockets are never closed with symfony profiler activated

[soullivaneuh]

Q	A
Bug?	yes
New Feature?	no
Version	v1.0.0

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.

[Nyholm]

I tried to reproduce this but I have some issues with my docker installation.

 ▶ php bin/test.php
2018-01-06T13:00:01+00:00 [info] Emit request: "POST /containers/create 1.1"
2018-01-06T13:00:01+00:00 [error] Error: "Not Found" with response: "404 Not Found 1.1" when emitting request: "POST /containers/create 1.1"

I created a repo for this bug: https://github.com/Nyholm/php-http-logger-bug-3

[soullivaneuh]

@Nyholm thanks for your time. I setup a docker env and completed the readme to make it working.

But on your sample, I can't reproduce the issue. It's very weird because on my project, I have the issue right after adding the logger plugin on the client...

Any idea?

[joelwurtz]

How is configured monolog ?

[soullivaneuh]

On config_dev.yml file (used):

monolog:
  handlers:
    main:
      type: rotating_file
      date_format: 'Y-m'
      max_files: 2
      path: '%kernel.logs_dir%/%kernel.environment%.log'
      level: debug
      channels: ['!event']
    console:
      type: console
      process_psr_3_messages: false
      channels: ['!event', '!doctrine', '!console']
    # To follow logs in real time, execute the following command:
    # `bin/console server:log -vv`
    server_log:
      type: server_log
      process_psr_3_messages: false
      host: 127.0.0.1:9911

On config_prod.yml:

monolog:
  handlers:
    # Buffer the logs. Use them only on errors.
    main:
      type: fingers_crossed
      action_level: error
      handler: buffer
    console:
      type: console
      process_psr_3_messages: false
    # Buffer the logs before send it. This is useful for async notification.
    buffer:
      type: buffer
      handler: bridge
    bridge:
      type: group
      members: [file, slack]
    file:
      type: rotating_file
      max_files: 12
      date_format: 'Y-m'
      path: '%kernel.logs_dir%/%kernel.environment%.log'
      level: debug
    slack:
      type: slackwebhook
      webhook_url: '%slack_endpoint%'
      channel: '#bots'
      level: error
      include_extra: true

No common configuration.

[joelwurtz]

Can you try to remove this configuration :

server_log:
      type: server_log
      process_psr_3_messages: false
      host: 127.0.0.1:9911

and see if you have still this bug ?

[soullivaneuh]

@joelwurtz Just did it, nothing changed.

[soullivaneuh]

I did a full copy of my personal project and remove most of the code to try to isolate the issue: https://github.com/Nyholm/php-http-logger-bug-3/tree/project-case

And I think I got a new clue. If you remove this config part:

# app/config/config_dev.yml
framework:
  profiler: { only_exceptions: false }

The issue is not reproducible anymore.

Ref: https://github.com/Nyholm/php-http-logger-bug-3/blob/266111911dc402ff8dd37a58bbaf612fd0cd2728/app/config/config_dev.yml#L4-L7

So it seems to be related to the Symfony profiler. But why? What do you think?

Regards.

[Nyholm]

Great.

Im not sure why this is. If I may make a guess I would assume that the profiler temporary stores logs somewhere.
But you can solve your problem by just running your command in production environment, right?

[soullivaneuh]

But you can solve your problem by just running your command in production environment, right?

I suppose to, but for now I simply deactivated logging on the docker client:

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