Http2ServerResponse#write(ByteBuf, boolean, Handler<AsyncResult<Void>>) should take empty trailers into consideration

[markdr-fr]

As part of the processing within io.vertx.core.http.impl.Http2ServerResponse#write(io.netty.buffer.ByteBuf, boolean, io.vertx.core.Handler<io.vertx.core.AsyncResult<java.lang.Void>>), the trailers variable is checked for null but not also if it is empty, which can lead to some parts of the response end processing to not complete as expected and no END_STREAM flag being sent.

This can occur when io.vertx.core.http.impl.Http2ServerResponse#trailers is called but no trailers are actually added.

[vietj]

can you provide a reproducer @markdr-fr ?

[markdr-fr]

This was seen when a Vert.x server app was deployed into k8 and liveness probes were failing with a PROTOCOL_ERROR. The server app was configured to listen on HTTPS and k8 was seen to be making HTTP/2 requests, from more detailed go debug logs it was a missing END_STREAM flag that was tripping up the go client. A standalone go app can be used to get the same results.

Taking the the typical Vert.x example, passing an HttpServerOptions options that has SSL enabled and making a call to response.trailers() but not adding a trailer is enough, for example:

public void start() throws Exception {
    // Create the HTTP server
    vertx.createHttpServer(options)
            // Handle every request using the router
            .requestHandler(httpServerRequest -> {
                HttpServerResponse response = httpServerRequest.response();
                response.trailers();
                response.putHeader("content-type", "text/plain").end("Hello from Vert.x!");
            })
            // Start listening
            .listen(8888)
            // Print the port
            .onSuccess(server ->
                    System.out.println("HTTP server started on port " + server.actualPort())
            );
  }

With verbose http2 logging enabled and running go client:

2021/06/30 12:31:32 http2: Framer 0xc0001720e0: read HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:31:32 http2: decoded hpack field header field ":status" = "200"
2021/06/30 12:31:32 http2: decoded hpack field header field "content-type" = "text/plain"
2021/06/30 12:31:32 http2: decoded hpack field header field "content-length" = "18"
2021/06/30 12:31:32 http2: Transport received HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:31:32 http2: Framer 0xc0001720e0: read DATA stream=1 len=18 data="Hello from Vert.x!"
2021/06/30 12:31:32 http2: Transport received DATA stream=1 len=18 data="Hello from Vert.x!"
2021/06/30 12:31:32 http2: Transport readFrame error on conn 0xc00014e180: (http2.StreamError) stream error: stream ID 1; PROTOCOL_ERROR
2021/06/30 12:31:32 http2: Framer 0xc0001720e0: wrote RST_STREAM stream=1 len=4 ErrCode=PROTOCOL_ERROR
2021/06/30 12:31:32 Failed reading response body: stream error: stream ID 1; PROTOCOL_ERROR

Taking out the trailers() call and things look better:

2021/06/30 12:43:47 http2: Framer 0xc0001a80e0: read HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:43:47 http2: decoded hpack field header field ":status" = "200"
2021/06/30 12:43:47 http2: decoded hpack field header field "content-type" = "text/plain"
2021/06/30 12:43:47 http2: decoded hpack field header field "content-length" = "18"
2021/06/30 12:43:47 http2: Transport received HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:43:47 http2: Framer 0xc0001a80e0: read DATA flags=END_STREAM stream=1 len=18 data="Hello from Vert.x!"
2021/06/30 12:43:47 http2: Transport received DATA flags=END_STREAM stream=1 len=18 data="Hello from Vert.x!"
Got response 200: HTTP/2.0 Hello from Vert.x!

A similar result when a trailer is added:

