[HttpClient] Add option to disable debug buffer in CurlResponse

[piotrekkr]

Description
I'm in need for an option to disable usage of debug buffer in CurlResponse. CurlResponse::getInfo() loads debug buffer to memory. Exceptions using HttpExceptionTrait triggers this method and sometimes this triggers memory size error:

Sentry\Exception\FatalErrorException: Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 236911944 bytes)
#0 /vendor/symfony/http-client/Response/CurlResponse.php(167): null

It is hard to debug actual reason of this since this is happening from time to time and on production server only. I don't need this debug information at all. Just HTTP status code would be enough and some response content. How can I disable this?

$ composer show | grep http-client 
psr/http-client                     1.0.0   Common interface for HTTP clients
symfony/http-client                 v4.3.5  Symfony HttpClient component
symfony/http-client-contracts       v1.1.7  Generic abstractions related to HTTP clients

[nicolas-grekas]

What makes you think this is related to the debug buffer?
The debug buffer is holding very few information, compared e.g. to the body of big responses.

[adrienfr]

Hello,

Don't know if this is related but we have the same memory error with HttpClient :

Symfony\Component\ErrorHandler\Error\OutOfMemoryError: Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 285792096 bytes)
#0 vendor/symfony/http-client/Response/CurlResponse.php(142): null

We tried to disable the buffer with $client->request('GET', $route, ['buffer' => false]); and use a streamed response but this doesn't fix anything.

This memory error occurs only on the first call, next calls are OK.

[nicolas-grekas]

Does the error disappear if you comment the line curl_setopt($ch, CURLOPT_VERBOSE, true); in CurlResponse.php?

[adrienfr]

Does the error disappear if you comment the line curl_setopt($ch, CURLOPT_VERBOSE, true); in CurlResponse.php?

Yes, I tried in my local environment with a lower memory_limit value, and the error is gone when I comment this line.

[nicolas-grekas]

OK thanks. Can you now uncomment the line again, and comment the next one?
curl_setopt($ch, CURLOPT_STDERR, $this->debugBuffer);

This will print the debug log to stderr, so you'll be able to "see" what's there.
It'd be interested in knowing what causes such a verbose log if you can share it (even privately).

[nicolas-grekas]

BTW, how many concurrent requests do you have? That might play a role also.

[nicolas-grekas]

Summary: the debug log is full of

* Expire in 200 ms for 1 (transfer 0x565147254b90)
* Expire in 200 ms for 1 (transfer 0x565147254b90)

and memory explodes when getInfo('debug') is called.
We might want to truncate the debug log to e.g. 2MB max

[piotrekkr]

@nicolas-grekas I've changed http_client class to NativeHttpClient in services.yml and problem disappeared :

    http_client:
        # https://github.com/symfony/symfony/issues/35975
        class: Symfony\Component\HttpClient\NativeHttpClient

NativeHttpClient works without errors for a week now. As far as I know native client don't have debug buffer so it seems to me like it can be the cause.

[nicolas-grekas]

@piotrekkr and @adrienfr can you please confirm #36038 fixes your issue?
If not @piotrekkr, can you follow the steps above and report what kind of repetitions you find in the output?

[adrienfr]

Seems good to me!

With your patch, debug file size is similar between each request.
Without it, I have a very large file with thousands of * Expire in 1 ms for 1 (transfer 0x5651472dfd50) lines inside every 1/5 request

[piotrekkr]

@nicolas-grekas I get logs with many lines like:

* Expire in 0 ms for 6 (transfer 0x560a63635460)
* Expire in 1 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 1 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 1 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 1 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)
* Expire in 0 ms for 1 (transfer 0x560a63635460)

Your patch works and debug info size is quite low and similar between requests.
I found that is known bug in curl library and docker php fpm images have curl with this bug.
I've tested on docker images:

php:7.3-fpm-buster
php:7.4-fpm-buster

Bug reports here:

https://curl.haxx.se/mail/lib-2019-02/0053.html
https://curl.haxx.se/mail/archive-2019-02/0013.html
https://www.linuxquestions.org/questions/slackware-14/curl-expire-in-1-ms-for-1-transfer-0xa5a060-4175649204/

[piotrekkr]

@nicolas-grekas @adrienfr Thanks for helping me out and finding what is the real problem. I still think that option for disabling verbose debug info would be nice to have :)

[nicolas-grekas]

Thanks for the confirmation. This means my PR is fixing your issue too, isn't it?
About the option, better not if we can avoid it. The less options the better.

[piotrekkr]

@nicolas-grekas Yes your PR resolves my problem, great work. Thanks. Should I close this issue or it will be closed when PR is merged?

[nicolas-grekas]

Which exact version of curl do you have @piotrekkr @adrienfr? Only 7.64.0 is affected apparently?

[adrienfr]

@nicolas-grekas

$ curl --version
curl 7.64.0 (x86_64-pc-linux-gnu) libcurl/7.64.0 OpenSSL/1.1.1d zlib/1.2.11 libidn2/2.0.5 libpsl/0.20.2 (+libidn2/2.0.5) libssh2/1.8.0 nghttp2/1.36.0 librtmp/2.3
Release-Date: 2019-02-06

[nicolas-grekas]

OK, so that kinda confirms the point. I'm mixed then: better do nothing here and let you upgrade curl instead, isn't it? Adding code for one specific version is quite a high maintenance cost to pay here...

[piotrekkr]

Same here:

$ docker run -it --rm -v "$(pwd):/var/www/html" php:7.4-fpm-buster bash
root@90e73865399b:/var/www/html$ curl --version
curl 7.64.0 (x86_64-pc-linux-gnu) libcurl/7.64.0 OpenSSL/1.1.1d zlib/1.2.11 libidn2/2.0.5 libpsl/0.20.2 (+libidn2/2.0.5) libssh2/1.8.0 nghttp2/1.36.0 librtmp/2.3
Release-Date: 2019-02-06
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

It is newest version curl available on debian 10. I quickly searched google how to upgrade or downgrade curl on buster but I didn't found anything usefull. It seems that solution would be using eaarlier docker image with php 7.3 and debian stretch:

$ docker run -it --rm  -v "$(pwd):/var/www/html" php:7.3-fpm-stretch bash
root@0409792af0de:/var/www/html# curl --version
curl 7.52.1 (x86_64-pc-linux-gnu) libcurl/7.52.1 OpenSSL/1.0.2u zlib/1.2.8 libidn2/0.16 libpsl/0.17.0 (+libidn2/0.16) libssh2/1.7.0 nghttp2/1.18.1 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

I'll test if this fix verbose logs

[piotrekkr]

Yeah downgrading curl or using docker image php:7.3-fpm-stretch with older curl fixes this without changing any code...

[nicolas-grekas]

Nice, thanks for the investigation. I updated the PR to just disable the debug log on curl 7.64.0.

[piotrekkr]

Ok, I'm closing this issue. My request has no meaning since it was caused by bug in curl. @nicolas-grekas @adrienfr thank you for your time and help.