php-http
Sockets are never closed with symfony profiler activated
| 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 https://github.com/php-http/HttplugBundle/issues/210#issuecomment-334863967):
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.
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
@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?
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.
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 ?
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.
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?
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