h2c support

README.md

@@ -4,7 +4,7 @@
 [![Go Reference](https://pkg.go.dev/badge/github.com/mt-inside/http-log.svg)](https://pkg.go.dev/github.com/mt-inside/http-log)
 [![Go Report Card](https://goreportcard.com/badge/github.com/mt-inside/http-log)](https://goreportcard.com/report/github.com/mt-inside/http-log)
 
-todo Asciinema etc
+TODO Asciinema etc
 
 ## Stand-alone Daemon
 
@@ -33,3 +33,18 @@ ${GOPATH}/bin/http-log
 `docker build ./cmd/lambda`
 
 Packaging and publishing is left as an exercise for the reader (I forgot how I did it)
+
+# Usage
+
+## HTTP Versions
+
+Note: h2c - h2 cleartext - is the name for h2/plaintext. The "correct" way to initiate such a connection is to send an http/1.1 request with an `Upgrade: h2c` field. Of course a client (like an Envoy proxy) can be configured with a-priori knowledge that the server accepts h2c, and just send h2 right away.
+
+* With TLS (a `-K` option other than `off`, or `-k/-c`)
+  * Default: TLS's ALPN field allows client and server to negotiate HTTP version. http-log supports h2, and any modern client will do as well. The default with TLS enabled is "let it negotiate", which makes h2 effectively the default.
+  * With `--http-11`: we force http/1.1. This is done by returning _no_ protocols in the ALPN field, which means negotiation can't happen, and the default is used, which is http/1.1.
+* Without TLS (`-K=off`, or no `-K` and no `-k/-c`) http/1.1 is the "standard" version. It's usually quite hard to force clients (and server libraries) to do h2 over plaintext.
+  * Default: because of some magic in the Go libraries, it's able to accept either http/1.1 or h2 simultaneously. h2 connections can either be h2 on the first request, or can upgrade with an HTTP/1.1 call with header `Upgrade: h2c`.
+  * With `--http-11`: we disable the h2 handling. http/1.1 will work fine.
+    * If you send an h2c upgrade request you'll see it printed, but the h2 upgrade and "main" request won't happen.
+    * If you send an immediate h2 request, you'll see a log of a PRI method, with no other data (as that very first part of the h2 request is h1 compatible)

cmd/http-log/main.go

@@ -21,6 +21,8 @@ import (
 	"github.com/pires/go-proxyproto"
 	"github.com/tetratelabs/telemetry"
 	"github.com/tetratelabs/telemetry/scope"
+	"golang.org/x/net/http2"
+	"golang.org/x/net/http2/h2c"
 
 	"github.com/mt-inside/http-log/internal/build"
 	"github.com/mt-inside/http-log/internal/ctxt"
@@ -273,14 +275,28 @@ func main() {
 		actionMux,
 	)
 
+	lis, err := net.Listen("tcp", opts.ListenAddr)
+	b.Unwrap(err)
+
+	proxyLis := &proxyproto.Listener{
+		Listener:          lis,
+		ReadHeaderTimeout: opts.HandleTimeout,
+	}
+	defer proxyLis.Close()
+
+	srv2 := &http2.Server{
+		IdleTimeout: 0,
+	}
+
 	srv := &http.Server{
-		Addr:              opts.ListenAddr,
-		ReadHeaderTimeout: opts.HandleTimeout, // Time for reading request headers (docs are unclear but seemingly subsumed into ReadTimeout)
-		ReadTimeout:       opts.HandleTimeout, // Time for reading request headers + body
-		WriteTimeout:      opts.HandleTimeout, // Time for writing response (headers + body)
-		IdleTimeout:       0,                  // Time between requests before the connection is dropped, when keep-alives are used.
-		Handler:           loggingMux,
-		// Called when the http server starts listening
+		Addr:              opts.ListenAddr,                                                          // TODO: doesn't need to be here because we make our own net.lis?
+		ReadHeaderTimeout: opts.HandleTimeout,                                                       // Time for reading request headers (docs are unclear but seemingly subsumed into ReadTimeout)
+		ReadTimeout:       opts.HandleTimeout,                                                       // Time for reading request headers + body
+		WriteTimeout:      opts.HandleTimeout,                                                       // Time for writing response (headers + body)
+		IdleTimeout:       0,                                                                        // Time between requests before the connection is dropped, when keep-alives are used.
+		Handler:           utils.Ternary(opts.Http11, loggingMux, h2c.NewHandler(loggingMux, srv2)), // This lib is tres useful. It handles upgrades from h1 using `Upgrade: h2c`, and also makes immediate-h2 work, I guess by spotting the PRI method and hijacking. It even arranges for BaseContext and ConnContext to be called, which I couldn't figure out driving http2 manually
+		// Called when the http server starts listening.
+		// Not called by http2.ServeCon
 		BaseContext: func(l net.Listener) context.Context {
 			extractor.NetListener(l, srvData)
 
@@ -293,6 +309,7 @@ func main() {
 			return ctx
 		},
 		// Called when the http server accepts an incoming connection
+		// Not called by h2.
 		ConnContext: func(ctx context.Context, c net.Conn) context.Context {
 			// TODO: ctx has a bunch of info under context-key "http-server"
 
@@ -313,15 +330,12 @@ func main() {
 			ctx = ctxt.RespDataToContext(ctx, respData)
 			ctx = ctxt.CtxCancelToContext(ctx, cancel)
 
-			if _, found := hackStore[c.RemoteAddr()]; found {
-				panic("Assumption broken: remoteAddr reused")
-				// TODO: remove conns from the map when their state changes to closed
-			}
-			hackStore[c.RemoteAddr()] = ctx
+			toHackStore(c, ctx)
 
 			return ctx
 		},
 		// Called when an http server connection changes state
+		// Called by h2.
 		ConnState: func(c net.Conn, cs http.ConnState) {
 			_, log := fromHackStore(c, log)
 
@@ -334,14 +348,6 @@ func main() {
 		},
 	}
 
-	lis, err := net.Listen("tcp", srv.Addr)
-	b.Unwrap(err)
-	proxyLis := &proxyproto.Listener{
-		Listener:          lis,
-		ReadHeaderTimeout: opts.HandleTimeout,
-	}
-	defer proxyLis.Close()
-
 	if srvData.TlsOn {
 		srv.TLSConfig = &tls.Config{
 			/* Hooks in order they're called */
@@ -395,12 +401,52 @@ func main() {
 		log.Info("Server shutting down")
 	} else {
 		b.Unwrap(srv.Serve(proxyLis))
+		// The h2c library is magic and handles h2/plaintext, even those without prior Upgrade requests.
+		// However if you did wanna do h2 manually, this is how (since I went to the effort of working it out):
+		// for {
+		// 	conn, err := proxyLis.Accept()
+		// 	b.Unwrap(err)
+
+		// 	// Have to do BaseContext and ConnContext in here. Neither are called by h2.
+		// 	ctx := context.Background()
+		// 	ctx = ctxt.SrvDataToContext(ctx, srvData)
+		// 	var cancel context.CancelFunc
+		// 	ctx, cancel = context.WithTimeout(ctx, opts.Timeout)
+		// 	reqData := state.NewRequestData()
+		// 	respData := state.NewResponseData()
+
+		// 	requestNo++
+		// 	ctx = telemetry.KeyValuesToContext(ctx, "request", requestNo)
+		// 	log := log.With(telemetry.KeyValuesFromContext(ctx)...)
+		// 	log.Info("Accepting tcp connection")
+		// 	extractor.NetConn(conn, requestNo, reqData)
+
+		// 	ctx = ctxt.ReqDataToContext(ctx, reqData)
+		// 	ctx = ctxt.RespDataToContext(ctx, respData)
+		// 	ctx = ctxt.CtxCancelToContext(ctx, cancel)
+		// 	toHackStore(conn, ctx)
+		// 	go srv2.ServeConn(
+		// 		conn,
+		// 		&http2.ServeConnOpts{
+		// 			BaseConfig: srv,
+		// 			Context:    ctx,
+		// 		},
+		// 	)
+		// }
 		log.Info("Server shutting down")
 	}
 }
 
 var hackStore = map[net.Addr]context.Context{}
 
+func toHackStore(c net.Conn, ctx context.Context) {
+	// TODO lock me
+	if _, found := hackStore[c.RemoteAddr()]; found {
+		panic("Assumption broken: remoteAddr reused")
+		// TODO: remove conns from the map when their state changes to closed
+	}
+	hackStore[c.RemoteAddr()] = ctx
+}
 func fromHackStore(c net.Conn, log telemetry.Logger) (context.Context, telemetry.Logger) {
 	// TODO lock me
 	ctx, found := hackStore[c.RemoteAddr()]

go.mod

@@ -16,11 +16,13 @@ require (
 	github.com/pires/go-proxyproto v0.7.0
 	github.com/tetratelabs/telemetry v0.8.0
 	go.uber.org/zap v1.25.0
+	golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4
 )
 
 require (
 	go.uber.org/multierr v1.11.0 // indirect
 	golang.org/x/exp v0.0.0-20230817173708-d852ddb80c63 // indirect
 	golang.org/x/sys v0.11.0 // indirect
+	golang.org/x/text v0.3.3 // indirect
 	k8s.io/klog/v2 v2.100.1 // indirect
 )

go.sum

@@ -62,6 +62,7 @@ golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
 golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
 golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
+golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4 h1:4nGaVu0QrbjT/AK2PRLuQfQuh6DJve+pELhqTdAj3x0=
 golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM=
 golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
@@ -76,6 +77,7 @@ golang.org/x/sys v0.11.0 h1:eG7RXZHdqOJ1i+0lgLgCpSXAp6M3LYlAo6osgSi0xOM=
 golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
+golang.org/x/text v0.3.3 h1:cokOdA+Jmi5PJGXLlLllQSgYigAEfHXJAERHVMaCc2k=
 golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=

melange.yaml

@@ -1,7 +1,7 @@
 package:
   name: http-log
   epoch: 0
-  version: v0.7.17-3-gea2a80b-dirty
+  version: v0.7.17-7-g5b74b27-dirty
   description: Logs HTTP requests
   url: https://github.com/mt-inside/http-log
   copyright:

pkg/handlers/log_middle.go

@@ -44,6 +44,7 @@ func (lm LogMiddle) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 	extractor.HttpRequest(r, srvData, reqData)
 
+	// TODO: h2c upgraded requests (eg from curl --http2, to us running plaintext without --http-11) stall here. If you ctrl-c curl (ie close the pipe) then we will show the right stuff. So reading the body is blocking after the h2c uprade. Read the h2c docs re closed bodies and what you're meant to do.
 	reqData.HttpBody, reqData.HttpBodyErr = io.ReadAll(r.Body)
 	reqData.HttpBodyTime = time.Now()