Strange 'hanging' request in specific HTTP/2 request sequence

[aukevanleeuwen]

Brief summary

K6 'hangs' on specific sequence of requests. I cannot reproduce this behaviour with (for example) curl or the native golang http client.

k6 version

v0.52.0, but tested as far back as v0.40.0

OS

macOS 14.5

Docker version and image (if applicable)

No response

Steps to reproduce the problem

I have a strange issue with K6. In one of my load test scenarios, k6 was hanging on a POST request. Running the test with different configurations of VUs I've narrowed it down to a specific sequence of requests.

1. GET https://example.com/some/path
2. GET https://example.com/some/path
3. POST https://example.com/some/path with request body of 16K random string
4. GET https://example.com/some/path
5. GET https://example.com/some/path
6. POST https://example.com/some/path with request body of 16K random string (this request hangs)

This is quite hard for me to debug (and describe in this issue), so bear with me. I've tried to go through a bunch of things trying to pin it down to something specific.

These requests fail on an API that is behind Akamai (with HTTP/2 behaviour configured). Some observations:

• Interestingly enough, if I would send just the GET requests, or just the POST requests, it all runs fine. So it's only the alternation of GETs and POSTs that triggers this issue. Weirder still. If I would half the request body size of the POST, the amount of iterations (2 GETs and 1 POST) doubles.
• If I skip Akamai and run these same requests directly against the (HTTP/2) origin (Spring Boot application behind AWS NLB), everything works.
  • Seems to indicate that it's a problem on the Akamai side
• I've tried to reproduce this with a series of curl requests using --next to make sure that we have connection reuse and trying to get as close as possible to whatever K6 is doing. It just works.
  • Seems to indicate a K6 problem (?)
• I've tried to reproduce with a small one-of golang CLI program using the native go lang HTTP client that is used by K6 under the hood, and I cannot reproduce. Disclaimer: my golang knowledge is quite limited, so maybe this is not close enough to whatever K6 is doing though.

In all of this testing, looking at logs from GODEBUG=http2debug=2 and breaking inside the k6 and http client source code I've narrowed it down to this:

While sending the POST data it enters this loop:

k6/vendor/golang.org/x/net/http2/transport.go