2021/06/30 12:45:48 http2: Framer 0xc0001b00e0: read HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:45:48 http2: decoded hpack field header field ":status" = "200"
2021/06/30 12:45:48 http2: decoded hpack field header field "content-type" = "text/plain"
2021/06/30 12:45:48 http2: decoded hpack field header field "content-length" = "18"
2021/06/30 12:45:48 http2: Transport received HEADERS flags=END_HEADERS|PRIORITY stream=1 len=22
2021/06/30 12:45:48 http2: Framer 0xc0001b00e0: read DATA stream=1 len=18 data="Hello from Vert.x!"
2021/06/30 12:45:48 http2: Transport received DATA stream=1 len=18 data="Hello from Vert.x!"
2021/06/30 12:45:48 http2: Framer 0xc0001b00e0: read HEADERS flags=END_STREAM|END_HEADERS|PRIORITY stream=1 len=26
2021/06/30 12:45:48 http2: decoded hpack field header field "x-trailer" = "x-trailer"
2021/06/30 12:45:48 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS|PRIORITY stream=1 len=26
Got response 200: HTTP/2.0 Hello from Vert.x!

This area of the code looks to be the key logic to include a check for trailers.isEmpty() along with null - io.vertx.core.http.impl.Http2ServerResponse#write(io.netty.buffer.ByteBuf, boolean, io.vertx.core.Handler<io.vertx.core.AsyncResult<java.lang.Void>>)

      boolean sent = checkSendHeaders(end && !hasBody && trailers == null);
      if (hasBody || (!sent && end)) {
        stream.writeData(chunk, end && trailers == null, handler);
      }
      if (end && trailers != null) {
        stream.writeHeaders(trailers, true, null);
      }

[laurentvaills]

Given that HttpServerResponse#trailers() lazily creates an empty Map for the trailers, just a simple call to this method make trailers non-null anymore.
So maybe everywhere a non-null check on trailers should be changed to (trailers == null || trailers.isEmpty()) ?

[vietj]

can you contribute a test and fix ?

[vietj]

so we are assuming that an empty trailer frame cannot be sent here

[vietj]

which client are you using exactly ?

[vietj]

my point is that I checked what it does to use an empty trailer and from the HTTP/2 perspective it seems valid to send an empty trailer frame, so I'm wondering if I'm not missing something here and why the client would complain

[markdr-fr]

I have only seen this as an issue for a GO client, standalone and within a k8 environment, when making http/2 HTTPS requests.
I can't validate if not sending an END_STREAM flag is valid http/2 behaviour but that appears to be the key difference between the 2 scenarios.

[vietj]

can you provide explanation with go client reproducing it ?

…

On Thu, Jul 1, 2021 at 12:31 AM markdr-fr ***@***.***> wrote: I have only seen this as an issue for a GO client, standalone and within a k8 environment, when making http/2 HTTPS requests. I can't validate if not sending an END_STREAM flag is valid http/2 behaviour but that appears to be the key difference between the 2 scenarios. — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub <#3985 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABXDCVXBEBQTKDHQPFS2J3TVOLKNANCNFSM47NBFS3A> .

[markdr-fr]

Here is a basic go client that can be used to reproduce the above logging output/behaviour. It is based on the examples found online, main difference is forcing it to use http/2 when making HTTPS calls. To get maximum debug logging, set this before running the go client export GODEBUG=http2debug=2

package main

import (
	"crypto/tls"
	"fmt"
	"io/ioutil"
	"log"
	"net/http"
	"golang.org/x/net/http2"
)

func main() {
	conf := &tls.Config{
		InsecureSkipVerify: true,
	}
	transport := &http2.Transport{
		TLSClientConfig: conf,
	}
	client := &http.Client{
		Transport: transport,
	}
	resp, err := client.Get("https://localhost:8888/")
	if err != nil {
		log.Fatalf("Failed get: %s", err)
	}
	defer resp.Body.Close()
	body, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		log.Fatalf("Failed reading response body: %s", err)
	}
	fmt.Printf("Got response %d: %s %s\n", resp.StatusCode, resp.Proto, string(body))
}

[vietj]

thanks