[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors #35659

B-Galati · 2020-02-10T08:43:46Z

Q	A
Branch?	master
Bug fix?	no
New feature?	yes/no
Deprecations?	no
Tickets	Fix #34289
License	MIT
Doc PR	symfony/symfony-docs#...

Tests
Doc
Changelog

Add HttpClient monolog processor that will write http request / response info in log context.
It can help debugging 4XX / 5XX in a prod context.

Processor can be enabled like this:

services:
    Symfony\Bridge\Monolog\Processor\HttpClientProcessor:
        tags:
            - { name: monolog.processor }

…nt errors

B-Galati · 2020-02-10T08:55:07Z

@nicolas-grekas

At the moment the processor is not able to log http client content for some reasons.

I try to dig a bit and observed that this code is able to get the response content while the processor cannot:

$response = $this->httpClient->request('GET', 'https://127.0.0.1:8000/sleep/1/throw');
try {
    $response->getContent();
} catch(HttpExceptionInterface $e) {
    dump($e->getResponse()->getContent(false));
}

My guess is that the CurlResponse::__destruct is doing stuff that may trash/cancel the request/response.

nicolas-grekas · 2020-02-10T08:56:54Z

If you don't read the content, neither will the client. The destructor will ensure headers arrived and close the stream just after. Why would it care about the body if the app doesn't ?

B-Galati · 2020-02-10T09:02:22Z

@nicolas-grekas Thanks for the quick answer.

For example, I was calling an API to update a user profile but that request ends in a 400 because one of the field was wrongly formatted.
The only way to know which field and why, was to read the response content.

nicolas-grekas · 2020-02-10T11:32:20Z

Then this should be done on the app's side, not in the processor (or you're taking the risk of logging an ISO/AVI file content...)

B-Galati · 2020-02-10T12:17:02Z

Then this should be done on the app's side, not in the processor (or you're taking the risk of logging an ISO/AVI file content...)

That's quite cumbersome to do sadly but I see your point. What do you think if we add safe guards like:

Check content size before downloading it? if it's too large let's not even log it.
Check if the content-type is safe for logging or not? Whitelist some of them like json, xml, text, etc.

At the moment the processor truncates the content in log after 10.000 characters.

nicolas-grekas · 2020-02-10T14:03:21Z

How are people going to enable this processor? Maybe you can update the description of the PR to hint about this as that'd help write the doc afterward?
If it's via service configuration, then providing constructor arguments telling which content-types should log the body might be a fit?
Don't miss fabbot's report, adding tests and a line in the changelog of course :)

B-Galati · 2020-02-10T14:35:55Z

How are people going to enable this processor? Maybe you can update the description of the PR to hint about this as that'd help write the doc afterward?

Updated.

If it's via service configuration, then providing constructor arguments telling which content-types should log the body might be a fit?

Yeap!

Don't miss fabbot's report, adding tests and a line in the changelog of course :)

Yeap it's on my todo but I wanted to talk about it before going too far for 2 reasons:

The response content is not logged when the Exception is thrown by CurlResponse::__destruct() and it was the big plus of the feature; at least to me. It is working at the moment for me with Symfony 4.3. I don't know what changed in 5.x. I am not sure to end this PR if I cannot get this working as it was the main reason I did it in the 1st place.
We talk about having the processor not breaking asynchronicity of the client in the issue but I don't really get how to achieve it.

nicolas-grekas · 2020-02-10T14:42:49Z

The response content is not logged when the Exception is thrown by CurlResponse::__destruct()

I don't get this issue as the response is not destructed yet when the exception is processed, so you should be able to get the body

the processor not breaking asynchronicity

that's not possible, but if this is opt-in (eg by default the body is ever logged), then this is fine I think.

B-Galati · 2020-02-10T15:19:16Z

I don't get this issue as the response is not destructed yet when the exception is processed, so you should be able to get the body

I will set up a reproducer tomorrow hopefully.

that's not possible, but if this is opt-in (eg by default the body is ever logged), then this is fine I think.