Lines 1841 to 1860 in 011a6b4

	for len(remain) > 0 && err == nil {
	var allowed int32
	allowed, err = cs.awaitFlowControl(len(remain))
	if err != nil {
	return err
	}
	cc.wmu.Lock()
	data := remain[:allowed]
	remain = remain[allowed:]
	sentEnd = sawEOF && len(remain) == 0 && !hasTrailers
	err = cc.fr.WriteData(cs.ID, sentEnd, data)
	if err == nil {
	// TODO(bradfitz): this flush is for latency, not bandwidth.
	// Most requests won't need this. Make this opt-in or
	// opt-out? Use some heuristic on the body type? Nagel-like
	// timers? Based on 'n'? Only last chunk of this for loop,
	// unless flow control tokens are low? For now, always.
	// If we change this, see comment below.
	err = cc.bw.Flush()
	}

The first time around this is going fine because, the allowed length to send in this frame is 16384, which is the entire buffer, remaining is [] and it will send the frame with flags=END_STREAM. All good. The second POST request however will enter that same loop, but for some reason that is beyond my understanding, cs.awaitFlowControl(len(remain)) will return 16383, so one byte less. This frame is created (without the END_STREAM flag obviously) and sent, it will enter the next iteration of the loop because there is still one byte to send and hit cs.awaitFlowControl(len(remain)) again. However inside that method on this line:

k6/vendor/golang.org/x/net/http2/transport.go

Line 1934 in 011a6b4

if a := cs.flow.available(); a > 0 {

cs.flow.available() will return 0 and therefore will block on the cc.cond.Wait() mutex (

k6/vendor/golang.org/x/net/http2/transport.go

Line 1946 in 011a6b4

cc.cond.Wait()

). It will not get out of this state, unless the timeout on the server is hit and some error is thrown then.

I wish I could explain this simpler to be honest, but I don't really. Following are the logs from both k6 and my own small CLI tool ran with GODEBUG=http2debug=2. Maybe it will help.

# without debug (to show what is *my* logging, vs debug logging)
❯ ./akamai-http2-test
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 200 [95ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 200 [27ms]
POST https://polly.edge.example.com/sized-response?dataSize=5B (request size: 16384)... 200 [72ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 200 [26ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 200 [52ms]
POST https://polly.edge.example.com/sized-response?dataSize=5B (request size: 16384)... 200 [69ms]

# with debug
❯ GODEBUG=http2debug=2 ./akamai-http2-test
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 2024/07/03 17:57:59 http2: Transport failed to get client conn for polly.edge.example.com:443: http2: no cached connection was available
2024/07/03 17:57:59 http2: Transport creating client conn 0x140000f4000 to [2a02:26f0:c900:6::174c:cc37]:443
2024/07/03 17:57:59 http2: Framer 0x140000e4540: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2024/07/03 17:57:59 http2: Framer 0x140000e4540: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2024/07/03 17:57:59 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:57:59 http2: Transport encoding header ":method" = "GET"
2024/07/03 17:57:59 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:57:59 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:57:59 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:57:59 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:57:59 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:57:59 http2: Framer 0x140000e4540: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=96
2024/07/03 17:57:59 http2: Framer 0x140000e4540: read SETTINGS len=30, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=32768
2024/07/03 17:57:59 http2: Transport received SETTINGS len=30, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=32768
2024/07/03 17:57:59 http2: Framer 0x140000e4540: wrote SETTINGS flags=ACK len=0
2024/07/03 17:57:59 http2: Framer 0x140000e4540: read SETTINGS flags=ACK len=0
2024/07/03 17:57:59 http2: Transport received SETTINGS flags=ACK len=0
2024/07/03 17:57:59 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=1 len=286
2024/07/03 17:57:59 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022279.73f7ba7" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:57:59 GMT" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:57:59 GMT" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "alt-svc" = "h3=\":443\"; ma=93600" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022279.73f77c3" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:57:59 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:57:59 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=286
2024/07/03 17:57:59 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=1 len=5 data="[ - ]"
2024/07/03 17:57:59 http2: Transport received DATA flags=END_STREAM stream=1 len=5 data="[ - ]"
200 [683ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 2024/07/03 17:57:59 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:57:59 http2: Transport encoding header ":method" = "GET"
2024/07/03 17:57:59 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:57:59 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:57:59 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:57:59 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:57:59 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:57:59 http2: Framer 0x140000e4540: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=10
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=3 len=260
2024/07/03 17:58:00 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022279.73f7c21" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022279.73f7c42" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:58:00 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=260
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=3 len=5 data="[ - ]"
2024/07/03 17:58:00 http2: Transport received DATA flags=END_STREAM stream=3 len=5 data="[ - ]"
200 [29ms]
POST https://polly.edge.example.com/sized-response?dataSize=5B (request size: 16384)... 2024/07/03 17:58:00 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:58:00 http2: Transport encoding header ":method" = "POST"
2024/07/03 17:58:00 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:58:00 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:58:00 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:58:00 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:58:00 http2: Transport encoding header "content-length" = "16384"
2024/07/03 17:58:00 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote HEADERS flags=END_HEADERS stream=5 len=13
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote DATA flags=END_STREAM stream=5 len=16384 data="6OtMhDRlt35Xgvu4PzgqNR0O0FT0RNldt2mL1AEdqVu3pT2zPSV1cMBNhOjyRVdMviiOwC1sQ7HWaLpSRPjU9GT4VWwU0VKUImOA9mKrI3gKKpJV9ojmzb5kxJ4gDp4gctLEKhVqR4qnp73Ub9foTXD8aHV4a1w31gV59SPjkbdW0FTIUHyPmB1EhdVhoIdm1DlK72joABtkw8ghpX713vV3ArjhrJugfazKYfa85EFEUidcE5PxD4xvICRhKNth" (16128 bytes omitted)
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=5 len=260
2024/07/03 17:58:00 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7bed" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7c79" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:58:00 http2: Transport received HEADERS flags=END_HEADERS stream=5 len=260
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=5 len=5 data="[ - ]"
2024/07/03 17:58:00 http2: Transport received DATA flags=END_STREAM stream=5 len=5 data="[ - ]"
200 [78ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 2024/07/03 17:58:00 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:58:00 http2: Transport encoding header ":method" = "GET"
2024/07/03 17:58:00 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:58:00 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:58:00 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:58:00 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:58:00 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote HEADERS flags=END_STREAM|END_HEADERS stream=7 len=7
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=7 len=260
2024/07/03 17:58:00 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7c6c" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7d04" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:58:00 http2: Transport received HEADERS flags=END_HEADERS stream=7 len=260
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=7 len=5 data="[ - ]"
2024/07/03 17:58:00 http2: Transport received DATA flags=END_STREAM stream=7 len=5 data="[ - ]"
200 [33ms]
GET  https://polly.edge.example.com/sized-response?dataSize=5B... 2024/07/03 17:58:00 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:58:00 http2: Transport encoding header ":method" = "GET"
2024/07/03 17:58:00 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:58:00 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:58:00 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:58:00 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:58:00 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote HEADERS flags=END_STREAM|END_HEADERS stream=9 len=7
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=9 len=260
2024/07/03 17:58:00 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7c9e" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7d5b" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:58:00 http2: Transport received HEADERS flags=END_HEADERS stream=9 len=260
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=9 len=5 data="[ - ]"
2024/07/03 17:58:00 http2: Transport received DATA flags=END_STREAM stream=9 len=5 data="[ - ]"
200 [53ms]
POST https://polly.edge.example.com/sized-response?dataSize=5B (request size: 16384)... 2024/07/03 17:58:00 http2: Transport encoding header ":authority" = "polly.edge.example.com"
2024/07/03 17:58:00 http2: Transport encoding header ":method" = "POST"
2024/07/03 17:58:00 http2: Transport encoding header ":path" = "/sized-response?dataSize=5B"
2024/07/03 17:58:00 http2: Transport encoding header ":scheme" = "https"
2024/07/03 17:58:00 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
2024/07/03 17:58:00 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
2024/07/03 17:58:00 http2: Transport encoding header "content-length" = "16384"
2024/07/03 17:58:00 http2: Transport encoding header "accept-encoding" = "gzip"
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote HEADERS flags=END_HEADERS stream=11 len=8
2024/07/03 17:58:00 http2: Framer 0x140000e4540: wrote DATA flags=END_STREAM stream=11 len=16384 data="JzXzMwMFL49kLULLyGphOWdn8WhSjZBRp63tt1IhW9XQ4Wqn7khZdDJiBCCz9x8rPZUX2X4SQgBLf3prrn9cdhewMerfRNEEl4mtGuxWXqH0ThGc6HKbTsEFgj2xAUL0yJVnMm1EOeVbEdnRIPevXaD672nHiQiaIdtnBHl3fhkD294VKKeoGW20CozHuKG3cfNXF86y47yqDl4LDrtcUpvev5bzQArXXiQYgt2WhLWFCeuenql42R0uk6U5GgCV" (16128 bytes omitted)
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read WINDOW_UPDATE len=4 (conn) incr=98303
2024/07/03 17:58:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=98303
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read HEADERS flags=END_HEADERS stream=11 len=260
2024/07/03 17:58:00 http2: decoded hpack field header field ":status" = "200" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7d4b" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 15:58:00 GMT" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "content-length" = "5" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-akamai-reference-id" = "0.37477b5c.1720022280.73f7dd2" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
2024/07/03 17:58:00 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
2024/07/03 17:58:00 http2: Transport received HEADERS flags=END_HEADERS stream=11 len=260
2024/07/03 17:58:00 http2: Framer 0x140000e4540: read DATA flags=END_STREAM stream=11 len=5 data="[ - ]"
2024/07/03 17:58:00 http2: Transport received DATA flags=END_STREAM stream=11 len=5 data="[ - ]"
200 [67ms]

This is the K6 output that is hanging.

❯ GODEBUG=http2debug=2 k6 run src/k6/load-test.js --env scenario=post_it

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

INFO[0000] 2024/07/03 16:56:19 http2: Transport failed to get client conn for jslib.k6.io:443: http2: no cached connection was available

<SNAP removed some stuff related to getting libraries from jslib.k6.io>

     execution: local
        script: src/k6/load-test.js
        output: -

     scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
              * post_it: 200 iterations for each of 1 VUs (maxDuration: 10m0s, exec: buggyPostBehaviour, gracefulStop: 30s)

INFO[0001] Using testId     : post_it-2024-07-03T14:56:19.739Z  source=console
INFO[0001] Akamai bypass    : false                      source=console
INFO[0001] EdgeWorker bypass: true                       source=console
INFO[0001] [0] Executing GET: 0                          source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport failed to get client conn for polly.edge.example.com:443: http2: no cached connection was available
INFO[0001] 2024/07/03 16:56:19 http2: Transport creating client conn 0x14001c3db00 to 2.16.6.91:443
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "GET"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "bcb3f2b5-1fc1-4447-beb8-863d06746a7e"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=198
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read SETTINGS len=30, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=32768
INFO[0001] 2024/07/03 16:56:19 http2: Transport received SETTINGS len=30, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=32768
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote SETTINGS flags=ACK len=0
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read SETTINGS flags=ACK len=0
INFO[0001] 2024/07/03 16:56:19 http2: Transport received SETTINGS flags=ACK len=0
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=1 len=242
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "alt-svc" = "h3=\":443\"; ma=93600" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018579.27df8d82" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=242
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=1 len=5 data="[ - ]"
INFO[0001] 2024/07/03 16:56:19 http2: Transport received DATA flags=END_STREAM stream=1 len=5 data="[ - ]"
INFO[0001] [0] Executing GET: 1                          source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "GET"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "cda4a585-8be9-4aed-a1d9-87fb1309890a"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=40
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=3 len=218
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018579.27df8ddd" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=218
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=3 len=5 data="[ - ]"
INFO[0001] 2024/07/03 16:56:19 http2: Transport received DATA flags=END_STREAM stream=3 len=5 data="[ - ]"
INFO[0001] [0] Executing POST                            source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "POST"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-type" = "text/plain"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "04bfb3c9-6753-4c48-b728-f7eaf82bb86f"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-length" = "16384"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=5 len=54
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote DATA flags=END_STREAM stream=5 len=16384 data="phsjwraryqnzegjjplyoabxhozlvvbvumqkaihbvdlzpjuiukmwffyfhnfgipmucvidapejpvjneynhowtywpqzkkdgsnmopescmsmuesannoaatxpoemuzuxzrzygmlfhjotplhshmmziojpoapxeokxndvpkpliqbandztyirwasopgvlpiosclxdzvbcmuhryptmxakrnznpnburntqdrgnacyakgrchtfwjeazhtwbmkgdebojwjfgzuhlcy" (16128 bytes omitted)
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=5 len=218
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018579.27df8df5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: Transport received HEADERS flags=END_HEADERS stream=5 len=218
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=5 len=5 data="[ - ]"
INFO[0001] 2024/07/03 16:56:19 http2: Transport received DATA flags=END_STREAM stream=5 len=5 data="[ - ]"
INFO[0001] [1] Executing GET: 0                          source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "GET"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-type" = "text/plain"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "3d71be4c-2820-419f-a9f9-476482530318"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-length" = "16384"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=7 len=40
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote DATA flags=END_STREAM stream=7 len=16384 data="phsjwraryqnzegjjplyoabxhozlvvbvumqkaihbvdlzpjuiukmwffyfhnfgipmucvidapejpvjneynhowtywpqzkkdgsnmopescmsmuesannoaatxpoemuzuxzrzygmlfhjotplhshmmziojpoapxeokxndvpkpliqbandztyirwasopgvlpiosclxdzvbcmuhryptmxakrnznpnburntqdrgnacyakgrchtfwjeazhtwbmkgdebojwjfgzuhlcy" (16128 bytes omitted)
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=7 len=218
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018579.27df8e6e" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: Transport received HEADERS flags=END_HEADERS stream=7 len=218
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=7 len=5 data="[ - ]"
INFO[0001] 2024/07/03 16:56:19 http2: Transport received DATA flags=END_STREAM stream=7 len=5 data="[ - ]"
INFO[0001] [1] Executing GET: 1                          source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "GET"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-type" = "text/plain"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "e3e8e98a-8511-4a68-9dc8-4707cb656395"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-length" = "16384"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=9 len=39
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote DATA flags=END_STREAM stream=9 len=16384 data="phsjwraryqnzegjjplyoabxhozlvvbvumqkaihbvdlzpjuiukmwffyfhnfgipmucvidapejpvjneynhowtywpqzkkdgsnmopescmsmuesannoaatxpoemuzuxzrzygmlfhjotplhshmmziojpoapxeokxndvpkpliqbandztyirwasopgvlpiosclxdzvbcmuhryptmxakrnznpnburntqdrgnacyakgrchtfwjeazhtwbmkgdebojwjfgzuhlcy" (16128 bytes omitted)
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=9 len=218
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:56:19 GMT" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018579.27df8e96" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0001] 2024/07/03 16:56:19 http2: Transport received HEADERS flags=END_HEADERS stream=9 len=218
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=9 len=5 data="[ - ]"
INFO[0001] 2024/07/03 16:56:19 http2: Transport received DATA flags=END_STREAM stream=9 len=5 data="[ - ]"
INFO[0001] [1] Executing POST                            source=console
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":method" = "POST"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header ":scheme" = "https"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-type" = "text/plain"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-request-id" = "cb86be16-9aed-4d07-b254-d013fe90a6b0"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-length" = "16384"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=11 len=39
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote DATA stream=11 len=16383 data="phsjwraryqnzegjjplyoabxhozlvvbvumqkaihbvdlzpjuiukmwffyfhnfgipmucvidapejpvjneynhowtywpqzkkdgsnmopescmsmuesannoaatxpoemuzuxzrzygmlfhjotplhshmmziojpoapxeokxndvpkpliqbandztyirwasopgvlpiosclxdzvbcmuhryptmxakrnznpnburntqdrgnacyakgrchtfwjeazhtwbmkgdebojwjfgzuhlcy" (16127 bytes omitted)
INFO[0062] 2024/07/03 16:57:20 RoundTrip failure: context deadline exceeded
INFO[0062] 2024/07/03 16:57:20 http2: Framer 0x140037f5500: wrote RST_STREAM stream=11 len=4 ErrCode=CANCEL
WARN[0062] Request Failed                                error="Post \"https://polly.edge.example.com/sized-response?ts=202406031656&dataSize=5B\": request timeout"
INFO[0062] [2] Executing GET: 0                          source=console
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header ":method" = "GET"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header ":scheme" = "https"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "content-type" = "text/plain"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "x-request-id" = "2b92785d-48db-4693-ad23-61ca896d3928"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0062] 2024/07/03 16:57:20 http2: Transport encoding header "content-length" = "16384"
INFO[0062] 2024/07/03 16:57:20 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=13 len=39
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=13 len=218
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:57:21 GMT" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:57:21 GMT" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018640.27e17f16" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: Transport received HEADERS flags=END_HEADERS stream=13 len=218
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=13 len=5 data="[ - ]"
INFO[0062] 2024/07/03 16:57:21 http2: Transport received DATA flags=END_STREAM stream=13 len=5 data="[ - ]"
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: wrote RST_STREAM stream=13 len=4 ErrCode=NO_ERROR
INFO[0062] [2] Executing GET: 1                          source=console
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":method" = "GET"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":scheme" = "https"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-request-id" = "d2b0249e-ef85-47b2-ab9f-36215c65fa82"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "content-type" = "text/plain"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "content-length" = "16384"
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=15 len=39
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: read HEADERS flags=END_HEADERS stream=15 len=218
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field ":status" = "200" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "content-type" = "application/octet-stream" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "content-length" = "5" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "expires" = "Wed, 03 Jul 2024 14:57:21 GMT" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "cache-control" = "max-age=0, no-cache, no-store" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "pragma" = "no-cache" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:57:21 GMT" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "x-akamai-reference-id" = "0.9b071002.1720018641.27e17f44" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "x-content-type-options" = "nosniff" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000 ; includeSubDomains ; preload" (sensitive)
INFO[0062] 2024/07/03 16:57:21 http2: Transport received HEADERS flags=END_HEADERS stream=15 len=218
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: read DATA flags=END_STREAM stream=15 len=5 data="[ - ]"
INFO[0062] 2024/07/03 16:57:21 http2: Transport received DATA flags=END_STREAM stream=15 len=5 data="[ - ]"
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: wrote RST_STREAM stream=15 len=4 ErrCode=NO_ERROR
INFO[0062] [2] Executing POST                            source=console
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":authority" = "polly.edge.example.com"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":method" = "POST"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":path" = "/sized-response?ts=202406031656&dataSize=5B"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header ":scheme" = "https"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-api-key" = "*** MASKED ***"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "content-type" = "text/plain"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-test-id" = "post_it-2024-07-03T14:56:19.739Z"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-request-id" = "43e1c1d0-8c7d-4377-8147-05176e73e8a1"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "x-ew-bypass" = "true"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "user-agent" = "k6/0.51.0 (https://k6.io/)"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "accept-encoding" = "gzip, deflate"
INFO[0062] 2024/07/03 16:57:21 http2: Transport encoding header "content-length" = "16384"
INFO[0062] 2024/07/03 16:57:21 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=17 len=39
INFO[0090] 2024/07/03 16:57:49 http2: Transport closing idle conn 0x14001fca480 (forSingleUse=false, maxStream=5)
INFO[0090] 2024/07/03 16:57:49 http2: Transport readFrame error on conn 0x14001fca480: (*net.OpError) read tcp 10.10.2.91:55973->18.238.243.126:443: use of closed network connection
INFO[0105] 2024/07/03 16:58:04 RoundTrip failure: context canceled
INFO[0105] 2024/07/03 16:58:04 http2: Framer 0x140037f5500: wrote RST_STREAM stream=17 len=4 ErrCode=CANCEL
INFO[0105] 2024/07/03 16:58:04 http2: Transport failed to get client conn for reports.k6.io:443: http2: no cached connection was available

     ✗ response code was 200
      ↳  87% — ✓ 7 / ✗ 1

     █ setup

     checks.........................: 87.50% ✓ 7        ✗ 1
     data_received..................: 7.9 kB 75 B/s
     data_sent......................: 67 kB  642 B/s
     http_req_blocked...............: avg=7.79ms   min=0s    med=500ns    max=62.35ms p(90)=18.7ms  p(95)=40.53ms
     http_req_connecting............: avg=667µs    min=0s    med=0s       max=5.33ms  p(90)=1.6ms   p(95)=3.46ms
   ✓ http_req_duration..............: avg=20.56ms  min=0s    med=21.53ms  max=52.44ms p(90)=45.25ms p(95)=48.85ms
       { expected_response:true }...: avg=23.5ms   min=229µs med=23.79ms  max=52.44ms p(90)=46.28ms p(95)=49.36ms
   ✗ http_req_failed................: 12.50% ✓ 1        ✗ 7
     http_req_receiving.............: avg=106.62µs min=0s    med=77.5µs   max=231µs   p(90)=229.6µs p(95)=230.3µs
     http_req_sending...............: avg=325.87µs min=0s    med=280µs    max=1.29ms  p(90)=657.5µs p(95)=974.24µs
     http_req_tls_handshaking.......: avg=1.84ms   min=0s    med=0s       max=14.75ms p(90)=4.42ms  p(95)=9.58ms
     http_req_waiting...............: avg=20.13ms  min=0s    med=21.15ms  max=51.06ms p(90)=44.54ms p(95)=47.8ms
     http_reqs......................: 8      0.076429/s
     iteration_duration.............: avg=20.41s   min=92µs  med=178.84ms max=1m1s    p(90)=48.88s  p(95)=54.96s
     iterations.....................: 2      0.019107/s
     vus............................: 1      min=1      max=1
     vus_max........................: 1      min=1      max=1


running (01m44.7s), 0/1 VUs, 2 complete and 1 interrupted iterations
post_it ✗ [--------------------------------------] 1 VUs  01m44.6s/10m0s  002/200 iters, 200 per VU
INFO[0106] 2024/07/03 16:58:04 http2: Transport creating client conn 0x14001fca480 to 3.128.116.196:443
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
INFO[0106] 2024/07/03 16:58:04 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header ":authority" = "reports.k6.io"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header ":method" = "POST"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header ":path" = "/"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header ":scheme" = "https"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header "content-type" = "application/json"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header "content-length" = "224"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header "accept-encoding" = "gzip"
INFO[0106] 2024/07/03 16:58:04 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: wrote HEADERS flags=END_HEADERS stream=1 len=52
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: wrote DATA flags=END_STREAM stream=1 len=224 data="{\"k6_version\":\"0.51.0\",\"executors\":{\"per-vu-iterations\":1},\"vus_max\":1,\"iterations\":2,\"duration\":\"1m44.671727s\",\"goos\":\"darwin\",\"goarch\":\"arm64\",\"modules\":[\"k6/crypto\",\"k6\",\"k6/timers\",\"k6/http\",\"k6/execution\"],\"outputs\":[]}"
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: wrote SETTINGS flags=ACK len=0
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: read WINDOW_UPDATE len=4 (conn) incr=2147418112
INFO[0106] 2024/07/03 16:58:04 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: read SETTINGS flags=ACK len=0
INFO[0106] 2024/07/03 16:58:04 http2: Transport received SETTINGS flags=ACK len=0
INFO[0106] 2024/07/03 16:58:04 http2: Framer 0x14002ef28c0: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=62
INFO[0106] 2024/07/03 16:58:04 http2: decoded hpack field header field ":status" = "200"
INFO[0106] 2024/07/03 16:58:04 http2: decoded hpack field header field "date" = "Wed, 03 Jul 2024 14:58:04 GMT"
INFO[0106] 2024/07/03 16:58:04 http2: decoded hpack field header field "content-type" = "text/html; charset=utf-8"
INFO[0106] 2024/07/03 16:58:04 http2: decoded hpack field header field "content-length" = "0"
INFO[0106] 2024/07/03 16:58:04 http2: decoded hpack field header field "server" = "gunicorn"
INFO[0106] 2024/07/03 16:58:04 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS stream=1 len=62
ERRO[0106] test run was aborted because k6 received a 'interrupt' signal

So the strange behaviour is here (snippet from above):

INFO[0001] 2024/07/03 16:56:19 http2: Transport encoding header "content-length" = "16384"
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote HEADERS flags=END_HEADERS stream=11 len=39
INFO[0001] 2024/07/03 16:56:19 http2: Framer 0x140037f5500: wrote DATA stream=11 len=16383 data="phsjwraryqnzegjjplyoabxhozlvvbvumqkaihbvdlzpjuiukmwffyfhnfgipmucvidapejpvjneynhowtywpqzkkdgsnmopescmsmuesannoaatxpoemuzuxzrzygmlfhjotplhshmmziojpoapxeokxndvpkpliqbandztyirwasopgvlpiosclxdzvbcmuhryptmxakrnznpnburntqdrgnacyakgrchtfwjeazhtwbmkgdebojwjfgzuhlcy" (16127 bytes omitted)
INFO[0062] 2024/07/03 16:57:20 RoundTrip failure: context deadline exceeded
INFO[0062] 2024/07/03 16:57:20 http2: Framer 0x140037f5500: wrote RST_STREAM stream=11 len=4 ErrCode=CANCEL
WARN[0062] Request Failed                                error="Post \"https://polly.edge.example.com/sized-response?ts=202406031656&dataSize=5B\": request timeout"

The content length and the length of the data frame don't match up. The fact that this is in fact 16383 rather than 16384 is already strange, but stranger still is the fact that it doesn't send yet another data frame with the last byte afterwards.

Notice that the failed request is roughly halfway, afterwards it will issue yet another 2 (successful) GET requests, but fail on the POST again 🤷 .

Expected behaviour

For k6 not to hang on these requests.

Actual behaviour

k6 hangs.

[aukevanleeuwen]

@joanlopez / @mstoykov , since I happened to see you active on the other issue... I realise this issue is quite involved, but maybe you can at least answer the following quick question: I'm trying to force HTTP/1.1 because of this issue. On the CLI locally I can do that with:

k6 run src/k6/load-test.js --env scenario=post_it --env GODEBUG=http2client=0

because it will hit this code:

k6/js/runner.go

Lines 255 to 271 in 011a6b4

	func (r *Runner) forceHTTP1() bool {
	if r.preInitState.LookupEnv == nil {
	return false
	}
	godebug, _ := r.preInitState.LookupEnv("GODEBUG")
	if godebug == "" {
	return false
	}
	variables := strings.SplitAfter(godebug, ",")
	for _, v := range variables {
	if strings.Trim(v, ",") == "http2client=0" {
	return true
	}
	}
	return false
	}

But it doesn't seem to work if I run this code with k6 cloud .... Can I force HTTP/1.1 when running tests on K6 Cloud?

Thanks in advance. Obviously I hope you are intrigued by this issue as well 😀

[aukevanleeuwen]

(I've updated the issue by referencing the vendored code inside this repository, since I just realised I was referencing the Golang HTTP client code directly instead. This makes it more clear.)

[mstoykov]

Hi @aukevanleeuwen , thank you a lot for the awesome issue report 🙇

Reading the issue my instinct is that this is a Golang std lib thing that Cloudflare started to exhibit likely to some recent change. I would expect otherwise we would've gotten more reports or more people would have hit it somehow. k6 doesn't really do anything specific to the http stream, so it will be quite interesting if some option we set, not set hits this.

There are number of issues that seem relevant on the golang issue tracker but are not 100% a hit, but can you:

1. try to set the user agent to curl (for example)
2. give us the program in go that you tried
3. Given how you have reported the issue I expect it is not possible to get a reproducible k6 script that we can run?

I'm trying to force HTTP/1.1 because of this issue. On the CLI locally I can do that with

Unfortunately the GODEBUG hack isn't supported in the cloud - unfortunately only an issue about documenting this exist. Please contact cloud support to see if we can figure out something else through the channel.

[mstoykov]

Also if we can get the script that sends the requests even with the url and authentication obscured, that might point out to something.

[aukevanleeuwen]

Reading the issue my instinct is that this is a Golang std lib thing that Cloudflare started to exhibit likely to some recent change.

Just double checking, but I think you mean Akamai here right?

Given how you have reported the issue I expect it is not possible to get a reproducible k6 script that we can run?

Sorry took some time to discuss this internally a bit. I think we can give you something that you can work with, but not publicly obviously. How can we get this to you privately? I need to strip some things in the script to just get to the core of it in the meantime.

[mstoykov]

Just double checking, but I think you mean Akamai here right?

Well I did mean Cloudflare ... because I apparently I just read "one" cdn and then swapped it for the other 😓 I guess cloudflare have better marketing for me 😅 .

This doesn't really change anything though - there are just as many strange issues around akamai as cloudflare. And just as many old cases where it ended up being "akamai has identified this as a bug and will be rolling out a fix".

Sorry took some time to discuss this internally a bit.

No problem - I don't expect we will be able to fix this very fast to begin with, and we are on low capacity due to the vacation season. So I am sorry, but we likely won't be able to look into this super fast :(

I think we can give you something that you can work with, but not publicly obviously

I would prefer that you reach through the support as that seems like the most official way and will let us have access internally even if I go out on vacation.

I need to strip some things in the script to just get to the core of it in the meantime.

Thank you 🙇

It will still be nice if we can have a public version if anybody else hits this or has ideas. The public version obviously should have no data, but might still point to a potential problem

[mstoykov]

@aukevanleeuwen you also might want to try to see if you can get the real traffic that goes in and out through tcpdump/wireshark and SSLKEYLOGGER , please see grafana/k6-docs#754 and the linked issues and article for more details.

It is particularly interesting what is beind send and received in that last call. Is the request being flushed at all, is the response received but not read

[aukevanleeuwen]

Thanks @mstoykov, we were just looking into this. I haven't had time to work any further on it as I was in client meetings.

[aukevanleeuwen]

Okay.. I figured it out with some Wiresharking¹. What I was accidentally doing was creating requests based on a request arguments object (basically this: https://github.com/DefinitelyTyped/DefinitelyTyped/blob/9378dc4325a341e0b0143a072ec53dda5d0a9849/types/k6/http.d.ts#L354-L366) that was accidentally carrying over the body of the previous post request 😱 . So roughly doing

Object.assign(options1, options2);

rather than

Object.assign({}, options1, options2);

Apparently Akamai doesn't like HTTP/2 GET requests with a body and reacts strangely when it does happen. I don't know very much about HTTP/2 flow control, but for some reason this seems to deplete the connection window size, without ever getting into a correct state again. I'm not entirely sure there is also something on the Golang HTTP client that should recover, because essentially any POST afterwards will fail, which is kind of strange to me.

Either way, fixing my code to not send GET requests with a body fixes the issue. I could reproduce this behaviour with my one-off Golang CLI program using just the native HTTP client, so definitely not a K6 issue.

Thanks for your help though!

¹ The fact that SSLKEYLOGFILE=/tmp/sslkey.log k6 run src/k6/load-test.js --env scenario=buggy_behaviour works is awesome.

[mstoykov]

Great job figuring out!

Glad it turned out we don't need to debug the sdlib http2 code 😅 .

Have you tried this with another server? I guess when you said:

If I skip Akamai and run these same requests directly against the (HTTP/2) origin (Spring Boot application behind AWS NLB), everything works.

Means that this works if not for Akamai even with your reproduction program?

if so it migth be worth reporting it to Akamai. Otherwise it migth be worth reporting it to golang.

[aukevanleeuwen]

I've tried it against the origin directly indeed, and also against https://nghttp2.org/httpbin/, both of which seemed to be fine with this behaviour.