Allow logging request data in the debug log #1089

noplanman · 2020-05-02T21:29:30Z

?	!
Type	feature
BC Break	no
Fixed issues	#1088

Summary

Add a new TelegramLog::$always_log_request_and_response variable, to output request data to the debug log before posting the request itself to Telegram.

jacklul

LGTM but what about logging what $action was requested?

asafov

Looks great

asafov · 2020-05-02T22:01:46Z

LGTM but what about logging what $action was requested?

Action? You mean method? It's present in request URL.

jacklul · 2020-05-02T22:02:51Z

LGTM but what about logging what $action was requested?

Action? You mean method? It's present in request URL.

I don't think it's in $data though!

asafov · 2020-05-02T22:29:28Z

LGTM but what about logging what $action was requested?

Action? You mean method? It's present in request URL.

I don't think it's in $data though!

What you mean under "Action"? Example please.

noplanman · 2020-05-03T05:42:23Z

@jacklul As @asafov mentioned, the action / method is in the post URL.

My initial thought was to keep the $data output to show only the parameters that have actually been sent as the data body.

You think it should be added to the $data debug output?

asafov · 2020-05-03T05:50:08Z

This information for example helps me to debug MarkdownV2 chars.
Without it i will not be able to fix it.

jacklul · 2020-05-03T07:56:09Z

@jacklul As @asafov mentioned, the action / method is in the post URL.

My initial thought was to keep the $data output to show only the parameters that have actually been sent as the data body.

You think it should be added to the $data debug output?

Actually I was worried that sometimes the record with URL can not be just before the data one when bot is heavily used, then I remember you could use Monolog's UidProcessor to know which records were in the same request...

noplanman · 2020-05-03T10:52:34Z

@jacklul I now understand what you mean!! I've moved the request data output to "just before" the actual response, so if a separate process gets in-between those, all bets are lost anyway 😅

asafov · 2020-05-03T10:56:55Z

So what about log response data too?

noplanman · 2020-05-03T11:14:05Z

@asafov The HTTP response gets logged just after the (now) request data and the response body itself gets logged in the update log, read here:
https://github.com/php-telegram-bot/core/blob/78024d7bc55cebf3987247b465a1009b5186060a/doc/01-utils.md

Or do you mean something more than that?

asafov · 2020-05-03T11:17:24Z

I mean this situation for example:

[2020-05-03 03:37:05] production.DEBUG: Request Data: Array
(
    [chat_id] => 837010404
    [text] => %5Byandexnavi%3A%2F%2Fbuild_route_on_map%3Flat_to%3D55.822313%26lon_to%3D37.377214%5D%28%D0%9E%D1%82%D0%BA%D1%80%D1%8B%D1%82%D1%8C+%D0%AF%D0%BD%D0%B4%D0%B5%D0%BA%D1%81.%D0%9D%D0%B0%D0%B2%D0%B8%D0%B3%D0%B0%D1%82%D0%BE%D1%80%29
    [parse_mode] => MarkdownV2
)
  
[2020-05-03 03:37:05] production.DEBUG: Response Body: {"ok":false,"error_code":400,"description":"Bad Request: can't parse entities: Character '.' is reserved and must be escaped with the preceding '\\'"}
  