Thanks! So what did you have in mind with this comment #34289 (comment)?

nicolas-grekas · 2020-02-10T15:21:08Z

My previous comment is not very relevant in the context of errors :)

B-Galati · 2020-02-11T07:32:53Z

@nicolas-grekas Hello! Here is the reproducer https://github.com/B-Galati/symfony_reproducer_34289

Let me know for anything.

nicolas-grekas · 2020-02-11T13:54:09Z

src/Symfony/Bridge/Monolog/Processor/HttpClientProcessor.php

+        while ($exception instanceof \Throwable) {
+            if ($exception instanceof HttpExceptionInterface) {
+                // It needs to be the 1st statement in order to fulfil the response info
+                $responseContent = $exception->getResponse()->getContent(false);


this must be wrapped in a try/catch(TransportExceptionInterface)

nicolas-grekas · 2020-02-11T13:54:49Z

src/Symfony/Bridge/Monolog/Processor/HttpClientProcessor.php

+
+                $record['context']['http_client'][] =
+                    $exception->getResponse()->getInfo()
+                    + ['response_content' => mb_strimwidth($responseContent, 0, 10000)]


mb_strimwidth is random to me (all mb_* without encoding arguments are, relying on global state).

Do you think it should be removed? What would be the alternative otherwise, specify the $encoding argument?

I guess it can be removed if the response size is checked before trying to get the content. WDYT?

@B-Galati

…ctor throwed an HttpExceptionInterface (nicolas-grekas) This PR was merged into the 4.4 branch. Discussion ---------- [HttpClient] fix getting response content after its destructor throwed an HttpExceptionInterface | Q | A | ------------- | --- | Branch? | 4.4 | Bug fix? | yes | New feature? | no | Deprecations? | no | Tickets | - | License | MIT | Doc PR | - Spotted by @B-Galati in #35659 (comment) Commits ------- 6d1657b [HttpClient] fix getting response content after its destructor throwed an HttpExceptionInterface

buteihua · 2020-02-11T17:07:08Z

OK

…

------------------ 原始邮件 ------------------ 发件人: "Benoit GALATI"<notifications@github.com>; 发送时间: 2020年2月12日(星期三) 凌晨1:00 收件人: "symfony/symfony"<symfony@noreply.github.com>; 抄送: "Subscribed"<subscribed@noreply.github.com>; 主题: Re: [symfony/symfony] [HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors (#35659) @B-Galati commented on this pull request. In src/Symfony/Bridge/Monolog/Processor/HttpClientProcessor.php: > + public function __invoke(array $record): array + { + $exception = $record['context']['exception'] ?? null; + + if ($exception === null) { + return $record; + } + + while ($exception instanceof \Throwable) { + if ($exception instanceof HttpExceptionInterface) { + // It needs to be the 1st statement in order to fulfil the response info + $responseContent = $exception->getResponse()->getContent(false); + + $record['context']['http_client'][] = + $exception->getResponse()->getInfo() + + ['response_content' => mb_strimwidth($responseContent, 0, 10000)] I guess it can be removed if the response size is checked before trying to get the content no. WDYT? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or unsubscribe.

nicolas-grekas · 2020-03-31T19:34:32Z

I'm not sure this is appropriate, especially if you consider prod: $response->getInfo() can contain personal data (eg cookies). What's the minimum amount of info that would be useful?

B-Galati · 2020-03-31T20:05:18Z

@nicolas-grekas Agree! I think response_headers, redirect_count, redirect_url and response_content should be enough no?

B-Galati · 2020-04-03T05:44:34Z

In fact, cookies are initially set by response headers so that's not what we want :D

B-Galati · 2020-06-27T13:06:08Z

@nicolas-grekas Sounds like a decorator using AsyncDecoratorTrait #36779 with a logger would do a better job than that no?

nicolas-grekas · 2020-06-30T13:17:13Z

@B-Galati AsyncDecoratorTrait would hook very differently, not sure it would cover the same need. On 2nd thought, I think it's OK to "break" async here - the exception has already been thrown. About the body, let's use the same regexp as in HttpClientTrait to log based on the content-type? '#^(?:text/|application/(?:.+\+)?(?:json|xml)$)#i' No need to truncate then to me, at least as a 1st step.

B-Galati · 2020-07-07T13:42:27Z

Indeed! The LoggerDecorator would log a lot more information that may be useless.

The regexp looks good to me 👍, very nice!

fabpot · 2020-08-18T14:16:21Z

@B-Galati What's the status of this PR?

B-Galati · 2020-08-18T18:00:41Z

@fabpot still WIP. I am going to change the status.

fabpot · 2020-08-23T17:43:28Z

@B-Galati My question was more about the mergeability status estimated time. If it won't be ready in the next few weeks, I'd recommend to close it and reopen when ready.

B-Galati · 2020-08-23T18:35:36Z

Sounds good to me 👍

carsonbot added Status: Needs Review MonologBridge Feature labels Feb 10, 2020

B-Galati changed the title ~~[MonologBridge] Add HttpClientProcessor to debug HttpClient errors~~ [HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors Feb 10, 2020

[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClie…

6ef1c2e

…nt errors

B-Galati force-pushed the 34289_http_client_monolog_processor branch from de54fe9 to 6ef1c2e Compare February 10, 2020 08:44

nicolas-grekas added this to the next milestone Feb 10, 2020

nicolas-grekas mentioned this pull request Feb 11, 2020

[HttpClient] fix getting response content after its destructor throwed an HttpExceptionInterface #35674

Closed

nicolas-grekas reviewed Feb 11, 2020

View reviewed changes

B-Galati marked this pull request as draft August 18, 2020 18:01

B-Galati closed this Aug 23, 2020

nicolas-grekas modified the milestones: next, 5.2 Oct 5, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors #35659

[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors #35659

B-Galati commented Feb 10, 2020 •

edited

Loading

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 11, 2020

nicolas-grekas Feb 11, 2020

nicolas-grekas Feb 11, 2020

B-Galati Feb 11, 2020

B-Galati Feb 11, 2020 •

edited

Loading

buteihua commented Feb 11, 2020 via email

nicolas-grekas commented Mar 31, 2020 •

edited

Loading

B-Galati commented Mar 31, 2020

B-Galati commented Apr 3, 2020

B-Galati commented Jun 27, 2020

nicolas-grekas commented Jun 30, 2020

B-Galati commented Jul 7, 2020

fabpot commented Aug 18, 2020

B-Galati commented Aug 18, 2020

fabpot commented Aug 23, 2020

B-Galati commented Aug 23, 2020

[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors #35659

[HttpClient][MonologBridge] Add HttpClientProcessor to debug HttpClient errors #35659

Conversation

B-Galati commented Feb 10, 2020 • edited Loading

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 10, 2020

nicolas-grekas commented Feb 10, 2020

B-Galati commented Feb 11, 2020

nicolas-grekas Feb 11, 2020

Choose a reason for hiding this comment

nicolas-grekas Feb 11, 2020

Choose a reason for hiding this comment

B-Galati Feb 11, 2020

Choose a reason for hiding this comment

B-Galati Feb 11, 2020 • edited Loading

Choose a reason for hiding this comment

buteihua commented Feb 11, 2020 via email

nicolas-grekas commented Mar 31, 2020 • edited Loading

B-Galati commented Mar 31, 2020

B-Galati commented Apr 3, 2020

B-Galati commented Jun 27, 2020

nicolas-grekas commented Jun 30, 2020

B-Galati commented Jul 7, 2020

fabpot commented Aug 18, 2020

B-Galati commented Aug 18, 2020

fabpot commented Aug 23, 2020

B-Galati commented Aug 23, 2020

B-Galati commented Feb 10, 2020 •

edited

Loading

B-Galati Feb 11, 2020 •

edited

Loading

nicolas-grekas commented Mar 31, 2020 •

edited

Loading