server: consistently log request_id at the same level #6244

lorenzo · 2020-11-23T16:59:33Z

Description

Before this change, the server is logging requests with a different
shape.

HTTPLog

{
  "type": "http-log",
  "timestamp": "2020-11-23T17:30:41.782+0100",
  "level": "info",
  "detail": {
    "operation": {
      "query_execution_time": 8.6201e-05,
      "user_vars": {
        "x-hasura-role": "admin"
      },
      "request_id": "f579069a-23fc-4119-b2d8-4bab1a4e29e6",
      "response_size": 347,
      "request_read_time": 3.884e-06
    },
    "http_info": {
      "status": 200,
      "http_version": "HTTP/1.1",
      "url": "/foo",
      "ip": "127.0.0.1",
      "method": "GET",
      "content_encoding": "gzip"
    }
  }
}

QueryLog

{
"detail":  {
  "query": {...}
  "request_id": "90b07309-38c1-483c-800e-9d51bd457797"
...
}

Notice that the request_id is nested in different levels in both
examples. This makes correlating the requests a bit more difficult than
it should be.

For instance, services like DataDog allow you to extract a json path as
a facet that can be used in searches. Since the request_id is at a
different level, it is not possible to correlate using the request_id.

After this change, the HttpLog will look like

{
"detail":  {
  "http_info" {...}
  "operation" {
    "query_execution_time": 0.001201056,
    "request_id": "e9bd9dd2-f5b3-4e26-9d88-9a39cff5acbb"
    ...
  },
  "request_id": "e9bd9dd2-f5b3-4e26-9d88-9a39cff5acbb"
},
"level": "info",
"timestamp": "2020-11-23T16:48:07.173+0000",
"type":	"http-log"
}

The request_id is still present in the operation key for backward
compatibility.

Changelog

CHANGELOG.md is updated with user-facing content relevant to this PR. If no changelog is required, then add the no-changelog-required label.

Affected components

Related Issues

Solution and Design

Steps to test and verify

Limitations, known bugs & workarounds

Server checklist

Catalog upgrade

Does this PR change Hasura Catalog version?

No
Yes
- Updated docs with SQL for downgrading the catalog

Metadata

Does this PR add a new Metadata feature?

No
Yes
- Does run_sql auto manages the new metadata through schema diffing?
  - Yes
  - Not required
- Does run_sql auto manages the definitions of metadata on renaming?
  - Yes
  - Not required
- Does export_metadata/replace_metadata supports the new metadata added?
  - Yes
  - Not required

GraphQL

No new GraphQL schema is generated
New GraphQL schema is being generated:
New types and typenames are correlated

Breaking changes

hasura-bot · 2020-11-23T16:59:36Z

Beep boop! 🤖

Hey @lorenzo, thanks for your PR!

One of my human friends will review this PR and get back to you as soon as possible.

Stay awesome! 😎

netlify · 2020-11-23T17:01:20Z

✔️ Deploy preview for hasura-docs ready!

🔨 Explore the source changes: fbe0b8e

🔍 Inspect the deploy logs: https://app.netlify.com/sites/hasura-docs/deploys/60043e75df9a59000899e980

😎 Browse the preview: https://deploy-preview-6244--hasura-docs.netlify.app

ecthiender · 2020-11-27T07:14:16Z

Hi @lorenzo

Can you help me understand the problem? I think I'm missing something.

You say:

Notice that the request_id is nested in different levels in both examples. This makes correlating the requests a bit more difficult than it should be.

But from the above sample log lines, I can see in the current shape:

http-log has request_id in .detail.operation.request_id
query-log has request_id in .detail.operation.request_id

So they're both at the same level right? I think I'm missing something, can you help me with it?

lorenzo · 2020-11-27T09:02:39Z

@ecthiender Sorry, I messed up the log outputs in the description. I had copied twice the same example from the log output thinking they were different. I have changed the description, but I'll summarize here again:

http-log: detail.operation.request_id
query-log: detail.request_id

After this change both will have: detail.request_id.

For backwards-compatibility, http-log will keep detail.operation.request_id as well.

lorenzo · 2020-12-04T21:41:51Z

@ecthiender did that clarify the issue for you?

ecthiender · 2020-12-05T05:36:02Z

@lorenzo yes it did. Thanks for the clarification. And sorry for the delay!

tirumaraiselvan

no changelog required

tirumaraiselvan · 2020-12-21T01:54:01Z

@lorenzo The docs would also require a change, correct? https://hasura.io/docs/1.0/graphql/core/deployment/logging.html#http-log-structure

As this is user-facing, a changelog would be preferred. Something like: "add request_id to top level in http-log"

tirumaraiselvan

#6244 (comment)

hgiasac · 2020-12-21T03:00:58Z

Just to confirm, will detail.operation.request_id field be removed on future release?

tirumaraiselvan · 2020-12-21T10:58:02Z

Just to confirm, will detail.operation.request_id field be removed on future release?

I don't think we can remove it without a major version bump. So it should not be removed anytime soon.

lorenzo · 2021-01-09T11:53:04Z

@tirumaraiselvan jus to make sure, should I be changing the docs and adding a line to the changelog?

tirumaraiselvan · 2021-01-11T06:35:57Z

@lorenzo Pls do!

lorenzo · 2021-01-17T13:38:47Z

@tirumaraiselvan done. Can you please review again?

Before this change, the server is logging requests with a different shape. - HTTPLog ```json { "type": "http-log", "timestamp": "2020-11-23T17:30:41.782+0100", "level": "info", "detail": { "operation": { "query_execution_time": 8.6201e-05, "user_vars": { "x-hasura-role": "admin" }, "request_id": "f579069a-23fc-4119-b2d8-4bab1a4e29e6", "response_size": 347, "request_read_time": 3.884e-06 }, "http_info": { "status": 200, "http_version": "HTTP/1.1", "url": "/foo", "ip": "127.0.0.1", "method": "GET", "content_encoding": "gzip" } } } ``` - QueryLog ```json { "detail": { "http_info" {...} "operation" { "query_execution_time": 0.001201056, "request_id": "e9bd9dd2-f5b3-4e26-9d88-9a39cff5acbb" ... } }, "level": "info", "timestamp": "2020-11-23T16:48:07.173+0000", "type": "http-log" } ``` Notice that the `request_id` is nested in different levels in both examples. This makes correlating the requests a bit more difficult than it should be. For instance, services like DataDog allow you to extract a json path as a facet that can be used in searches. Since the `request_id` is at a different level, it is not possible to correlate using the `request_id`. After this change, the `QueryLog` will look like ```json { "detail": { "http_info" {...} "operation" { "query_execution_time": 0.001201056, "request_id": "e9bd9dd2-f5b3-4e26-9d88-9a39cff5acbb" ... }, "request_id": "e9bd9dd2-f5b3-4e26-9d88-9a39cff5acbb" }, "level": "info", "timestamp": "2020-11-23T16:48:07.173+0000", "type": "http-log" } ``` The `request_id` is still present in the `operation` key for backwards compatibility.

GITHUB_PR_NUMBER: 6244 GITHUB_PR_URL: #6244 Co-authored-by: José Lorenzo Rodríguez <37621+lorenzo@users.noreply.github.com> GitOrigin-RevId: fef22d9

hasura-bot · 2021-01-19T17:26:56Z

Beep boop! 🤖

Awesome work @lorenzo!

Your changes were merged successfully. All of us at Hasura ❤️ what you did.

Thanks again 🤗

0x777 requested a review from ecthiender November 26, 2020 14:08

ecthiender added the c/server Related to server label Nov 27, 2020

mehtavishwa30 changed the title ~~Consistently log the request_id at the same level~~ Server: Consistently log the request_id at the same level Nov 30, 2020

ecthiender changed the title ~~Server: Consistently log the request_id at the same level~~ server: consistently log request_id at the same level Dec 5, 2020

ecthiender approved these changes Dec 5, 2020

View reviewed changes

ecthiender added the no-changelog-required label Dec 6, 2020

ecthiender requested a review from a team December 6, 2020 15:13

tirumaraiselvan approved these changes Dec 15, 2020

View reviewed changes

tirumaraiselvan added this to the v1.3.4 milestone Dec 21, 2020

tirumaraiselvan requested changes Dec 21, 2020

View reviewed changes

tirumaraiselvan removed this from the v1.3.4 milestone Dec 22, 2020

lorenzo requested a review from a team as a code owner January 17, 2021 13:38

lorenzo added 2 commits January 17, 2021 14:39

fixed docs and added changelog

fbe0b8e

tirumaraiselvan approved these changes Jan 18, 2021

View reviewed changes

hasura-bot added the merged label Jan 19, 2021

hasura-bot closed this Jan 19, 2021

hasura-bot added a commit that referenced this pull request Jan 19, 2021

server: consistently log request_id at the same level

38fc4cb

GITHUB_PR_NUMBER: 6244 GITHUB_PR_URL: #6244 Co-authored-by: José Lorenzo Rodríguez <37621+lorenzo@users.noreply.github.com> GitOrigin-RevId: fef22d9

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

server: consistently log request_id at the same level #6244

server: consistently log request_id at the same level #6244

lorenzo commented Nov 23, 2020 •

edited

hasura-bot commented Nov 23, 2020

netlify bot commented Nov 23, 2020 •

edited

ecthiender commented Nov 27, 2020

lorenzo commented Nov 27, 2020

lorenzo commented Dec 4, 2020

ecthiender commented Dec 5, 2020

tirumaraiselvan left a comment

tirumaraiselvan commented Dec 21, 2020

tirumaraiselvan left a comment

hgiasac commented Dec 21, 2020 •

edited

tirumaraiselvan commented Dec 21, 2020

lorenzo commented Jan 9, 2021

tirumaraiselvan commented Jan 11, 2021

lorenzo commented Jan 17, 2021

hasura-bot commented Jan 19, 2021

server: consistently log request_id at the same level #6244

server: consistently log request_id at the same level #6244

Conversation

lorenzo commented Nov 23, 2020 • edited

Description

Changelog

Affected components

Related Issues

Solution and Design

Steps to test and verify

Limitations, known bugs & workarounds

Server checklist

Catalog upgrade

Metadata

GraphQL

Breaking changes

hasura-bot commented Nov 23, 2020

netlify bot commented Nov 23, 2020 • edited

ecthiender commented Nov 27, 2020

lorenzo commented Nov 27, 2020

lorenzo commented Dec 4, 2020

ecthiender commented Dec 5, 2020

tirumaraiselvan left a comment

Choose a reason for hiding this comment

tirumaraiselvan commented Dec 21, 2020

tirumaraiselvan left a comment

Choose a reason for hiding this comment

hgiasac commented Dec 21, 2020 • edited

tirumaraiselvan commented Dec 21, 2020

lorenzo commented Jan 9, 2021

tirumaraiselvan commented Jan 11, 2021

lorenzo commented Jan 17, 2021

hasura-bot commented Jan 19, 2021

lorenzo commented Nov 23, 2020 •

edited

netlify bot commented Nov 23, 2020 •

edited

hgiasac commented Dec 21, 2020 •

edited