Improve logging of http requests to aid debugging #3485

BillCarsonFr · 2023-06-19T13:47:31Z

Checklist

Tests written for new code (and old code if feasible)
Linter and other CI checks pass
Sign-off given on the changes (see CONTRIBUTING.md)

Added simple logging for all requests made from the js-sdk to ease rageshakes investigation.

~~Looks like that:~~

FetchHttpApi: GET --> http://localhost:8080/_matrix/client/r0/sync?filter=0&timeout=30000&since=s26_3787_3_8_29_1_12_38_0_1

udpated as per to remove url params that could contain secrets

FetchHttpApi: PUT --> /_matrix/client/v3/sendToDevice/m.room.encrypted/b8f4c87559504be794f3e1496a8970a5
rageshake.ts:77 FetchHttpApi:  <-- 200 8ms /_matrix/client/v3/sendToDevice/m.room.encrypted/b8f4c87559504be794f3e1496a8970a5
rageshake.ts:77 FetchHttpApi: PUT --> /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/typing/%40alice%3Alocalhost%3A8480
rageshake.ts:77 FetchHttpApi:  <-- 200 10ms /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/typing/%40alice%3Alocalhost%3A8480
rageshake.ts:77 FetchHttpApi:  <-- 200 2662ms /_matrix/client/r0/sync
rageshake.ts:77 FetchHttpApi: GET --> /_matrix/client/r0/sync
rageshake.ts:77 FetchHttpApi: PUT --> /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/typing/%40alice%3Alocalhost%3A8480
rageshake.ts:77 FetchHttpApi:  <-- 200 28ms /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/typing/%40alice%3Alocalhost%3A8480
rageshake.ts:77 FetchHttpApi:  <-- 200 247ms /_matrix/client/r0/sync
rageshake.ts:77 FetchHttpApi: GET --> /_matrix/client/r0/sync
rageshake.ts:77 FetchHttpApi: PUT --> /_matrix/client/v3/sendToDevice/m.room.encrypted/815dbfb5a7b54c9a9cfe09a8080a8704
rageshake.ts:77 FetchHttpApi:  <-- 200 10ms /_matrix/client/v3/sendToDevice/m.room.encrypted/815dbfb5a7b54c9a9cfe09a8080a8704
rageshake.ts:77 FetchHttpApi: PUT --> /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/send/m.room.encrypted/m1688377642353.0
rageshake.ts:77 FetchHttpApi:  <-- 200 30ms /_matrix/client/r0/rooms/!ZTAJxYLImTUucVDSZW%3Alocalhost%3A8480/send/m.room.encrypted/m1688377642353.0

This change is marked as an internal change (Task), so will not be included in the changelog.

t3chguy

Query parameters can contain secrets, we can't just print them all

Most of the secrets are ephemeral but some aren't single-use.

src/http-api/fetch.ts

BillCarsonFr · 2023-07-03T10:01:58Z

Query parameters can contain secrets, we can't just print them all

Most of the secrets are ephemeral but some aren't single-use.

I modified to just print out the url path

src/http-api/fetch.ts

t3chguy

Any chance of tests for this change?

BillCarsonFr · 2023-07-03T12:57:44Z

Any chance of tests for this change?

I could refactor a bit and extract a sort of "HttpFetchLogger" and add some unit test, could allow to have simple unit test to see if it's handling URL as expected and doing the time correctly.

Or are you thinking about more integrated tests with sending a rageshake and checking for log reports in the RS files?

t3chguy · 2023-07-03T12:59:45Z

I was thinking of a basic unit test which just mocks/stubs logger, calls http-api and asserts that logger was called with expected log lines

richvdh · 2023-07-07T10:46:32Z

It's a bit frustrating that real quality-of-life improvements like this get stuck behind a requirement for improved testing. Can we land it anyway without spending the time writing tests?

t3chguy · 2023-07-07T10:47:24Z

Given it has potential to leak secrets if it is broken I'd advocate for tests to assert that it does not...

richvdh · 2023-07-07T10:47:45Z

Most of the secrets are ephemeral but some aren't single-use.

If there are non-single-use secrets in query params, that seems like a problem, as such secrets will also get logged server-side. What are you thinking of?

.

src/http-api/fetch.ts

t3chguy

Small nits

I would have personally thought the logs would make more sense with the least granular thing first e.g.

FetchHttpApi: <-- $METHOD $URL [$TIME $STATUS/$ERROR]

For scanning logs I'd have thought keeping the method & url in a fixed column position would have been helpful

Fixed the test to not have status=undefined and not use 1234 for both the port and the time

spec/unit/http-api/fetch.spec.ts

Co-authored-by: Michael Telatynski <[email protected]>

Follow-up to #3485

* Log query parameters on HTTP requests Follow-up to #3485 * Only stringify once See #3591 (comment)

Since #3485, we log every request anyway, so there's no need to log twice.,

Simple request logging with status and duration

56abf74

BillCarsonFr requested a review from a team as a code owner June 19, 2023 13:47

BillCarsonFr requested review from andybalaam and germain-gg June 19, 2023 13:47

github-actions bot deployed to PR Documentation Preview June 19, 2023 13:50 View deployment

t3chguy requested changes Jun 19, 2023

View reviewed changes

erikjohnston reviewed Jun 22, 2023

View reviewed changes

src/http-api/fetch.ts Outdated Show resolved Hide resolved

germain-gg removed their request for review June 26, 2023 14:38

