Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

debug could make the CLI more chatty about API requests #1014

Open
1 of 4 tasks
iximeow opened this issue Feb 12, 2025 · 1 comment · May be fixed by #1053
Open
1 of 4 tasks

debug could make the CLI more chatty about API requests #1014

iximeow opened this issue Feb 12, 2025 · 1 comment · May be fixed by #1053
Assignees
@wfchandler
Labels
feature Issue for a new feature that does not break current functionality

Comments

@iximeow
Copy link
Member

iximeow commented Feb 12, 2025

Target component

  • CLI
  • SDK
  • Something else
  • Not sure

Overview

in getting to oxidecomputer/omicron#7532, i'd started with a CLI invocation that clearly did something wrong.

./target/debug/oxide --profile dogfood \
    experimental timeseries query \
    --project ixi \
    --query "\
        get virtual_machine:vcpu_usage | \
          filter timestamp >= @2025-02-11T00:59:44.938 && timestamp < @2025-02-11T01:20:24.938 && \
            instance_id == \"cdffcf35-6ae3-488d-a03d-64cf45f88fb2\" && state == \"emulation\" | \
          align mean_within(20s) | group_by [instance_id], sum"

returned

Error Response: status: 400 Bad Request; headers: {"content-type":
"application/json", "x-request-id": "f96ba139-2229-4a39-8435-7f6b39d640fb",
"content-length": "551", "date": "Wed, 12 Feb 2025 20:15:45 GMT"}; value: Error
{ error_code: Some("InvalidRequest"), message: "The filter expression
\"(silo_id == \"7bd7623a-68ed-4636-8ecb-b59e3b068787\") && (project_id ==
\"9c4152f9-4317-4269-9018-66142964d21c\")\" is not valid, the following errors
were encountered\n  > The filter expression refers to identifiers that are not
valid for its input table \"virtual_machine:vcpu_usage\". Invalid identifiers:
[\"silo_id\", \"project_id\"], valid identifiers: [\"datum\", \"instance_id\",
\"start_time\", \"timestamp\"]", request_id:
"f96ba139-2229-4a39-8435-7f6b39d640fb" }

in there is something about a filter expression using silo_id and project_id. that wasn't in my command. was it added by the CLI? SDK? i really wanted to know exactly what the HTTP request was that the CLI made on my behalf. --debug did not really help:

./target/debug/oxide --profile dogfood experimental timeseries query --project ixi --query "\
        get virtual_machine:vcpu_usage | \
          filter timestamp >= @2025-02-11T00:59:44.938 && timestamp < @2025-02-11T01:20:24.938 && \
            instance_id == \"cdffcf35-6ae3-488d-a03d-64cf45f88fb2\" && state == \"emulation\" | \
          align mean_within(20s) | group_by [instance_id, project_id, silo_id], sum"
[2025-02-12T20:43:07Z DEBUG reqwest::connect] starting new connection: https://oxide.sys.rack2.eng.oxide.computer/
{
  "tables": [
... snip ...

i can't really tell why the one random reqwest::connect log is there and nothing else. maybe because we're only configuring env_logger and the dependencies involved use tracing?

so for myself, i'd added eprintln!("request: {:?}", request); in the function handling the project-scoped timeseries query and that got me about what i'd wanted:

  • request method
  • request path
  • query parameters
  • headers - unfortunately not all! i stole a cookie from my browser login to auth in my curl reproduction.

(the hostname is good! but i already knew i was talking to dogfood.)

this did not get me the query body for /v1/timeseries/query, unfortunately. i'd guessed at the right POST body and happened to get it first try.

Implementation details

it would be really nice if --debug caused the CLI to log at least a request head before getting to client.client.execute(request) in the various handlers. i think that gets 90% of the way there without sweating request bodies.

Anything else you would like to add?

obviously not all CLI operations are a single HTTP request, and even ones that are, you might not want to log a 100MB POST body. i don't think we have a clever way to know which endpoints we'd expect have reasonably-loggable POST bodies either. ideally for some operations like timeseries queries with these relatively small json POST bodies we could know to log the body for easy reproduction. disk upload in particular is where i would be concerned that is a footgun if used carelessly.
@iximeow iximeow added the feature Issue for a new feature that does not break current functionality label Feb 12, 2025
@iximeow
Copy link
Member Author

iximeow commented Feb 12, 2025

i suppose it's worth saying: i'd just go Do This but particularly with --debug doing so little i'm not totally sure i'm not just holding it wrong.

@wfchandler wfchandler self-assigned this Feb 24, 2025
wfchandler added a commit that referenced this issue Feb 26, 2025
@wfchandler
Add detailed request logging
c6a1fd2 
Currently we don't offer a way to expose the details of the API requests
the CLI or other SDK consumers to users, making troubleshooting
difficult.

With the new `middleware` feature available in Progenitor, we can now
inject our own logger using the `reqwest-tracing` crate. This gives us
output like:

  ./target/debug/oxide --debug disk list --project will | jq .
  {
    "timestamp": "2025-02-26T17:29:23.354297Z",
    "level": "DEBUG",
    "fields": {
      "message": "close",
      "time.busy": "16.7ms",
      "time.idle": "365ms"
    },
    "target": "oxide::tracing",
    "span": {
      "host": "oxide.sys.r3.oxide-preview.com",
      "http.request.method": "GET",
      "http.response.content_length": 998,
      "http.response.status_code": 200,
      "oxide.request_id": "c5e7d65e-bcb2-4ade-a817-6f13b681b19b",
      "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
      "name": "Oxide API Request"
    },
    "spans": []
  }

We will also log the first KiB of the request body, if present. This
should be enough to capture the details human-readable requests, e.g. an
OxQL query, but avoid too much noise from something like a disk import.

The `--debug` flag will enable debug logs for both the CLI and any
dependencies, such as `hyper`. To view only CLI logs, set
`RUST_LOG=oxide=debug`.

Closes #1014.
@wfchandler wfchandler mentioned this issue Feb 26, 2025
Closed
wfchandler added a commit that referenced this issue Mar 4, 2025
@wfchandler
Add detailed request logging
5a151b4 
Currently we don't offer a way to expose the details of the API requests
the CLI or other SDK consumers to users, making troubleshooting
difficult.

With the new `middleware` feature available in Progenitor, we can now
inject our own logger using the `reqwest-tracing` crate. This gives us
output like:

  ./target/debug/oxide --debug disk list --project will | jq .
  {
    "timestamp": "2025-02-26T17:29:23.354297Z",
    "level": "DEBUG",
    "fields": {
      "message": "close",
      "time.busy": "16.7ms",
      "time.idle": "365ms"
    },
    "target": "oxide::tracing",
    "span": {
      "host": "oxide.sys.r3.oxide-preview.com",
      "http.request.method": "GET",
      "http.response.content_length": 998,
      "http.response.status_code": 200,
      "oxide.request_id": "c5e7d65e-bcb2-4ade-a817-6f13b681b19b",
      "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
      "name": "Oxide API Request"
    },
    "spans": []
  }

We will also log the first KiB of the request body, if present. This
should be enough to capture the details human-readable requests, e.g. an
OxQL query, but avoid too much noise from something like a disk import.

The `--debug` flag will enable debug logs for both the CLI and any
dependencies, such as `hyper`. To view only CLI logs, set
`RUST_LOG=oxide=debug`.

Closes #1014.
wfchandler added a commit that referenced this issue Mar 12, 2025
@wfchandler
Add debug logging for all Oxide API requests
b5860f3 
Currently only the `auth` CLI subcommand will log any request details
when debug logging is enabled. Adding debug logging for all requests
will enable users to troubleshoot issues on any API endpoint.

To do this, we add add pre and post-request hooks via Progenitor.
However, this does not lend itself to tracking the duration of the
request, or creating a single log event with the details from the the
`Request` and `Response`.

We add a `LogCtx` inner type to the client to act as a store while
requests are in flight, but need something to associate the start and
end. We could inject a header into the request, but on failure this will
not be available to us.

Instead, we use the tokio `task::Id` as an identifier, which is unique
within a given runtime. This raises the possibility of a client shared
between runtimes associating the wrong start with a finished request.
We do not have a way to detect which runtime a task is associated with,
`runtime::Id` is an unstable feature, but we will log a warning if we
find a response without a corresponding request, along with the response
details. Should a request be run outside of a task, we fall back to
logging separate events for start and end.

We also create a `Span` that includes the log event. This is ignored by
the CLI, but may be useful for other consumers of the SDK that want to
integrate it with their monitoring infrastructure.

An example event:

  {
    "timestamp": "2025-03-12T15:25:58.487790Z",
    "level": "DEBUG",
    "message": "request succeeded",
    "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
    "path": "/v1/disks",
    "remote_addr": "45.154.216.35:443",
    "http.request.method": "GET",
    "http.response.content_length": 998,
    "http.response.status_code": 200,
    "start_time": "2025-03-12T15:25:58.048984Z",
    "duration_ms": 438,
    "oxide.request_id": "5d738e7a-ad78-4938-b682-c43f7b2a84be",
    "target": "oxide::tracing"
  }

Closes #1014
@wfchandler wfchandler linked a pull request Mar 12, 2025 that will close this issue
Open
wfchandler added a commit that referenced this issue Mar 12, 2025
@wfchandler
Add debug logging for all Oxide API requests
0b5b0b3 
Currently only the `auth` CLI subcommand will log any request details
when debug logging is enabled. Adding debug logging for all requests
will enable users to troubleshoot issues on any API endpoint.

To do this, we add add pre and post-request hooks via Progenitor.
However, this does not lend itself to tracking the duration of the
request, or creating a single log event with the details from the the
`Request` and `Response`.

We add a `LogCtx` inner type to the client to act as a store while
requests are in flight, but need something to associate the start and
end. We could inject a header into the request, but on failure this will
not be available to us.

Instead, we use the tokio `task::Id` as an identifier, which is unique
within a given runtime. This raises the possibility of a client shared
between runtimes associating the wrong start with a finished request.
We do not have a way to detect which runtime a task is associated with,
`runtime::Id` is an unstable feature, but we will log a warning if we
find a response without a corresponding request, along with the response
details. Should a request be run outside of a task, we fall back to
logging separate events for start and end.

We also create a `Span` that includes the log event. This is ignored by
the CLI, but may be useful for other consumers of the SDK that want to
integrate it with their monitoring infrastructure.

An example event:

  {
    "timestamp": "2025-03-12T15:25:58.487790Z",
    "level": "DEBUG",
    "message": "request succeeded",
    "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
    "path": "/v1/disks",
    "remote_addr": "45.154.216.35:443",
    "http.request.method": "GET",
    "http.response.content_length": 998,
    "http.response.status_code": 200,
    "start_time": "2025-03-12T15:25:58.048984Z",
    "duration_ms": 438,
    "oxide.request_id": "5d738e7a-ad78-4938-b682-c43f7b2a84be",
    "target": "oxide::tracing"
  }

Closes #1014
wfchandler added a commit that referenced this issue Mar 12, 2025
@wfchandler
Add debug logging for all Oxide API requests
3060f3c 
Currently only the `auth` CLI subcommand will log any request details
when debug logging is enabled. Adding debug logging for all requests
will enable users to troubleshoot issues on any API endpoint.

To do this, we add add pre and post-request hooks via Progenitor.
However, this does not lend itself to tracking the duration of the
request, or creating a single log event with the details from the the
`Request` and `Response`.

We add a `LogCtx` inner type to the client to act as a store while
requests are in flight, but need something to associate the start and
end. We could inject a header into the request, but on failure this will
not be available to us.

Instead, we use the tokio `task::Id` as an identifier, which is unique
within a given runtime. This raises the possibility of a client shared
between runtimes associating the wrong start with a finished request.
We do not have a way to detect which runtime a task is associated with,
`runtime::Id` is an unstable feature, but we will log a warning if we
find a response without a corresponding request, along with the response
details. Should a request be run outside of a task, we fall back to
logging separate events for start and end.

We also create a `Span` that includes the log event. This is ignored by
the CLI, but may be useful for other consumers of the SDK that want to
integrate it with their monitoring infrastructure.

An example event:

  {
    "timestamp": "2025-03-12T15:25:58.487790Z",
    "level": "DEBUG",
    "message": "request succeeded",
    "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
    "path": "/v1/disks",
    "remote_addr": "45.154.216.35:443",
    "http.request.method": "GET",
    "http.response.content_length": 998,
    "http.response.status_code": 200,
    "start_time": "2025-03-12T15:25:58.048984Z",
    "duration_ms": 438,
    "oxide.request_id": "5d738e7a-ad78-4938-b682-c43f7b2a84be",
    "target": "oxide::tracing"
  }

Closes #1014
wfchandler added a commit that referenced this issue Mar 13, 2025
@wfchandler
Add debug logging for all Oxide API requests
c612eea 
Currently only the `auth` CLI subcommand will log any request details
when debug logging is enabled. Adding debug logging for all requests
will enable users to troubleshoot issues on any API endpoint.

To do this, we add add pre and post-request hooks via Progenitor.
However, this does not lend itself to tracking the duration of the
request, or creating a single log event with the details from the the
`Request` and `Response`.

We add a `LogCtx` inner type to the client to act as a store while
requests are in flight, but need something to associate the start and
end. We could inject a header into the request, but on failure this will
not be available to us.

Instead, we use the tokio `task::Id` as an identifier, which is unique
within a given runtime. This raises the possibility of a client shared
between runtimes associating the wrong start with a finished request.
We do not have a way to detect which runtime a task is associated with,
`runtime::Id` is an unstable feature, but we will log a warning if we
find a response without a corresponding request, along with the response
details. When a request is run outside of a task, we fall back to
logging separate events for start and end.

We also create a `Span` that includes the log event. This is ignored by
the CLI, but may be useful for other consumers of the SDK that want to
integrate it with their monitoring infrastructure.

An example event:

  {
    "timestamp": "2025-03-12T15:25:58.487790Z",
    "level": "DEBUG",
    "message": "request succeeded",
    "url": "https://oxide.sys.r3.oxide-preview.com/v1/disks?project=will",
    "path": "/v1/disks",
    "remote_addr": "45.154.216.35:443",
    "http.request.method": "GET",
    "http.response.content_length": 998,
    "http.response.status_code": 200,
    "start_time": "2025-03-12T15:25:58.048984Z",
    "duration_ms": 438,
    "oxide.request_id": "5d738e7a-ad78-4938-b682-c43f7b2a84be",
    "target": "oxide::tracing"
  }

Closes #1014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@wfchandler wfchandler

Labels
feature Issue for a new feature that does not break current functionality
Projects
None yet
Milestone
No milestone
2 participants
@iximeow @wfchandler