Panic on mutation with `query_deduplication` enabled

[radekmie]

Describe the bug We've switched from Apollo Gateway to Apollo Router (v0.9.5) last Friday, and everything went smoothly. We've tested it on a few most used queries (no mutations) - it looked fine.

Today we've got a few alerts, that one of the mutations is not working properly, and it returns an error. The mutation is fairly simple:

mutation Login($input: LoginInput!) {
  login(input: $input) {
    token
  }
}

And the error was quite cryptic:

{
  "data": null,
  "errors": [
    {
      "message": "empty response",
      "locations": [],
      "path": null
    }
  ]
}

We've quickly reverted the deployment, and checked the logs. The weren't many of them:

1. First 4 messages are the standard "starting" messages.
2. Then we saw exactly 25 messages like this (of course, the timestamp is different):

   {"timestamp":"2022-07-04T09:18:29.464674Z","level":"ERROR","fields":{"message":"response failed","classification":"Status code: 500 Internal Server Error","latency":"0 ms"},"target":"tower_http::trace::on_failure","span":{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"}]} 

3. Next was a single

   note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace 

4. And since then, every call to this mutation still resulted in an error, but in addition to the message from 2., it prints this:

   thread 'tokio-runtime-worker' panicked at 'buffer full; poll_ready must be called first', /home/circleci/.cargo/registry/src/github.com-1ecc6299db9ec823/tower-0.4.12/src/buffer/service.rs:146:14  

As I've checked, making a request directly at the subgraph works, and so does the gateway - it's only the router.

To Reproduce I can reproduce it in multiple environments of ours, but haven't prepared a reproduction yet. Also, restarting the router doesn't help either.

Expected behavior No errors at all. (And a better error messasge...)

Additional context The router configuration:

server:
  listen: 0.0.0.0:4000
  cors:
    allow_any_origin: true
headers:
  all:
    - propagate:
        matching: .*
traffic_shaping:
  variables_deduplication: true
  all:
    query_deduplication: true
    compression: gzip

[krisztian-sala]

I noticed the same behavior with mutations with v0.9.4. On v0.9.3 they are working. I couldn't test with v0.9.5 because it's not starting for some reason.

[bnjjj]

Did you try to run it with the variables_deduplication option disabled ?

[radekmie]

@bnjjj We will, thanks!

[radekmie]

@bnjjj Nope, it doesn't change anything - it's still failing.

[radekmie]

@bnjjj We've tried a few different configurations, and it looks like only query_deduplication is causing problems - it works with variables_deduplication enabled and disabled.

[Geal]

@radekmie do you see anything suspicious when running the router with --log debug or --log trace ?

[radekmie]

@Geal It's hard for me to know which log is first when a request is made, as there's so many of them, so here are two most often recurring patterns:

Probably the mutation

```json {"timestamp":"2022-07-05T08:12:08.714717Z","level":"ERROR","fields":{"message":"response failed","classification":"Status code: 500 Internal Server Error","latency":"3 ms"},"target":"tower_http::trace::on_failure","span":{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:08.714795Z","level":"TRACE","fields":{"message":"Server::encode status=500, body=Some(Unknown), req_method=Some(POST)"},"target":"hyper::proto::h1::role","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]} {"timestamp":"2022-07-05T08:12:08.714871Z","level":"TRACE","fields":{"message":"encoding chunked 64B"},"target":"hyper::proto::h1::encode"} {"timestamp":"2022-07-05T08:12:08.714892Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":280,"buf.len":70},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:08.714904Z","level":"TRACE","fields":{"message":"encoding chunked 29B"},"target":"hyper::proto::h1::encode"} {"timestamp":"2022-07-05T08:12:08.714913Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":350,"buf.len":35},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:08.714921Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":385,"buf.len":5},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:08.714977Z","level":"DEBUG","fields":{"message":"flushed 390 bytes"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:08.714995Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.224920Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.224963Z","level":"TRACE","fields":{"message":"received 915 bytes"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:09.225002Z","level":"TRACE","fields":{"message":"Request.parse","bytes":915},"target":"hyper::proto::h1::role","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]} {"timestamp":"2022-07-05T08:12:09.225037Z","level":"TRACE","fields":{"message":"Request.parse Complete(915)"},"target":"hyper::proto::h1::role","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]} {"timestamp":"2022-07-05T08:12:09.225111Z","level":"DEBUG","fields":{"message":"parsed 22 headers"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:09.225129Z","level":"DEBUG","fields":{"message":"incoming body is content-length (291 bytes)"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.225170Z","level":"TRACE","fields":{"message":"decode; state=Length(291)"},"target":"hyper::proto::h1::decode"} {"timestamp":"2022-07-05T08:12:09.225237Z","level":"DEBUG","fields":{"message":"started processing request"},"target":"tower_http::trace::on_request","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.225306Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Body(Length(291)), writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.226744Z","level":"TRACE","fields":{"message":"decode; state=Length(291)"},"target":"hyper::proto::h1::decode"} {"timestamp":"2022-07-05T08:12:09.226770Z","level":"TRACE","fields":{"message":"received 291 bytes"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:12:09.226779Z","level":"DEBUG","fields":{"message":"incoming body completed"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.226838Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.226880Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.226901Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.226911Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.226920Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.226946Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.226967Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.226990Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227014Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227024Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227031Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227039Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227061Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227088Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227124Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227148Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227157Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227179Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227189Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227214Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} thread 'tokio-runtime-worker' panicked at 'buffer full; poll_ready must be called first', /home/circleci/.cargo/registry/src/github.com-1ecc6299db9ec823/tower-0.4.12/src/buffer/service.rs:146:14 {"timestamp":"2022-07-05T08:12:09.227273Z","level":"TRACE","fields":{"message":"request is preflighted"},"target":"apollo_router::plugins::csrf","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227310Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:12:09.227335Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227333Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.227434Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227485Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.227503Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227522Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227531Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227565Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227609Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227644Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227689Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227727Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.227745Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227770Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227779Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227807Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227849Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"}]} {"timestamp":"2022-07-05T08:12:09.227879Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.227912Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:12:09.227937Z","level":"TRACE","fields":{"message":"query plan\nFetch(FetchNode { service_name: \"core\", requires: [], variable_usages: [\"input\"], operation: \"mutation Login__core__0($input:LoginInput!){login(input:$input){token}}\", operation_name: Some(\"Login__core__0\"), operation_kind: Mutation })"},"target":"apollo_router::query_planner::log","span":{"otel.kind":"internal","name":"execution"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"}]} {"timestamp":"2022-07-05T08:12:09.227982Z","level":"TRACE","fields":{"message":"executing plan:\nFetch(\n FetchNode {\n service_name: \"core\",\n requires: [],\n variable_usages: [\n \"input\",\n ],\n operation: \"mutation Login__core__0($input:LoginInput!){login(input:$input){token}}\",\n operation_name: Some(\n \"Login__core__0\",\n ),\n operation_kind: Mutation,\n },\n)"},"target":"apollo_router::query_planner","span":{"otel.kind":"internal","name":"execution"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"}]} {"timestamp":"2022-07-05T08:12:09.228072Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"name":"subfetch_stream"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"},{"name":"subfetch_stream"}]} {"timestamp":"2022-07-05T08:12:09.228111Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.228126Z","level":"TRACE","fields":{"message":"processing new request"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.228136Z","level":"TRACE","fields":{"resumed":false,"message":"worker received request; waiting for service readiness"},"target":"tower::buffer::worker","span":{"name":"subfetch_stream"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"},{"name":"subfetch_stream"}]} {"timestamp":"2022-07-05T08:12:09.228166Z","level":"DEBUG","fields":{"service.ready":true,"message":"processing request"},"target":"tower::buffer::worker","span":{"name":"subfetch_stream"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"},{"name":"subfetch_stream"}]} {"timestamp":"2022-07-05T08:12:09.228220Z","level":"TRACE","fields":{"message":"returning response future"},"target":"tower::buffer::worker","span":{"name":"subfetch_stream"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"},{"name":"subfetch_stream"}]} {"timestamp":"2022-07-05T08:12:09.228251Z","level":"TRACE","fields":{"message":"worker polling for next message"},"target":"tower::buffer::worker"} {"timestamp":"2022-07-05T08:12:09.228269Z","level":"TRACE","fields":{"message":"sending request to buffer worker"},"target":"tower::buffer::service","span":{"name":"core","otel.kind":"internal","name":"subgraph"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"},{"name":"subfetch_stream"},{"name":"core","otel.kind":"internal","name":"subgraph"}]} {"timestamp":"2022-07-05T08:12:09.228463Z","level":"DEBUG","fields":{"message":"invalid type for data in response."},"target":"apollo_router::spec::query","span":{"name":"format_response"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"apollo-studio","client_version":"1.0.0","operation_name":"Login","otel.kind":"internal","query":"mutation Login($input: LoginInput!) {\n login(input: $input) {\n token\n }\n}\n","name":"router"},{"name":"format_response"},{"name":"format_response"}]} {"timestamp":"2022-07-05T08:12:09.228582Z","level":"ERROR","fields":{"message":"response failed","classification":"Status code: 500 Internal Server Error","latency":"3 ms"},"target":"tower_http::trace::on_failure","span":{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"ERROR","uri":"/","version":"HTTP/1.1","name":"request"}]} ```

Something

```json {"timestamp":"2022-07-05T08:16:40.936742Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.936767Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.936786Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.936796Z","level":"TRACE","fields":{"message":"received 132 bytes"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:16:40.936827Z","level":"TRACE","fields":{"message":"Request.parse","bytes":132},"target":"hyper::proto::h1::role","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]} {"timestamp":"2022-07-05T08:16:40.936857Z","level":"TRACE","fields":{"message":"Request.parse Complete(132)"},"target":"hyper::proto::h1::role","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]} {"timestamp":"2022-07-05T08:16:40.936897Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:16:40.936916Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.936923Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.936978Z","level":"DEBUG","fields":{"message":"started processing request"},"target":"tower_http::trace::on_request","span":{"method":"GET","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},"spans":[{"method":"GET","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"}]} {"timestamp":"2022-07-05T08:16:40.937061Z","level":"TRACE","fields":{"message":"Server::encode status=400, body=Some(Unknown), req_method=Some(GET)"},"target":"hyper::proto::h1::role","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]} {"timestamp":"2022-07-05T08:16:40.937105Z","level":"TRACE","fields":{"message":"sized write, len = 23"},"target":"hyper::proto::h1::encode"} {"timestamp":"2022-07-05T08:16:40.937124Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":247,"buf.len":23},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:16:40.937132Z","level":"TRACE","fields":{"message":"no more write body allowed, user body is_end_stream = false"},"target":"hyper::proto::h1::dispatch"} {"timestamp":"2022-07-05T08:16:40.937160Z","level":"DEBUG","fields":{"message":"flushed 270 bytes"},"target":"hyper::proto::h1::io"} {"timestamp":"2022-07-05T08:16:40.937194Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.937203Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:40.937219Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn"} {"timestamp":"2022-07-05T08:16:41.238438Z","level":"TRACE","fields":{"message":"checkout waiting for idle connection: (\"https\", uplink.api.apollographql.com)"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.238516Z","level":"TRACE","fields":{"message":"Http::connect; scheme=Some(\"https\"), host=Some(\"uplink.api.apollographql.com\"), port=None"},"target":"hyper::client::connect::http"} {"timestamp":"2022-07-05T08:16:41.238550Z","level":"DEBUG","fields":{"message":"resolving host=\"uplink.api.apollographql.com\""},"target":"hyper::client::connect::dns"} {"timestamp":"2022-07-05T08:16:41.239876Z","level":"DEBUG","fields":{"message":"connecting to 34.117.186.194:443"},"target":"hyper::client::connect::http"} {"timestamp":"2022-07-05T08:16:41.241619Z","level":"DEBUG","fields":{"message":"connected to 34.117.186.194:443"},"target":"hyper::client::connect::http"} {"timestamp":"2022-07-05T08:16:41.245101Z","level":"TRACE","fields":{"message":"ALPN negotiated h2, updating pool"},"target":"hyper::client::client"} {"timestamp":"2022-07-05T08:16:41.245122Z","level":"TRACE","fields":{"message":"client handshake Http2"},"target":"hyper::client::conn"} {"timestamp":"2022-07-05T08:16:41.245142Z","level":"DEBUG","fields":{"message":"binding client connection"},"target":"h2::client"} {"timestamp":"2022-07-05T08:16:41.245164Z","level":"DEBUG","fields":{"message":"client connection bound"},"target":"h2::client"} {"timestamp":"2022-07-05T08:16:41.245209Z","level":"DEBUG","fields":{"message":"send","frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }"},"target":"h2::codec::framed_write","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245242Z","level":"TRACE","fields":{"message":"encoding SETTINGS; len=18"},"target":"h2::frame::settings","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245263Z","level":"TRACE","fields":{"message":"encoding setting; val=EnablePush(0)"},"target":"h2::frame::settings","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245283Z","level":"TRACE","fields":{"message":"encoding setting; val=InitialWindowSize(2097152)"},"target":"h2::frame::settings","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245302Z","level":"TRACE","fields":{"message":"encoding setting; val=MaxFrameSize(16384)"},"target":"h2::frame::settings","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245326Z","level":"TRACE","fields":{"message":"encoded settings","rem":27},"target":"h2::codec::framed_write","span":{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"},"spans":[{"frame":"Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.245371Z","level":"TRACE","fields":{"message":"inc_window; sz=65535; old=0; new=65535"},"target":"h2::proto::streams::flow_control"} {"timestamp":"2022-07-05T08:16:41.245383Z","level":"TRACE","fields":{"message":"inc_window; sz=65535; old=0; new=65535"},"target":"h2::proto::streams::flow_control"} {"timestamp":"2022-07-05T08:16:41.245391Z","level":"TRACE","fields":{"message":"Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }"},"target":"h2::proto::streams::prioritize"} {"timestamp":"2022-07-05T08:16:41.245417Z","level":"TRACE","fields":{"message":"set_target_connection_window; target=5242880; available=65535, reserved=0"},"target":"h2::proto::streams::recv"} {"timestamp":"2022-07-05T08:16:41.245438Z","level":"TRACE","fields":{"message":"handshake complete, spawning background dispatcher task"},"target":"hyper::client::client"} {"timestamp":"2022-07-05T08:16:41.245471Z","level":"TRACE","fields":{"message":"put; add idle connection for (\"https\", uplink.api.apollographql.com)"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.245490Z","level":"DEBUG","fields":{"message":"pooling idle connection for (\"https\", uplink.api.apollographql.com)"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.245509Z","level":"TRACE","fields":{"message":"checkout dropped for (\"https\", uplink.api.apollographql.com)"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.245537Z","level":"TRACE","fields":{"message":"inc_window; sz=2097152; old=0; new=2097152"},"target":"h2::proto::streams::flow_control"} {"timestamp":"2022-07-05T08:16:41.245547Z","level":"TRACE","fields":{"message":"inc_window; sz=65535; old=0; new=65535"},"target":"h2::proto::streams::flow_control"} {"timestamp":"2022-07-05T08:16:41.245560Z","level":"TRACE","fields":{"message":"send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=65535"},"target":"h2::proto::streams::send"} {"timestamp":"2022-07-05T08:16:41.245591Z","level":"TRACE","fields":{"message":"schedule_send","stream.id":"StreamId(1)"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.245612Z","level":"TRACE","fields":{"message":"Queue::push"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.245632Z","level":"TRACE","fields":{"message":" -> first entry"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.245696Z","level":"TRACE","fields":{"requested":1,"additional":1,"buffered":0,"window":65535,"conn":"65535"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"curr":0,"effective":1,"requested":1,"stream.id":"StreamId(1)","name":"reserve_capacity"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245723Z","level":"TRACE","fields":{"message":"assigning","capacity":1},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"curr":0,"effective":1,"requested":1,"stream.id":"StreamId(1)","name":"reserve_capacity"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245747Z","level":"TRACE","fields":{"message":" assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576"},"target":"h2::proto::streams::stream","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"curr":0,"effective":1,"requested":1,"stream.id":"StreamId(1)","name":"reserve_capacity"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245770Z","level":"TRACE","fields":{"message":" notifying task"},"target":"h2::proto::streams::stream","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"curr":0,"effective":1,"requested":1,"stream.id":"StreamId(1)","name":"reserve_capacity"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245790Z","level":"TRACE","fields":{"available":"1","requested":1,"buffered":0,"has_unavailable":"true"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"curr":0,"effective":1,"requested":1,"stream.id":"StreamId(1)","name":"reserve_capacity"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245837Z","level":"TRACE","fields":{"message":"send body chunk: 559 bytes, eos=true"},"target":"hyper::proto::h2"} {"timestamp":"2022-07-05T08:16:41.245862Z","level":"TRACE","fields":{"buffered":559},"target":"h2::proto::streams::prioritize","span":{"requested":1,"sz":559,"name":"send_data"},"spans":[{"requested":1,"sz":559,"name":"send_data"}]} {"timestamp":"2022-07-05T08:16:41.245894Z","level":"TRACE","fields":{"requested":559,"additional":558,"buffered":559,"window":65535,"conn":"65534"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245915Z","level":"TRACE","fields":{"message":"assigning","capacity":558},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245936Z","level":"TRACE","fields":{"message":" assigned capacity to stream; available=559; buffered=559; id=StreamId(1); max_buffer_size=1048576"},"target":"h2::proto::streams::stream","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245957Z","level":"TRACE","fields":{"available":"559","requested":559,"buffered":559,"has_unavailable":"true"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245978Z","level":"TRACE","fields":{"message":"Queue::push"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.245998Z","level":"TRACE","fields":{"message":" -> already queued"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"try_assign_capacity"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"try_assign_capacity"}]} {"timestamp":"2022-07-05T08:16:41.246032Z","level":"TRACE","fields":{"message":"send_close: Open => HalfClosedLocal(AwaitingHeaders)"},"target":"h2::proto::streams::state","span":{"requested":1,"sz":559,"name":"send_data"},"spans":[{"requested":1,"sz":559,"name":"send_data"}]} {"timestamp":"2022-07-05T08:16:41.246078Z","level":"TRACE","fields":{"available":"559","buffered":559},"target":"h2::proto::streams::prioritize","span":{"requested":1,"sz":559,"name":"send_data"},"spans":[{"requested":1,"sz":559,"name":"send_data"}]} {"timestamp":"2022-07-05T08:16:41.246108Z","level":"TRACE","fields":{"message":"schedule_send","stream.id":"StreamId(1)"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.246128Z","level":"TRACE","fields":{"message":"Queue::push"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.246151Z","level":"TRACE","fields":{"message":" -> already queued"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"},"spans":[{"requested":1,"sz":559,"name":"send_data"},{"stream.id":"StreamId(1)","name":"Prioritize::queue_frame"}]} {"timestamp":"2022-07-05T08:16:41.246193Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=559; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts"} {"timestamp":"2022-07-05T08:16:41.246213Z","level":"TRACE","fields":{"message":"drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(65535), available: Window(559) }, requested_send_capacity: 559, buffered_send_data: 559, send_task: Some(Waker { data: 0x7f42841b1a50, vtable: 0x5603239173c0 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 1 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097152), available: Window(2097152) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }"},"target":"h2::proto::streams::streams"} {"timestamp":"2022-07-05T08:16:41.246241Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=559; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts"} {"timestamp":"2022-07-05T08:16:41.246275Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246318Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.246364Z","level":"DEBUG","fields":{"message":"send","frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }"},"target":"h2::codec::framed_write","span":{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.246396Z","level":"TRACE","fields":{"message":"encoding WINDOW_UPDATE; id=StreamId(0)"},"target":"h2::frame::window_update","span":{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.246418Z","level":"TRACE","fields":{"message":"encoded window_update","rem":40},"target":"h2::codec::framed_write","span":{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.246474Z","level":"TRACE","fields":{"message":"inc_window; sz=5177345; old=65535; new=5242880"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246512Z","level":"TRACE","fields":{"message":"poll_complete"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246559Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246597Z","level":"TRACE","fields":{"is_pending_reset":false},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246620Z","level":"TRACE","fields":{"message":"pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246649Z","level":"TRACE","fields":{"message":"Queue::push"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246669Z","level":"TRACE","fields":{"message":" -> first entry"},"target":"h2::proto::streams::store","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246690Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=559; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246735Z","level":"TRACE","fields":{"message":"writing","frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246774Z","level":"DEBUG","fields":{"message":"send","frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"},"target":"h2::codec::framed_write","span":{"frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.246833Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.246871Z","level":"TRACE","fields":{"is_pending_reset":false},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246892Z","level":"TRACE","fields":{"message":"data frame","sz":559,"eos":true,"window":"559","available":"559","requested":559,"buffered":559},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246923Z","level":"TRACE","fields":{"message":"sending data frame","len":559},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.246954Z","level":"TRACE","fields":{"message":"send_data; sz=559; window=65535; available=559"},"target":"h2::proto::streams::flow_control","span":{"name":"updating stream flow"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},{"name":"updating stream flow"}]} {"timestamp":"2022-07-05T08:16:41.246990Z","level":"TRACE","fields":{"message":"send_data; sz=559; window=65535; available=65535"},"target":"h2::proto::streams::flow_control","span":{"name":"updating connection flow"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},{"name":"updating connection flow"}]} {"timestamp":"2022-07-05T08:16:41.247019Z","level":"TRACE","fields":{"message":"pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"},"target":"h2::proto::streams::prioritize","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.247043Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: HalfClosedLocal(AwaitingHeaders) }","name":"popped"}]} {"timestamp":"2022-07-05T08:16:41.247086Z","level":"TRACE","fields":{"message":"writing","frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.247126Z","level":"DEBUG","fields":{"message":"send","frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"},"target":"h2::codec::framed_write","span":{"frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.247165Z","level":"TRACE","fields":{"queued_data_frame":true},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.247193Z","level":"TRACE","fields":{"queued_data_frame":true},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.247218Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.247257Z","level":"TRACE","fields":{"message":"reclaimed","frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }","sz":0},"target":"h2::proto::streams::prioritize","span":{"name":"try_reclaim_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"try_reclaim_frame"}]} {"timestamp":"2022-07-05T08:16:41.247294Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.247330Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.247392Z","level":"TRACE","fields":{"message":"idle interval checking for expired"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.247418Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.247462Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247517Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247539Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247558Z","level":"TRACE","fields":{"read.bytes":27},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247588Z","level":"TRACE","fields":{"message":"decoding frame from 27B"},"target":"h2::codec::framed_read","span":{"offset":27,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":27,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.247608Z","level":"TRACE","fields":{"frame.kind":"Settings"},"target":"h2::codec::framed_read","span":{"offset":27,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":27,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.247643Z","level":"DEBUG","fields":{"message":"received","frame":"Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 1048576, max_header_list_size: 65536 }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247677Z","level":"TRACE","fields":{"message":"recv SETTINGS","frame":"Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 1048576, max_header_list_size: 65536 }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.247716Z","level":"DEBUG","fields":{"message":"send","frame":"Settings { flags: (0x1: ACK) }"},"target":"h2::codec::framed_write","span":{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.247740Z","level":"TRACE","fields":{"message":"encoding SETTINGS; len=0"},"target":"h2::frame::settings","span":{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.247766Z","level":"TRACE","fields":{"message":"encoded settings","rem":9},"target":"h2::codec::framed_write","span":{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Settings { flags: (0x1: ACK) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.247798Z","level":"TRACE","fields":{"message":"ACK sent; applying settings"},"target":"h2::proto::settings","span":{"name":"poll_ready"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"}]} {"timestamp":"2022-07-05T08:16:41.247853Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247872Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247894Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247911Z","level":"TRACE","fields":{"read.bytes":13},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.247939Z","level":"TRACE","fields":{"message":"decoding frame from 13B"},"target":"h2::codec::framed_read","span":{"offset":13,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":13,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.247962Z","level":"TRACE","fields":{"frame.kind":"WindowUpdate"},"target":"h2::codec::framed_read","span":{"offset":13,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":13,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.247996Z","level":"DEBUG","fields":{"message":"received","frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.248029Z","level":"TRACE","fields":{"message":"recv WINDOW_UPDATE","frame":"WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.248049Z","level":"TRACE","fields":{"message":"inc_window; sz=983041; old=64976; new=1048017"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.248099Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.248117Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.248159Z","level":"TRACE","fields":{"message":"poll_complete"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.248177Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.248209Z","level":"TRACE","fields":{"queued_data_frame":false},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.248237Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.254105Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254159Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254200Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254231Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254257Z","level":"TRACE","fields":{"read.bytes":9},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254293Z","level":"TRACE","fields":{"message":"decoding frame from 9B"},"target":"h2::codec::framed_read","span":{"offset":9,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":9,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.254322Z","level":"TRACE","fields":{"frame.kind":"Settings"},"target":"h2::codec::framed_read","span":{"offset":9,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":9,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.254356Z","level":"DEBUG","fields":{"message":"received","frame":"Settings { flags: (0x1: ACK) }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254396Z","level":"TRACE","fields":{"message":"recv SETTINGS","frame":"Settings { flags: (0x1: ACK) }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254423Z","level":"DEBUG","fields":{"message":"received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }"},"target":"h2::proto::settings","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254472Z","level":"TRACE","fields":{"message":"update_initial_window_size; new=2097152; old=2097152"},"target":"h2::proto::streams::recv","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254535Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254562Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.254618Z","level":"TRACE","fields":{"message":"poll_complete"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254644Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.254679Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.388376Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.388469Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.388522Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.388569Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.388599Z","level":"TRACE","fields":{"read.bytes":196},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.388640Z","level":"TRACE","fields":{"message":"decoding frame from 196B"},"target":"h2::codec::framed_read","span":{"offset":196,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.388678Z","level":"TRACE","fields":{"frame.kind":"Headers"},"target":"h2::codec::framed_read","span":{"offset":196,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.388701Z","level":"TRACE","fields":{"message":"loading headers; flags=(0x4: END_HEADERS)"},"target":"h2::frame::headers","span":{"offset":196,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.388736Z","level":"TRACE","fields":{"message":"decode"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388763Z","level":"TRACE","fields":{"rem":187,"kind":"Indexed"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388787Z","level":"TRACE","fields":{"rem":186,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388816Z","level":"TRACE","fields":{"rem":163,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388848Z","level":"TRACE","fields":{"rem":136,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388879Z","level":"TRACE","fields":{"rem":95,"kind":"LiteralWithoutIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388906Z","level":"TRACE","fields":{"rem":70,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388928Z","level":"TRACE","fields":{"rem":57,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388952Z","level":"TRACE","fields":{"rem":53,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.388985Z","level":"TRACE","fields":{"rem":44,"kind":"LiteralWithIndexing"},"target":"h2::hpack::decoder","span":{"name":"hpack::decode"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":196,"name":"FramedRead::decode_frame"},{"name":"hpack::decode"}]} {"timestamp":"2022-07-05T08:16:41.389047Z","level":"DEBUG","fields":{"message":"received","frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389089Z","level":"TRACE","fields":{"message":"recv HEADERS","frame":"Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389122Z","level":"TRACE","fields":{"message":"recv_headers; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }"},"target":"h2::proto::streams::streams","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389141Z","level":"TRACE","fields":{"message":"opening stream; init_window=2097152"},"target":"h2::proto::streams::recv","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389163Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389216Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389241Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389257Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389274Z","level":"TRACE","fields":{"read.bytes":61},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389306Z","level":"TRACE","fields":{"message":"decoding frame from 61B"},"target":"h2::codec::framed_read","span":{"offset":61,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":61,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.389327Z","level":"TRACE","fields":{"frame.kind":"Data"},"target":"h2::codec::framed_read","span":{"offset":61,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":61,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.389356Z","level":"DEBUG","fields":{"message":"received","frame":"Data { stream_id: StreamId(1) }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389396Z","level":"TRACE","fields":{"message":"recv DATA","frame":"Data { stream_id: StreamId(1) }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389418Z","level":"TRACE","fields":{"message":"recv_data; size=52; connection=5242880; stream=2097152"},"target":"h2::proto::streams::recv","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389438Z","level":"TRACE","fields":{"message":"send_data; sz=52; window=5242880; available=5242880"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389458Z","level":"TRACE","fields":{"message":"send_data; sz=52; window=2097152; available=2097152"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389478Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389524Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389544Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389564Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389582Z","level":"TRACE","fields":{"read.bytes":9},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389611Z","level":"TRACE","fields":{"message":"decoding frame from 9B"},"target":"h2::codec::framed_read","span":{"offset":9,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":9,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.389633Z","level":"TRACE","fields":{"frame.kind":"Data"},"target":"h2::codec::framed_read","span":{"offset":9,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":9,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.389665Z","level":"DEBUG","fields":{"message":"received","frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389702Z","level":"TRACE","fields":{"message":"recv DATA","frame":"Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389728Z","level":"TRACE","fields":{"message":"recv_data; size=0; connection=5242828; stream=2097100"},"target":"h2::proto::streams::recv","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389747Z","level":"TRACE","fields":{"message":"send_data; sz=0; window=5242828; available=5242828"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389766Z","level":"TRACE","fields":{"message":"recv_close: HalfClosedLocal => Closed"},"target":"h2::proto::streams::state","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389784Z","level":"TRACE","fields":{"message":"send_data; sz=0; window=2097100; available=2097100"},"target":"h2::proto::streams::flow_control","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389803Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389827Z","level":"TRACE","fields":{"message":"dec_num_streams; stream=StreamId(1)"},"target":"h2::proto::streams::counts","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.389870Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389891Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389920Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389937Z","level":"TRACE","fields":{"message":"frame decoded from buffer"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389956Z","level":"TRACE","fields":{"read.bytes":17},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.389986Z","level":"TRACE","fields":{"message":"decoding frame from 17B"},"target":"h2::codec::framed_read","span":{"offset":17,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":17,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.390005Z","level":"TRACE","fields":{"frame.kind":"Ping"},"target":"h2::codec::framed_read","span":{"offset":17,"name":"FramedRead::decode_frame"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"},{"offset":17,"name":"FramedRead::decode_frame"}]} {"timestamp":"2022-07-05T08:16:41.390038Z","level":"DEBUG","fields":{"message":"received","frame":"Ping { ack: false, payload: [0, 0, 0, 0, 0, 0, 0, 0] }"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.390079Z","level":"TRACE","fields":{"message":"recv PING","frame":"Ping { ack: false, payload: [0, 0, 0, 0, 0, 0, 0, 0] }"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390119Z","level":"DEBUG","fields":{"message":"send","frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }"},"target":"h2::codec::framed_write","span":{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.390141Z","level":"TRACE","fields":{"message":"encoding PING; ack=true len=8"},"target":"h2::frame::ping","span":{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.390163Z","level":"TRACE","fields":{"message":"encoded ping","rem":17},"target":"h2::codec::framed_write","span":{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"poll_ready"},{"frame":"Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.390209Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.390232Z","level":"TRACE","fields":{"message":"attempting to decode a frame"},"target":"tokio_util::codec::framed_impl","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.390278Z","level":"TRACE","fields":{"message":"poll_complete"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390297Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390333Z","level":"TRACE","fields":{"queued_data_frame":false},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.390370Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.390443Z","level":"TRACE","fields":{"message":"drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(64976), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x7f42841b1a50, vtable: 0x5603239173c0 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097100), available: Window(2097100) }, in_flight_recv_data: 52, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: Some(Indices { head: 1, tail: 2 }) }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Remaining(0) }"},"target":"h2::proto::streams::streams"} {"timestamp":"2022-07-05T08:16:41.390499Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0"},"target":"h2::proto::streams::counts"} {"timestamp":"2022-07-05T08:16:41.390529Z","level":"TRACE","fields":{"message":"release_capacity; size=52"},"target":"h2::proto::streams::recv"} {"timestamp":"2022-07-05T08:16:41.390541Z","level":"TRACE","fields":{"message":"release_connection_capacity; size=52, connection in_flight_data=52"},"target":"h2::proto::streams::recv"} {"timestamp":"2022-07-05T08:16:41.390549Z","level":"TRACE","fields":{"message":"release_capacity; size=0"},"target":"h2::proto::streams::recv"} {"timestamp":"2022-07-05T08:16:41.390559Z","level":"TRACE","fields":{"message":"release_connection_capacity; size=0, connection in_flight_data=0"},"target":"h2::proto::streams::recv"} {"timestamp":"2022-07-05T08:16:41.390569Z","level":"TRACE","fields":{"message":"drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(64976), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x7f42841b1a50, vtable: 0x5603239173c0 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097100), available: Window(2097152) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Remaining(0) }"},"target":"h2::proto::streams::streams"} {"timestamp":"2022-07-05T08:16:41.390598Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0"},"target":"h2::proto::streams::counts"} {"timestamp":"2022-07-05T08:16:41.390691Z","level":"TRACE","fields":{"message":"schema did not change"},"target":"apollo_uplink"} {"timestamp":"2022-07-05T08:16:41.390706Z","level":"TRACE","fields":{"message":"pool closed, canceling idle interval"},"target":"hyper::client::pool"} {"timestamp":"2022-07-05T08:16:41.390718Z","level":"TRACE","fields":{"message":"client::dispatch::Sender dropped"},"target":"hyper::proto::h2::client"} {"timestamp":"2022-07-05T08:16:41.390715Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390791Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","span":{"name":"FramedRead::poll_next"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]} {"timestamp":"2022-07-05T08:16:41.390869Z","level":"TRACE","fields":{"message":"poll_complete"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390898Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.390943Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.391002Z","level":"TRACE","fields":{"message":"send_request dropped, starting conn shutdown"},"target":"hyper::proto::h2::client"} {"timestamp":"2022-07-05T08:16:41.391032Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391073Z","level":"DEBUG","fields":{"message":"send","frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }"},"target":"h2::codec::framed_write","span":{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.391105Z","level":"TRACE","fields":{"message":"encoding GO_AWAY; code=NO_ERROR"},"target":"h2::frame::go_away","span":{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.391132Z","level":"TRACE","fields":{"message":"encoded go_away","rem":17},"target":"h2::codec::framed_write","span":{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }","name":"FramedWrite::buffer"}]} {"timestamp":"2022-07-05T08:16:41.391171Z","level":"DEBUG","fields":{"message":"Connection::poll; connection error","error":"GoAway(b\"\", NO_ERROR, Library)"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391201Z","level":"TRACE","fields":{"message":" -> already going away"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391222Z","level":"TRACE","fields":{"connection.state":"Closing(NO_ERROR, Library)"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391244Z","level":"TRACE","fields":{"message":"connection closing after flush"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391272Z","level":"TRACE","fields":{"queued_data_frame":false},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.391305Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","span":{"name":"FramedWrite::flush"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]} {"timestamp":"2022-07-05T08:16:41.391374Z","level":"TRACE","fields":{"connection.state":"Closed(NO_ERROR, Library)"},"target":"h2::proto::connection","span":{"name":"poll"},"spans":[{"peer":"Client","name":"Connection"},{"name":"poll"}]} {"timestamp":"2022-07-05T08:16:41.391426Z","level":"TRACE","fields":{"message":"Streams::recv_eof"},"target":"h2::proto::streams::streams"} {"timestamp":"2022-07-05T08:16:50.937089Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn"} ```

I could send you all of the logs (~76k lines), but I'd need an automated way to anonymize them - our Apollo key as well some IPs are there.

[Geal]

@radekmie we're not sure yet it would fix your issue but https://github.com/apollographql/router/pull/1350 is very probably related to it

[Geal]

@radekmie we just released the router v0.10, can you check if it solves your issue?

[radekmie]

@Geal I can confirm that v0.10.0 solved the problem. Thank you for your fast response!

[Geal]

awesome!