remove url params from logs

ecb9e4a

github-actions bot deployed to PR Documentation Preview July 3, 2023 09:56 View deployment

BillCarsonFr requested review from t3chguy and erikjohnston July 3, 2023 10:04

t3chguy previously requested changes Jul 3, 2023

View reviewed changes

src/http-api/fetch.ts Outdated Show resolved Hide resolved

superfluous toString()

6916723

github-actions bot deployed to PR Documentation Preview July 3, 2023 10:36 View deployment

t3chguy reviewed Jul 3, 2023

View reviewed changes

t3chguy added the T-Task Tasks for the team like planning label Jul 7, 2023

t3chguy changed the title ~~Fix | Http requests are not included in Rageshakes (https://github.com/vector-im/element-web/issues/25570)~~ Improve logging of http requests to aid debugging Jul 7, 2023

Add tests

b0d665c

github-actions bot deployed to PR Documentation Preview July 7, 2023 11:48 View deployment

t3chguy requested a review from richvdh July 7, 2023 13:20

richvdh reviewed Jul 7, 2023

View reviewed changes

src/http-api/fetch.ts Outdated Show resolved Hide resolved

src/http-api/fetch.ts Outdated Show resolved Hide resolved

src/http-api/fetch.ts Outdated Show resolved Hide resolved

Apply suggestions from code review

5a925d1

update snapshots

ce45066

richvdh requested a review from t3chguy July 11, 2023 15:51

t3chguy approved these changes Jul 11, 2023

View reviewed changes

spec/unit/http-api/fetch.spec.ts Outdated Show resolved Hide resolved

spec/unit/http-api/fetch.spec.ts Outdated Show resolved Hide resolved

spec/unit/http-api/fetch.spec.ts Outdated Show resolved Hide resolved

spec/unit/http-api/fetch.spec.ts Outdated Show resolved Hide resolved

github-actions bot deployed to PR Documentation Preview July 11, 2023 16:04 View deployment

update log format

31d5603

richvdh reviewed Jul 11, 2023

View reviewed changes

spec/unit/http-api/fetch.spec.ts Outdated Show resolved Hide resolved

richvdh and others added 2 commits July 11, 2023 18:19

Apply suggestions from code review

f19e801

Co-authored-by: Michael Telatynski <[email protected]>

update snapshot

091c0ca

richvdh enabled auto-merge July 11, 2023 17:20

github-actions bot deployed to PR Documentation Preview July 11, 2023 17:22 View deployment

richvdh added this pull request to the merge queue Jul 11, 2023

Merged via the queue into develop with commit 3385adf Jul 11, 2023
21 checks passed

richvdh deleted the valere/log_request_in_rs branch July 11, 2023 17:40

MadLittleMods mentioned this pull request Jul 11, 2023

HTTP requests are not included in rageshakes element-hq/element-web#25570

Closed

MadLittleMods added a commit that referenced this pull request Jul 11, 2023

Log query parameters on HTTP requests

3525658

Follow-up to #3485

MadLittleMods mentioned this pull request Jul 12, 2023

Log query parameters on HTTP requests #3591

Merged

3 tasks

github-merge-queue bot pushed a commit that referenced this pull request Jul 13, 2023

Log query parameters on HTTP requests (#3591)

8ef2e84

* Log query parameters on HTTP requests Follow-up to #3485 * Only stringify once See #3591 (comment)

richvdh added a commit that referenced this pull request Oct 4, 2023

Element-R: don't log every HTTP request

8fee5dc

Since #3485, we log every request anyway, so there's no need to log twice.,

richvdh mentioned this pull request Oct 4, 2023

Element-R: don't log every HTTP request #3780

Merged

github-merge-queue bot pushed a commit that referenced this pull request Oct 5, 2023

Element-R: don't log every HTTP request (#3780)

02ca5c7

Since #3485, we log every request anyway, so there's no need to log twice.,

richvdh mentioned this pull request Nov 9, 2023

Rageshake only reports a tiny number of logs these days element-hq/element-web#26532

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logging of http requests to aid debugging #3485

Improve logging of http requests to aid debugging #3485

BillCarsonFr commented Jun 19, 2023 •

edited by github-actions bot

Loading

t3chguy left a comment

BillCarsonFr commented Jul 3, 2023

t3chguy left a comment

BillCarsonFr commented Jul 3, 2023

t3chguy commented Jul 3, 2023 •

edited

Loading

richvdh commented Jul 7, 2023

t3chguy commented Jul 7, 2023

richvdh commented Jul 7, 2023

t3chguy left a comment •

edited

Loading

Improve logging of http requests to aid debugging #3485

Improve logging of http requests to aid debugging #3485

Conversation

BillCarsonFr commented Jun 19, 2023 • edited by github-actions bot Loading

Checklist

t3chguy left a comment

Choose a reason for hiding this comment

BillCarsonFr commented Jul 3, 2023

t3chguy left a comment

Choose a reason for hiding this comment

BillCarsonFr commented Jul 3, 2023

t3chguy commented Jul 3, 2023 • edited Loading

richvdh commented Jul 7, 2023

t3chguy commented Jul 7, 2023

richvdh commented Jul 7, 2023

t3chguy left a comment • edited Loading

Choose a reason for hiding this comment

BillCarsonFr commented Jun 19, 2023 •

edited by github-actions bot

Loading

t3chguy commented Jul 3, 2023 •

edited

Loading

t3chguy left a comment •

edited

Loading