Log of read only connection stream gives connection closed messages

[nulian]

I'm working with grpc server_stream and the server where i'm connected with will throw an {:goaway, :no_error, ""}

And it will keep giving me data messages afterwards but the log in mint confused me a bit because it showed [debug] Server closed connection normally (with debug data: "")

Data keeps coming in so it seems to me that log message isn't fitting when a read stream is still open.

[whatyouhide]

Hi @nulian!

Do you have a small example that reproduces this error?

[nulian]

Can post test app but might be a lot of work to setup because it's authzed + grpc client master branch connecting to spicedb. And then changed their mint adapter for the Mint.open? to check on read instead of the default so it wouldn't break connection on server stream.

So maybe posting my logs and debug will help enough for it.

The error is mostly the debug message that was added in 1.5 Server closed connection while it still is open in 1 direction. Here is the grpc connection when it switches over from both directions to server_stream only.

First it get's this message after like 30 seconds having the connection open.

{:tcp, #Port<0.9>,
 <<0, 0, 8, 7, 0, 0, 0, 0, 0, 127, 255, 255, 255, 0, 0, 0, 0, 0, 0, 8, 6, 0, 0,
   0, 0, 0, 1, 6, 1, 8, 0, 3, 3, 9>>}
[debug] Received frame: GOAWAY[stream_id: 0, flags: 0, last_stream_id: 2147483647, error_code: :no_error, debug_data: ""]
[debug] Received frame: PING[stream_id: 0, flags: 0, opaque_data: <<1, 6, 1, 8, 0, 3, 3, 9>>]
[debug] Server closed connection normally (with debug data: "")

Mint connection

%Mint.HTTP2{
  buffer: "",
  client_settings: %{
    enable_push: true,
    initial_window_size: 65535,
    max_concurrent_streams: 100,
    max_frame_size: 16384,
    max_header_list_size: :infinity
  },
  client_settings_queue: {[], []},
  decode_table: %HPAX.Table{
    entries: [
      {"io.spicedb.respmeta.requestid", "b9da65e8303b5671786310f2bedc9ee6"},
      {"content-type", "application/grpc"}
    ],
    length: 2,
    max_table_size: 4096,
    size: 153
  },
  encode_table: %HPAX.Table{
    entries: [{"te", "trailers"}],
    length: 1,
    max_table_size: 4096,
    size: 42
  },
  headers_being_processed: nil,
  hostname: "localhost",
  log: true,
  mode: :active,
  next_stream_id: 5,
  open_client_stream_count: 1,
  open_server_stream_count: 0,
  ping_queue: {[], []},
  port: 50051,
  private: %{},
  proxy_headers: [],
  ref_to_stream_id: %{#Reference<0.2883477312.2718695436.233169> => 3},
  scheme: "http",
  server_settings: %{
    enable_connect_protocol: false,
    enable_push: true,
    initial_window_size: 65535,
    max_concurrent_streams: 100,
    max_frame_size: 16384,
    max_header_list_size: :infinity
  },
  socket: #Port<0.9>,
  state: {:goaway, :no_error, ""},
  streams: %{
    3 => %{
      id: 3,
      received_first_headers?: true,
      ref: #Reference<0.2883477312.2718695436.233169>,
      state: :half_closed_local,
      window_size: 65530
    }
  },
  transport: Mint.Core.Transport.TCP,
  window_size: 65535
}

Then second message

{:tcp, #Port<0.9>, <<0, 0, 8, 7, 0, 0, 0, 0, 0, 0, 0, 0, 3, 0, 0, 0, 0>>}
[debug] Received frame: GOAWAY[stream_id: 0, flags: 0, last_stream_id: 3, error_code: :no_error, debug_data: ""]
[debug] Server closed connection normally (with debug data: "")

Mint client stays the same

After that you will get data streams which is mostly repeat of below though debug message server closed is a bit weird

[debug] Received frame: DATA[stream_id: 3, flags: 0, data: <<0, 0, 0, 0, 109, 10, 91, 8, 3, 18, 87, 10, 44, 10, 4, 114, 111, 108, 101, 18, 36, 100, 57, 99, 51, 55, 49, 97, 54, 45, 98, 50, 98, 53, 45, 52, 55, 51, 101, 45, 57, 50, 99, 57, 45, 53, 102, ...>>, padding: nil]
[debug] Server closed connection normally (with debug data: "")

%Mint.HTTP2{
  buffer: "",
  client_settings: %{
    enable_push: true,
    initial_window_size: 65535,
    max_concurrent_streams: 100,
    max_frame_size: 16384,
    max_header_list_size: :infinity
  },
  client_settings_queue: {[], []},
  decode_table: %HPAX.Table{
    entries: [
      {"io.spicedb.respmeta.requestid", "b9da65e8303b5671786310f2bedc9ee6"},
      {"content-type", "application/grpc"}
    ],
    length: 2,
    max_table_size: 4096,
    size: 153
  },
  encode_table: %HPAX.Table{
    entries: [{"te", "trailers"}],
    length: 1,
    max_table_size: 4096,
    size: 42
  },
  headers_being_processed: nil,
  hostname: "localhost",
  log: true,
  mode: :active,
  next_stream_id: 5,
  open_client_stream_count: 1,
  open_server_stream_count: 0,
  ping_queue: {[], []},
  port: 50051,
  private: %{},
  proxy_headers: [],
  ref_to_stream_id: %{#Reference<0.2883477312.2718695436.233169> => 3},
  scheme: "http",
  server_settings: %{
    enable_connect_protocol: false,
    enable_push: true,
    initial_window_size: 65535,
    max_concurrent_streams: 100,
    max_frame_size: 16384,
    max_header_list_size: :infinity
  },
  socket: #Port<0.9>,
  state: {:goaway, :no_error, ""},
  streams: %{
    3 => %{
      id: 3,
      received_first_headers?: true,
      ref: #Reference<0.2883477312.2718695436.233169>,
      state: :half_closed_local,
      window_size: 65530
    }
  },
  transport: Mint.Core.Transport.TCP,
  window_size: 65535
}

[whatyouhide]

You are correct, this is just an issue with the logging. Should be fixed by https://github.com/elixir-mint/mint/pull/398.