Au test post-early-return fails sporadically for HTTP/2 client

[ywkaras]

I change the test to enable debug output for tag http2_stream. I ran the test 80 times, and it failed 5 times. I removed the timestamp and event thread number from the output. This is the output for (all) the failed runs:

<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_LOCAL
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
<Http2Stream.cc:434 (do_io_close)> (http2_stream) [4] [1] do_io_close
<Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [4] [1] Destroy stream, sent 0 bytes

The output for the successful runs was either (16 runs):

<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_LOCAL
<Http2Stream.cc:434 (do_io_close)> (http2_stream) [4] [1] do_io_close
<Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [4] [1] Destroy stream, sent 0 bytes
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED

or (59 runs):

<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
<Http2Stream.cc:376 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
<Http2Stream.cc:434 (do_io_close)> (http2_stream) [4] [1] do_io_close
<Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [4] [1] Destroy stream, sent 0 bytes

The commit (on master) I built to do this test: 4547ed7

config.nice:

#! /bin/sh
#
# Created by configure

CFLAGS=" "; export CFLAGS
CXXFLAGS=" "; export CXXFLAGS
LDFLAGS="-L/opt/oath/libssh2/1.8/lib -L/opt/oath/nghttp2/1.36/lib"; export LDFLAGS
"./configure" \
"--with-openssl=/opt/oath/openssl/1.1.1" \
"--enable-experimental-plugins" \
"--enable-example-plugins" \
"--with-brotli=/opt/oath/brotli/1.0/include:/opt/oath/brotli/1.0/lib" \
"--enable-ccache" \
"--enable-werror" \
"--prefix=/Users/wkaras/TSX/TS4" \
"--exec-prefix=/Users/wkaras/TSX/TS4" \
"PKG_CONFIG_PATH=/opt/rh/devtoolset-8/root/usr/lib64/pkgconfig:/opt/rh/httpd24/root/usr/lib64/pkgconfig:/opt/rh/rh-python36/root/usr/lib64/pkgconfig:/opt/rh/devtoolset-8/root/usr/lib64/pkgconfig:/opt/rh/httpd24/root/usr/lib64/pkgconfig:/opt/rh/devtoolset-8/root/usr/lib64/pkgconfig" \
"CFLAGS=" \
"LDFLAGS=-L/opt/oath/libssh2/1.8/lib -L/opt/oath/nghttp2/1.36/lib" \
"CXXFLAGS=" \
"$@"

This was on RHEL7 (with mysterious Yahoo hacks) and devtoolset 8.

[ywkaras]

The error output of the (verbose) failed curl command is:

*   Trying 127.0.0.1:61311...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Connected to 127.0.0.1 (127.0.0.1) port 61311 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/pki/tls/certs/ca-bundle.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [873 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [264 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=IE; ST=Dublin; L=Dublin; O=example.com; OU=example.com; CN=example.com
*  start date: Jan 26 14:56:08 2021 GMT
*  expire date: Aug 21 14:56:08 2119 GMT
*  issuer: C=IE; ST=Dublin; L=Dublin; O=example.com; OU=example.com; CN=example.com
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multiplexing
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x1523ad0)
} [5 bytes data]
> POST /post-http2 HTTP/2
> Host: 127.0.0.1:61311
> user-agent: curl/7.79.0-DEV
> accept: */*
> content-length: 2310700
> content-type: application/x-www-form-urlencoded
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
} [5 bytes data]
< HTTP/2 420 
< content-length: 0
< date: Wed, 17 Nov 2021 20:19:03 GMT
< age: 0
< server: ATS/10.0.0
* HTTP error before end of send, stop sending
< 
* HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)
* stopped the pause stream!
 61 2256k    0     0   61 1391k      0  60.0M --:--:-- --:--:-- --:--:-- 61.7M
* Connection #0 to host 127.0.0.1 left intact
curl: (92) HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)

[ywkaras]

This is the bash script I used to find the three unique cases:

rm -rf /tmp/dir
mkdir /tmp/dir
mkdir /tmp/dir/link

let N=0
for I in $( seq 1 80 )
do
  fgrep DEBUG: xyz$I/_output/*ts/*all* | sed 's/^.*DEBUG: //' >| /tmp/dir/tmp
  let F=0
  if (( N != 0 )) ; then
    for I2 in $( seq 1 $N )
    do
      cmp /tmp/dir/tmp /tmp/dir/out$I2
      if (( $? == 0 )) ; then
        ln -s /tmp/dir/out$I2 /tmp/dir/link/out$I
        let F=1
        break
      fi
    done
  fi
  if (( F == 0 )) ; then
    let N=N+1
    mv /tmp/dir/tmp /tmp/dir/out$N
    ln -s /tmp/dir/out$N /tmp/dir/link/out$I
  fi
done

[maskit]

I suppose the INTERNAL_ERROR came from here:

trafficserver/proxy/http2/Http2ConnectionState.cc

Lines 181 to 184 in 4547ed7

	MIOBuffer *writer = stream->read_vio_writer();
	if (writer == nullptr) {
	return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_STREAM, Http2ErrorCode::HTTP2_ERROR_INTERNAL_ERROR);
	}

[ywkaras]

If anyone wants to try to reproduce this, the way I run the same test back to back, multiple times, is to first cd to the directory containing the test, and create aliases for it using symbolic links:

for n in $( seq 1 100 ); do ln -s post-early-return.test.py xyz$n.test.py; done

Then cd to the TS tests subdirectory, and run the test multiple times using the aliases:

./autest.sh --ats-bin ~/TSX/TS4/bin -f $( for n in $( seq 1 80 ) ; do echo xyz$n ; done )

[ywkaras]

I will retest, and close if the failures are no longer present.

[ywkaras]

In my environment, this test seems to be working worse now than before. But seems to work OK in open source CI Au test regression run.