Confusing behavior for H2 session closed by client before a request is sent

[nigoroll]

This issue is about behavior originally observed in production on varnish-6.0.13 with varnishlog -g session -q ... after enabling the Debug vsl:

*   << Session  >> 166912765
-   Begin          sess 0 PROXY
-   SessOpen       0.0.0.0 0 ssloff8443 0.0.0.0 0 1740071921.280130 2005
(...sockopt-related removed..)
-   Proxy          2 *redacted* 37430 *redacted* 8443
-   Debug          "H2: Got pu PRISM%00"
-   Debug          "H2RXF SETTINGS[6] 0x00 0x00000000 0x000401000000%00"
-   Debug          "H2SETTING initial_window_size=0x01000000%00"
-   Debug          "H2RXF WINDOW_UPDATE[4] 0x00 0x00000000 0x00ff0001%00"
-   Debug          "H2 CLEANUP ENHANCE_YOUR_CALM%00"
-   ReqAcct        18 10 28 27 14 41
-   End

Here the circumstances leading to the situation are not clear from the log, there is no information given regarding which system call failed and no session closure reason. Also, why ENHANCE_YOUR_CALM ?

It has taken me a surprisingly long time trying to come up with a reproducer, and I now I hope to have one:

varnishtest "PROXY2 http2 SHUT_WR before request"

varnish v1 \
    -arg "-a ${tmpdir}/v1.sock,PROXY" \
    -arg "-p feature=+http2" \
    -arg "-p debug=+syncvsl" \
    -vcl+backend {
    	backend proforma none;
} -start

client c1 -connect "${tmpdir}/v1.sock" -proxy2 "1.2.3.4:2314 5.6.7.8:2828" {
	txpri
	stream 0 {
		txsettings -winsize 16777216
		txwinup -size 16711681
	} -run
	shutdown -write
} -run

When run on varnish-6.0.13 (a395739 with a backport of c40c352), the relevant VSL produced by the test case is:

1000 Begin           c sess 0 PROXY
1000 SessOpen        c 0.0.0.0 0 a0 0.0.0.0 0 1740215897.228172 21
(...sockopt-related removed..)
1000 Proxy           c 2 1.2.3.4 2314 5.6.7.8 2828                                                                                      
   0 Debug           - H2 Prior Knowledge Upgrade
1000 Debug           c H2: Got pu PRISM                                                                                                 
1000 H2RxHdr         c [000006040000000000]
1000 H2RxBody        c [000401000000]
1000 Debug           c H2RXF SETTINGS[6] 0x00 0x00000000 0x000401000000
1000 Debug           c H2SETTING initial_window_size=0x01000000
1000 H2RxHdr         c [000004080000000000]
1000 H2RxBody        c [00ff0001]
1000 Debug           c H2RXF WINDOW_UPDATE[4] 0x00 0x00000000 0x00ff0001
1000 Debug           c H2 CLEANUP ENHANCE_YOUR_CALM
1000 ReqAcct         c 18 10 28 27 20 47
1000 End             c 
1000 SessClose       c OVERLOAD 0.010
1000 End             c 

One difference which I am unhappy about is that in the production VSL, 14 response body bytes are logged, but 20 in the suspected reproducer.

So here we already see one issue, the duplicate End, which explains why we do not see the SessClose in the production VSL.

When run on current code 3cd6596, the VSL from the VTC is:

1000 Begin           c sess 0 PROXY
1000 SessOpen        c 0.0.0.0 0 a0 0.0.0.0 0 1740216325.010066 19
(...sockopt-related removed..)
1000 Proxy           c 2 1.2.3.4 2314 5.6.7.8 2828
1000 Debug           c H2 Prior Knowledge Upgrade
1000 Debug           c H2: Got pu PRISM
1000 H2RxHdr         c [000006040000000000]
1000 H2RxBody        c [000401000000]
1000 Debug           c H2RXF SETTINGS[6] 0x00 0x00000000 0x000401000000
1000 Debug           c H2SETTING initial_window_size=0x01000000
1000 H2RxHdr         c [000004080000000000]
1000 H2RxBody        c [00ff0001]
1000 Debug           c H2RXF WINDOW_UPDATE[4] 0x00 0x00000000 0x00ff0001
1000 SessError       c H2: HTC eof (Unexpected end of input)
1000 Debug           c H2 CLEANUP ENHANCE_YOUR_CALM
1000 ReqAcct         c 18 10 28 27 26 53
1000 SessClose       c OVERLOAD 0.012
1000 End             c                       

So two problems have been solved in the meantime: There is no duplicate End any more, and a helpful SessError is logged.

But is H2 ENHANCE_YOUR_CALM / SessClose OVERLOAD the best option?

[nigoroll]

So two problems have been solved in the meantime: There is no duplicate End any more, and a helpful SessError is logged.

Checked other branches:

• 7.5 f74d210 has End tag corrected, but no SessError

1000 Debug           c H2: Got pu PRISM
1000 H2RxHdr         c [000006040000000000]
1000 H2RxBody        c [000401000000]
1000 Debug           c H2RXF SETTINGS[6] 0x00 0x00000000 0x000401000000
1000 Debug           c H2SETTING initial_window_size=0x01000000
1000 H2RxHdr         c [000004080000000000]
1000 H2RxBody        c [00ff0001]
1000 Debug           c H2RXF WINDOW_UPDATE[4] 0x00 0x00000000 0x00ff0001
1000 Debug           c H2 CLEANUP ENHANCE_YOUR_CALM
1000 ReqAcct         c 18 10 28 27 26 53
1000 SessClose       c OVERLOAD 0.010
1000 End             c                  

• 7.6.1 c3d5882 has SessError. This was introduced with 9381d23 from H2: Improve logging for connection level errors #4150

1000 Debug           c H2: Got pu PRISM
1000 H2RxHdr         c [000006040000000000]
1000 H2RxBody        c [000401000000]
1000 Debug           c H2RXF SETTINGS[6] 0x00 0x00000000 0x000401000000
1000 Debug           c H2SETTING initial_window_size=0x01000000
1000 H2RxHdr         c [000004080000000000]
1000 H2RxBody        c [00ff0001]
1000 Debug           c H2RXF WINDOW_UPDATE[4] 0x00 0x00000000 0x00ff0001
1000 SessError       c H2: HTC eof (Unexpected end of input)
1000 Debug           c H2 CLEANUP ENHANCE_YOUR_CALM
1000 ReqAcct         c 18 10 28 27 26 53
1000 SessClose       c OVERLOAD 0.009
1000 End             c