[2020-05-03 03:37:05] production.DEBUG: Verbose HTTP Request output:
* About to connect() to api.telegram.org port 443 (#1489)
*   Trying 149.154.167.220...
* Connected to api.telegram.org (149.154.167.220) port 443 (#1489)
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* SSL connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate:
* 	subject: CN=api.telegram.org,OU=Domain Control Validated
* 	start date: Mar 24 13:48:17 2020 GMT
* 	expire date: May 23 16:17:38 2022 GMT
* 	common name: api.telegram.org
* 	issuer: CN=Go Daddy Secure Certificate Authority - G2,OU=http://certs.godaddy.com/repository/,O="GoDaddy.com, Inc.",L=Scottsdale,ST=Arizona,C=US
> POST /botXXXXXX/sendMessage HTTP/1.1
User-Agent: GuzzleHttp/6.5.3 curl/7.29.0 PHP/7.2.27
Content-Type: application/x-www-form-urlencoded
Host: api.telegram.org
Content-Length: 382

* upload completely sent off: 382 out of 382 bytes
< HTTP/1.1 400 Bad Request
< Server: nginx/1.16.1
< Date: Sun, 03 May 2020 00:37:05 GMT
< Content-Type: application/json
< Content-Length: 150
< Connection: keep-alive
< Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
< Access-Control-Allow-Origin: *
< Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection
< 
* Connection #1489 to host api.telegram.org left intact

asafov · 2020-05-03T11:17:59Z

If query isn't successfully no any update log will be writed.

…able

noplanman · 2020-05-03T11:28:19Z

Ah yes, of course! Thought that was in the cURL response 🤦
(but only the reason is stated there, like HTTP/1.1 400 Bad Request)

asafov · 2020-05-03T11:33:00Z

Now you understand what i want? But my PR is incorrect too - it's log all responses, not only errors. Can you fix it? And i think that for errors not need param for log or not, coz it's real error.

noplanman · 2020-05-03T11:52:53Z

The way it is now, the debug log contains all requests, successful and failed.

I think you're right in that only errors should be logged, for de-bugging purposes.
(Which is confirmed on Wikipedia)

So it's probably best to change this behaviour altogether.
@jacklul What do you think? This would obviously be a BC change in the sense that logged output would be different from now on, but I must admit that the noise makes the debug log a difficult to use. Or introduce another variable to allow ALL logging? I guess that's what TRACE would be for, but we don't have that available.

jacklul · 2020-05-03T13:03:54Z

@asafov I've removed bot token you accidentaly posted with the log. You should generate a new one for safety.

@noplanman Any chance we could filter out bot tokens from the output ?
I think simple switch variable would be okay or option to pass separate Logger for http requests debug.

noplanman · 2020-05-03T13:15:38Z

Thanks for removing the key @jacklul.
@asafov Since GitHub remembers all edits and your API key can still be viewed, please reset it with @BotFather.

I like the idea of removing the API key from the debug output, but I'm just wondering of a use-case where it might actually help to see it to debug a problem 🤔
Should be easy to do with regex.

Regarding the separate logger, you're suggesting another logger instance on top of the two already set when initialising the logger?

asafov · 2020-05-03T13:33:48Z

@jacklul thank you very much.
@noplanman done, thank you.

jacklul · 2020-05-04T09:03:21Z

@noplanman Actually I just found out you can remove edit revisions too
I think having it by default remove the token might make it more safe to post the logs for people with technical issues

jacklul@8d02217

…t and add optional switch to also output it for successful requests.

noplanman · 2020-05-04T09:20:55Z

@jacklul Cool, thanks for the info, didn't know that!
Ah nice, a PR maybe for the API token removal?

I've updated this PR to include a variable TelegramLog::$always_log_request_and_response to define if request and response data should be output to the debug log, even when it's a successful request. Failed requests always get logged.

@asafov Could you have a quick look at this before I merge please?

jacklul · 2020-05-04T09:23:16Z

@jacklul Cool, thanks for the info, didn't know that!
Ah nice, a PR maybe for the API token removal?

I'll PR when I verify it doesn't remove anything else except token, so far I can see it messes up the dates

noplanman · 2020-05-04T09:27:51Z

Right. It would be nice if we had access to Telegram::getApiKey to literally just remove the API key, but we don't 😕

It might need more specific parameters, like '~/bot\d+:[\w\-]+/~' (untested)

jacklul · 2020-05-04T09:54:54Z

Actually I'm thinking if we could use second parameter of debug() function to post the array data to?
I don't know if there would be any benefit from this though!

noplanman · 2020-05-04T10:48:47Z

@jacklul You mean like this

TelegramLog::debug("Request data:\n{data}", ['data' => print_r($data, true)]);
TelegramLog::debug("Response data:\n{data}", ['data' => $result]);

instead of this?

TelegramLog::debug('Request data:' . PHP_EOL . print_r($data, true));
TelegramLog::debug('Response data:' . PHP_EOL . $result);

Not sure that helps with code readability though.

jacklul · 2020-05-04T10:59:33Z

@jacklul You mean like this
...

No, second argument for methods in PsrLog is context array.

TelegramLog::debug('Request data', $data);
TelegramLog::debug('Response data:' . PHP_EOL . $result);
TelegramLog::debug('Response data' , ['result' => $result]);

[2020-05-04 12:52:39] test.DEBUG: Request data {"offset":0,"limit":null,"timeout":null} []
[2020-05-04 12:52:39] test.DEBUG: Response data: 
{"ok":true,"result":[]} [] []
[2020-05-04 12:52:39] test.DEBUG: Response data {"result":"{\"ok\":true,\"result\":[]}"} []

Not sure that helps with code readability though.

It actually makes things even worse 😇
The only advantage is that (depending on logger) this can be used to further process the array/data.

I'd say leave it as it is now, if anyone requests it we could implement a switch for this in the future.

noplanman · 2020-05-04T11:54:07Z

I see, your code takes advantage of Monologs way of converting parameters into strings, in this case converting the $data array to JSON. Apix does the same.

This only works for frameworks with such behaviour, which (as far as I know) is not part of the PSR-3 spec. It's kind of "misusing" the context parameters.

We'll leave it as it is in that case.
Ready to merge then? 😃

Allow logging request data in the debug log

08b5a82

noplanman self-assigned this May 2, 2020

noplanman requested a review from a team May 2, 2020 21:38

jacklul approved these changes May 2, 2020

View reviewed changes

asafov approved these changes May 2, 2020

View reviewed changes

noplanman mentioned this pull request May 3, 2020

Ability to log response data from telegram server #1091

Closed

Write the request data just before writing the debug response.

a62e60e

asafov approved these changes May 3, 2020

View reviewed changes

Add documentation entry for new TelegramLog::$log_request_data vari…

c1a72a1

…able

noplanman added 2 commits May 4, 2020 11:14

Always output request and response data to debug log on failed reques…

449bd65

…t and add optional switch to also output it for successful requests.

Merge branch 'upstream/develop' into 1088-log_request_data

add4b88

noplanman requested a review from jacklul May 4, 2020 09:33

jacklul approved these changes May 4, 2020

View reviewed changes

Merge branch 'upstream/develop' into 1088-log_request_data

1b5827b

noplanman merged commit 617e524 into php-telegram-bot:develop May 4, 2020

noplanman deleted the 1088-log_request_data branch May 4, 2020 12:04

noplanman mentioned this pull request May 4, 2020

Log api.telegram response errors #733

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Allow logging request data in the debug log #1089

Allow logging request data in the debug log #1089

noplanman commented May 2, 2020 •

edited

jacklul left a comment

asafov left a comment

asafov commented May 2, 2020

jacklul commented May 2, 2020

asafov commented May 2, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

jacklul commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020 •

edited by jacklul

asafov commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

noplanman commented May 3, 2020

jacklul commented May 3, 2020 •

edited

noplanman commented May 3, 2020

asafov commented May 3, 2020

jacklul commented May 4, 2020 •

edited

noplanman commented May 4, 2020

jacklul commented May 4, 2020

noplanman commented May 4, 2020 •

edited

jacklul commented May 4, 2020 •

edited

noplanman commented May 4, 2020

jacklul commented May 4, 2020

noplanman commented May 4, 2020

Allow logging request data in the debug log #1089

Allow logging request data in the debug log #1089

Conversation

noplanman commented May 2, 2020 • edited

Summary

jacklul left a comment

Choose a reason for hiding this comment

asafov left a comment

Choose a reason for hiding this comment

asafov commented May 2, 2020

jacklul commented May 2, 2020

asafov commented May 2, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

jacklul commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020 • edited by jacklul

asafov commented May 3, 2020

noplanman commented May 3, 2020

asafov commented May 3, 2020

noplanman commented May 3, 2020

jacklul commented May 3, 2020 • edited

noplanman commented May 3, 2020

asafov commented May 3, 2020

jacklul commented May 4, 2020 • edited

noplanman commented May 4, 2020

jacklul commented May 4, 2020

noplanman commented May 4, 2020 • edited

jacklul commented May 4, 2020 • edited

noplanman commented May 4, 2020

jacklul commented May 4, 2020

noplanman commented May 4, 2020

noplanman commented May 2, 2020 •

edited

asafov commented May 3, 2020 •

edited by jacklul

jacklul commented May 3, 2020 •

edited

jacklul commented May 4, 2020 •

edited

noplanman commented May 4, 2020 •

edited

jacklul commented May 4, 2020 •

edited