Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Experimental IETF-standard HTTP/3 support #2727

Merged
merged 8 commits into from Sep 10, 2019

Conversation

@mholt
Copy link
Member

commented Aug 26, 2019

1. What does this change do, exactly?

Adds IETF HTTP/3 functionality to Caddy.

2. Please link to the relevant issues.

Closes #2450

3. Which documentation changes (if any) need to be made because of this PR?

Add HTTP/3 to our ad-hoc docs for Caddy 2.

4. Checklist

  • I have written tests and verified that they fail without my change
  • I have squashed any insignificant commits
  • This change has comments explaining package types, values, functions, and non-obvious lines of code
  • I am willing to help maintain this change if there are issues with it later
@mholt mholt added this to the 2.0 milestone Aug 26, 2019
@mholt mholt referenced this pull request Aug 26, 2019
@mholt mholt added the v2 label Aug 26, 2019
Also use latest quic-go for ALPN fix
@mholt

This comment has been minimized.

Copy link
Member Author

commented Aug 31, 2019

@marten-seemann This is almost working all the way. Last thing to do is figure out how to handle config reloads gracefully. I need a couple things for that to happen:

  1. CloseGracefully() to be implemented (this doesn't have to happen immediately; see lucas-clemente/quic-go#2103).
  2. When http3.Server.Close() (or http3.Server.CloseGracefully()) is called, I need that to call Close() on the underlying PacketConn that I pass into http3.Server.Serve(). I've also explained this in lucas-clemente/quic-go#2103. Without calling Close(), Caddy has no way to do its bookkeeping and thus leaks resources and requests hang.

There is one more problem, too, which I'm hoping you'll have insights on. It only arises when QUIC_GO_LOG_LEVEL=debug is NOT set. In other words, when QUIC_GO_LOG_LEVEL=.

Can you replicate the error?

First, I did use a replace in my local go.mod to use a modified copy of your lib that calls Close() like I mentioned in the other issue:

replace github.com/lucas-clemente/quic-go => ../../lucas-clemente/quic-go

Then I used this Caddy config in a file called caddy.json (be sure to specify your own certificate and key, in this case I'm not using automatic HTTPS):

{
	"apps": {
		"tls": {
			"certificates": {
				"load_files": [
					{"certificate": "cert.pem", "key": "key.pem"}
				]
			}
		},
		"http": {
			"http_port": 2080,
			"https_port": 2443,
			"servers": {
				"myserver": {
					"listen": [":2443"],
					"routes": [
						{
							"handle": [
								{
									"handler": "static_response",
									"body": "Hello world!"
								}
							]
						}
					],
					"tls_connection_policies": [
						{}
					]
				}
			}
		}
	}
}

Then from this branch I run Caddy 2:

$ GO111MODULE=on go run main.go run -config caddy.json

Then in another terminal I run the HTTP/3 client:

$ GO111MODULE=on go run main.go -insecure https://your-domain:2443

It should reply with "Hello, world!"

But then change the config slightly, for example change the body to "Goodbye, cruel world!" and then reload it in a separate terminal with:

$ curl -X POST -d @caddy.json -H "Content-Type: application/json" "http://localhost:2019/load"

(don't stop the running Caddy process, make sure this reload happens while it's still running)

Then try the client again. It should hang and panic:

NO_ERROR: Handshake did not complete in time

Now, stop Caddy and run it again but set QUIC_GO_LOG_LEVEL=debug on the server. Repeat the process (do a request, see that it works, then change the config and POST it, then do another request) and you should see that... it still works!

In other words, I can only replicate the hanging if QUIC_GO_LOG_LEVEL=debug is NOT set, making it difficult to debug.

Unfortunately, the only way I can get this PR finished and merged, is if we can gracefully apply new configuration. So any help would be appreciated! :)

@marten-seemann

This comment has been minimized.

Copy link
Contributor

commented Sep 2, 2019

Hi @mholt, I just tried to reproduce this, but I'm failing at the very first step.
I have the http3 branch checked out, and I added the replace line to go.mod. I'm in the cmd/caddy/ directory and I'm running main.go using the caddy.json you provided, with a self-signed cert.

The output is

❯ QUIC_GO_LOG_LEVEL=debug go run main.go run -config caddy.json
2019/09/02 18:04:35 Caddy 2 admin endpoint listening on localhost:2019
2019/09/02 18:04:35 [INFO][cache:0xc0000e6870] Started certificate maintenance routine
2019/09/02 18:04:35 [WARNING] Stapling OCSP: no OCSP stapling for [localhost]: no OCSP server specified in certificate
2019/09/02 18:04:35 Caddy 2 serving initial configuration

Caddy is listening on localhost TCP 2443, but apparently not on the corresponding UDP port. Is there anything else I need to do to enable QUIC?

@mholt

This comment has been minimized.

Copy link
Member Author

commented Sep 2, 2019

@marten-seemann Thanks for taking a look! I'm not sure what happened, but somehow this part of the config got left out of my paste:

"tls_connection_policies": [ {} ]

This enables the default HTTPS configuration for that server. I've updated my post to include the proper config which I have tested will enable the HTTP/3 listener. Sorry for the mishap! Let me know how that works.

@marten-seemann

This comment has been minimized.

Copy link
Contributor

commented Sep 3, 2019

Hi @mholt, I finally had the time to dig into this.

The problem seems to be the fakeClosePacketConn. In quic-go, when you call Listen with a new packet conn, we check if we already know this packet conn: https://github.com/lucas-clemente/quic-go/blob/d689f9a39233d265f917f9819ad2d6ca20951c89/multiplexer.go#L52-L69.
If not, we start a new listener on this packet conn.

Apparently, after applying the new config, you're passing a new fakeClosePacketConn to quic-go, so we end in the situation that two go routines are calling Read on the same underlying UDP connection. Can you make sure to pass the same struct to quic-go every time?

@marten-seemann

This comment has been minimized.

Copy link
Contributor

commented Sep 3, 2019

Looks like this is not Caddy's fault after all. The problem seems to be that we're not correctly recognizing the same packet conn being passed to quic-go.
I just added a (failing) test case to demonstrate the problem: https://github.com/lucas-clemente/quic-go/compare/multiplexer-multiple-conns, as well as lucas-clemente/quic-go#2108. Not sure yet how to solve it...

@mholt mholt changed the title WIP: HTTP/3 support WIP: IETF-standard HTTP/3 support Sep 3, 2019
@mholt

This comment has been minimized.

Copy link
Member Author

commented Sep 5, 2019

Phew, thanks for all the investigative work @marten-seemann ! I think some good improvements have been made.

Unfortunately, though, after pulling the latest master of quic-go and building Caddy with it, I still see the hanging / panic from the client after shutting down the old server and starting a new one with the same underlying PacketConn.

Also, even though I thought that not Close()'ing the old server worked, it seems to cause problems; with more trials I found that the old servers were responding to some requests with the old configuration (which makes sense). So I can't use that as a workaround and thus will be Close()'ing the http3.Servers.

So, with that said, I've found out something else which may be helpful to you:

With debug mode enabled on the server, sometimes requests do work after doing a config reload. However, the requests often take much longer at least for the first several seconds.

BEFORE a config reload, when things work peachy, the server's output is about 150 lines long:


2019/09/05 08:27:42 server <- Received Initial packet.
2019/09/05 08:27:42 server      Long Header{Type: Initial, DestConnectionID: 0xcae58bfb710d84bca6ee4ab9172c, SrcConnectionID: (empty), Token: (empty), PacketNumber: 0x0, PacketNumberLen: 0, Length: 1176, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server Changing connection ID to 0x26378a08.
2019/09/05 08:27:42 server -> Sending Retry
2019/09/05 08:27:42 server      Long Header{Type: Retry, DestConnectionID: (empty), SrcConnectionID: 0x26378a08, Token: 0x120daaf0994370ec0e3b6dc012ca393454829026a5e483ae26593d7eca6e1a5c6eb84c36cd5d429abde0bfb53dd7dfb6fdcff21ea30ab548918067bf1385517b21f70b3ef7818b25d8b25e6693bec637f597e2386a78682ce9a86413c51457ca257e, OrigDestConnectionID: 0xcae58bfb710d84bca6ee4ab9172c, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server <- Received Initial packet.
2019/09/05 08:27:42 server Changing connection ID to 0x3c45ae1a.
2019/09/05 08:27:42 server <- Reading packet 0x1 (1200 bytes) for connection 0x26378a08, Initial
2019/09/05 08:27:42 server      Long Header{Type: Initial, DestConnectionID: 0x26378a08, SrcConnectionID: (empty), Token: 0x120daaf0994370ec0e3b6dc012ca393454829026a5e483ae26593d7eca6e1a5c6eb84c36cd5d429abde0bfb53dd7dfb6fdcff21ea30ab548918067bf1385517b21f70b3ef7818b25d8b25e6693bec637f597e2386a78682ce9a86413c51457ca257e, PacketNumber: 0x1, PacketNumberLen: 4, Length: 1087, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x165, Offset + Data length: 0x165}
2019/09/05 08:27:42 server Received ClientHello message (357 bytes, encryption level: Initial)
2019/09/05 08:27:42 server Received Transport Parameters: &handshake.TransportParameters{OriginalConnectionID: (empty), InitialMaxStreamDataBidiLocal: 0x80000, InitialMaxStreamDataBidiRemote: 0x80000, InitialMaxStreamDataUni: 0x80000, InitialMaxData: 0xc0000, MaxBidiStreamNum: 0, MaxUniStreamNum: 100, IdleTimeout: 30s, AckDelayExponent: 3, MaxAckDelay: 26ms}
2019/09/05 08:27:42 server Installed Handshake Read keys
2019/09/05 08:27:42 server Installed Handshake Write keys
2019/09/05 08:27:42 server Installed 1-RTT Write keys
2019/09/05 08:27:42 server Handled crypto frame at level Initial. encLevelChanged: true
2019/09/05 08:27:42 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.754368 -0600 MDT m=+4.462448765)
2019/09/05 08:27:42 server -> Sending packet 0x0 (165 bytes) for connection 0x3c45ae1a, Initial
2019/09/05 08:27:42 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, Token: (empty), PacketNumber: 0x0, PacketNumberLen: 4, Length: 151, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x1, DelayTime: 0s}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc000288840), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.754732 -0600 MDT m=+4.462813529)
2019/09/05 08:27:42 server -> Sending packet 0x0 (1252 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, PacketNumber: 0x0, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc00000e320), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.754819 -0600 MDT m=+4.462900289)
2019/09/05 08:27:42 server -> Sending packet 0x1 (1252 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, PacketNumber: 0x1, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc00000e460), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server <- Reading packet 0x2 (1200 bytes) for connection 0x3c45ae1a, Initial
2019/09/05 08:27:42 server      Long Header{Type: Initial, DestConnectionID: 0x3c45ae1a, SrcConnectionID: (empty), Token: 0x120daaf0994370ec0e3b6dc012ca393454829026a5e483ae26593d7eca6e1a5c6eb84c36cd5d429abde0bfb53dd7dfb6fdcff21ea30ab548918067bf1385517b21f70b3ef7818b25d8b25e6693bec637f597e2386a78682ce9a86413c51457ca257e, PacketNumber: 0x2, PacketNumberLen: 4, Length: 1087, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:27:42 server      updated RTT: 836.627µs (σ: 418.313µs)
2019/09/05 08:27:42 server      newly acked packets (1): [0x0]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.583328879 -0600 MDT m=+4.291410168)
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.598381879 -0600 MDT m=+4.306463147)
2019/09/05 08:27:42 server -> Sending packet 0x2 (723 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, PacketNumber: 0x2, PacketNumberLen: 4, Length: 710, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc00000e560), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server <- Reading packet 0x0 (37 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: 0x3c45ae1a, SrcConnectionID: (empty), PacketNumber: 0x0, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:27:42 server      updated RTT: 794µs (σ: 397µs)
2019/09/05 08:27:42 server      newly acked packets (1): [0x0]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.598254 -0600 MDT m=+4.306335268)
2019/09/05 08:27:42 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:27:42 server -> Sending packet 0x3 (37 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, PacketNumber: 0x3, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:27:42 server <- Reading packet 0x1 (37 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: 0x3c45ae1a, SrcConnectionID: (empty), PacketNumber: 0x1, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:27:42 server      updated RTT: 2.495ms (σ: 3.701ms)
2019/09/05 08:27:42 server      newly acked packets (1): [0x1]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.613171 -0600 MDT m=+4.321252268)
2019/09/05 08:27:42 server <- Reading packet 0x2 (71 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: 0x3c45ae1a, SrcConnectionID: (empty), PacketNumber: 0x2, PacketNumberLen: 4, Length: 59, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x24, Offset + Data length: 0x24}
2019/09/05 08:27:42 server Received Finished message (36 bytes, encryption level: Handshake)
2019/09/05 08:27:42 server Installed 1-RTT Read keys
2019/09/05 08:27:42 server Handled crypto frame at level Handshake. encLevelChanged: true
2019/09/05 08:27:42 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:27:42 server      Setting ACK timer to 1/8 min-RTT: 62.715µs (-185.364µs from now)
2019/09/05 08:27:42 server Sending ACK because the ACK timer expired.
2019/09/05 08:27:42 server -> Sending packet 0x4 (37 bytes) for connection 0x3c45ae1a, Handshake
2019/09/05 08:27:42 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x3c45ae1a, PacketNumber: 0x4, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x2, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.627212 -0600 MDT m=+4.335292550)
2019/09/05 08:27:42 server -> Sending packet 0x0 (121 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x0, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000ecb80), OnLost:(func(wire.Frame))(0x15bd430), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server <- Reading packet 0x0 (155 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x0, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.StreamFrame{StreamID: 0, FinBit: false, Offset: 0x0, Data length: 0x82, Offset + Data length: 0x82}
2019/09/05 08:27:42 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.627943 -0600 MDT m=+4.336023408)
2019/09/05 08:27:42 server -> Sending packet 0x1 (117 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x1, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 4.736158ms}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.NewTokenFrame)(0xc00000e9c0), OnLost:(func(wire.Frame))(0x15bd430), OnAcked:(func())(nil)}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc000283110), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server <- Reading packet 0x1 (28 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x1, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.StreamFrame{StreamID: 2, FinBit: false, Offset: 0x0, Data length: 0x3, Offset + Data length: 0x3}
2019/09/05 08:27:42 server GET example.local:2443/, on stream 0
2019/09/05 08:27:42 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:27:42 server      Setting ACK timer to 1/8 min-RTT: 62.715µs (-5.104557ms from now)
2019/09/05 08:27:42 server Sending ACK because the ACK timer expired.
2019/09/05 08:27:42 server -> Sending packet 0x2 (25 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x2, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 5.177348ms}
2019/09/05 08:27:42 server <- Reading packet 0x2 (27 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server Responding with 200
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x2, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.StreamFrame{StreamID: 0, FinBit: true, Offset: 0x82, Data length: 0x0, Offset + Data length: 0x82}
2019/09/05 08:27:42 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.628745 -0600 MDT m=+4.336825088)
2019/09/05 08:27:42 server -> Sending packet 0x3 (23 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x3, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0002e39b0), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.628807 -0600 MDT m=+4.336887113)
2019/09/05 08:27:42 server -> Sending packet 0x4 (50 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x4, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0002e3a10), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.629968 -0600 MDT m=+4.338048168)
2019/09/05 08:27:42 server -> Sending packet 0x5 (25 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0003c0030), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.630105 -0600 MDT m=+4.338185660)
2019/09/05 08:27:42 server -> Sending packet 0x6 (95 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x6, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0003c0090), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.630306 -0600 MDT m=+4.338386953)
2019/09/05 08:27:42 server -> Sending packet 0x7 (23 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x7, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0003c00f0), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:27:42 server <- Reading packet 0x3 (28 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x3, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 112µs}
2019/09/05 08:27:42 server      updated RTT: 2.227ms (σ: 3.311ms)
2019/09/05 08:27:42 server      newly acked packets (1): [0x0]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.628478 -0600 MDT m=+4.336558953)
2019/09/05 08:27:42 server Dropping Initial keys.
2019/09/05 08:27:42 server Dropping Handshake keys.
2019/09/05 08:27:42 server <- Reading packet 0x4 (28 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x4, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 256µs}
2019/09/05 08:27:42 server      updated RTT: 2.016ms (σ: 2.903ms)
2019/09/05 08:27:42 server      newly acked packets (1): [0x1]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.626635 -0600 MDT m=+4.334715953)
2019/09/05 08:27:42 server      Ignoring all packets below 0x1.
2019/09/05 08:27:42 server <- Reading packet 0x5 (28 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x4, LowestAcked: 0x0, DelayTime: 48µs}
2019/09/05 08:27:42 server      updated RTT: 1.933ms (σ: 2.342ms)
2019/09/05 08:27:42 server      newly acked packets (2): [0x3 0x4]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.624308 -0600 MDT m=+4.332388953)
2019/09/05 08:27:42 server <- Reading packet 0x6 (28 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x6, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.AckFrame{LargestAcked: 0x6, LowestAcked: 0x0, DelayTime: 56µs}
2019/09/05 08:27:42 server      updated RTT: 1.746ms (σ: 2.13ms)
2019/09/05 08:27:42 server      newly acked packets (2): [0x5 0x6]
2019/09/05 08:27:42 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:27:42.623273 -0600 MDT m=+4.331353953)
2019/09/05 08:27:42 server <- Reading packet 0x7 (27 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: 0x3c45ae1a, PacketNumber: 0x7, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      <- &wire.ConnectionCloseFrame{IsApplicationError:false, ErrorCode:0x0, FrameType:0x0, ReasonPhrase:""}
2019/09/05 08:27:42 server Peer closed session with error: NO_ERROR
2019/09/05 08:27:42 server      Queueing ACK because packet 2 packets were received after the last ACK (using initial threshold: 2).
2019/09/05 08:27:42 server -> Sending packet 0x8 (25 bytes) for connection 0x3c45ae1a, 1-RTT
2019/09/05 08:27:42 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x8, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:27:42 server      -> &wire.AckFrame{LargestAcked: 0x7, LowestAcked: 0x1, DelayTime: 639.732µs}
2019/09/05 08:27:42 server Connection 0x3c45ae1a closed.
2019/09/05 08:27:42 server Accepting stream failed: NO_ERROR

AFTER the config reload, the debug output is over 100 lines longer, indicating that the server (and client) have to do a lot more work to make the connection succeed:


2019/09/05 08:23:58 muxer received a packet with an unexpected connection ID 0x97fce529676f03ff63a61c35d7594c1acd
2019/09/05 08:23:58 server <- Received Initial packet.
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: 0x97fce529676f03ff63a61c35d7594c1acd, SrcConnectionID: (empty), Token: (empty), PacketNumber: 0x0, PacketNumberLen: 0, Length: 1173, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server <- Received Initial packet.
2019/09/05 08:23:58 server Changing connection ID to 0x70dfd7aa.
2019/09/05 08:23:58 server -> Sending Retry
2019/09/05 08:23:58 server      Long Header{Type: Retry, DestConnectionID: (empty), SrcConnectionID: 0x70dfd7aa, Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, OrigDestConnectionID: 0x97fce529676f03ff63a61c35d7594c1acd, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: 0x97fce529676f03ff63a61c35d7594c1acd, SrcConnectionID: (empty), Token: (empty), PacketNumber: 0x0, PacketNumberLen: 0, Length: 1173, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server Changing connection ID to 0xeffdbd91.
2019/09/05 08:23:58 server -> Sending Retry
2019/09/05 08:23:58 server      Long Header{Type: Retry, DestConnectionID: (empty), SrcConnectionID: 0xeffdbd91, Token: 0x25789383ef8c6bdd21fa8ebd0f1d4b65fc25d0a748047a4454cbb8e094c8e1ba3e0cd225e12f5aab9cf02d8b022c8ba6ed8f5f5ed4314e49498517ef2a9b94833b553946e99dfdf15ac7ffc20e56bfa87144d60b0c4610d6206954abc75daccbea7617ffd2, OrigDestConnectionID: 0x97fce529676f03ff63a61c35d7594c1acd, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 muxer received a packet with an unexpected connection ID 0x70dfd7aa
2019/09/05 08:23:58 server <- Received Initial packet.
2019/09/05 08:23:58 server <- Received Initial packet.
2019/09/05 08:23:58 server Changing connection ID to 0x331f2e59.
2019/09/05 08:23:58 server Changing connection ID to 0x8580a74d.
2019/09/05 08:23:58 server <- Reading packet 0x4 (1200 bytes) for connection 0x70dfd7aa, Initial
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: 0x70dfd7aa, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0x4, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x16e, Offset + Data length: 0x16e}
2019/09/05 08:23:58 server Received ClientHello message (366 bytes, encryption level: Initial)
2019/09/05 08:23:58 server <- Reading packet 0x5 (1200 bytes) for connection 0x70dfd7aa, Initial
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: 0x70dfd7aa, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0x5, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x16e, Offset + Data length: 0x16e}
2019/09/05 08:23:58 server Received ClientHello message (366 bytes, encryption level: Initial)
2019/09/05 08:23:58 server Received Transport Parameters: &handshake.TransportParameters{OriginalConnectionID: (empty), InitialMaxStreamDataBidiLocal: 0x80000, InitialMaxStreamDataBidiRemote: 0x80000, InitialMaxStreamDataUni: 0x80000, InitialMaxData: 0xc0000, MaxBidiStreamNum: 0, MaxUniStreamNum: 100, IdleTimeout: 30s, AckDelayExponent: 3, MaxAckDelay: 26ms}
2019/09/05 08:23:58 server Installed Handshake Read keys
2019/09/05 08:23:58 server Installed Handshake Write keys
2019/09/05 08:23:58 server Received Transport Parameters: &handshake.TransportParameters{OriginalConnectionID: (empty), InitialMaxStreamDataBidiLocal: 0x80000, InitialMaxStreamDataBidiRemote: 0x80000, InitialMaxStreamDataUni: 0x80000, InitialMaxData: 0xc0000, MaxBidiStreamNum: 0, MaxUniStreamNum: 100, IdleTimeout: 30s, AckDelayExponent: 3, MaxAckDelay: 26ms}
2019/09/05 08:23:58 server Installed Handshake Read keys
2019/09/05 08:23:58 server Installed Handshake Write keys
2019/09/05 08:23:58 server Installed 1-RTT Write keys
2019/09/05 08:23:58 server Handled crypto frame at level Initial. encLevelChanged: true
2019/09/05 08:23:58 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.170019 -0600 MDT m=+17.094516746)
2019/09/05 08:23:58 server -> Sending packet 0x0 (165 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:58 server Installed 1-RTT Write keys
2019/09/05 08:23:58 server Handled crypto frame at level Initial. encLevelChanged: true
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, Token: (empty), PacketNumber: 0x0, PacketNumberLen: 4, Length: 151, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:23:58 server      -> &wire.AckFrame{LargestAcked: 0x4, LowestAcked: 0x4, DelayTime: 0s}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000f2600), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.182544 -0600 MDT m=+17.107041616)
2019/09/05 08:23:58 server -> Sending packet 0x0 (165 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:23:58 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x0, PacketNumberLen: 4, Length: 151, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> &wire.AckFrame{LargestAcked: 0x5, LowestAcked: 0x5, DelayTime: 0s}
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.182607 -0600 MDT m=+17.107105090)
2019/09/05 08:23:58 server -> Sending packet 0x0 (1252 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 muxer received a packet with an unexpected connection ID 0x331f2e59
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, PacketNumber: 0x0, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000f26c0), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.183655 -0600 MDT m=+17.108153271)
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.183913 -0600 MDT m=+17.108410795)
2019/09/05 08:23:58 server -> Sending packet 0x1 (1252 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 server -> Sending packet 0x0 (1252 bytes) for connection 0x8580a74d, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, PacketNumber: 0x1, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0001462c0), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, PacketNumber: 0x0, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc000146240), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.184007 -0600 MDT m=+17.108504816)
2019/09/05 08:23:58 server -> Sending packet 0x2 (733 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, PacketNumber: 0x2, PacketNumberLen: 4, Length: 720, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.184104 -0600 MDT m=+17.108601363)
2019/09/05 08:23:58 server -> Sending packet 0x1 (1252 bytes) for connection 0x8580a74d, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, PacketNumber: 0x1, PacketNumberLen: 4, Length: 1239, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc000146320), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000f2840), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server <- Reading packet 0x0 (37 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.184442 -0600 MDT m=+17.108939925)
2019/09/05 08:23:58 server -> Sending packet 0x2 (733 bytes) for connection 0x8580a74d, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), PacketNumber: 0x0, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      <- &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, PacketNumber: 0x2, PacketNumberLen: 4, Length: 720, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0003884c0), OnLost:(func(wire.Frame))(0x15bd260), OnAcked:(func())(nil)}
2019/09/05 08:23:58 server      updated RTT: 1.613714ms (σ: 806.857µs)
2019/09/05 08:23:58 server      newly acked packets (1): [0x0]
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.014848142 -0600 MDT m=+16.939345958)
2019/09/05 08:23:58 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:23:58 server -> Sending packet 0x3 (37 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, PacketNumber: 0x3, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      -> &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:58 server <- Reading packet 0x1 (37 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:58 server      Long Header{Type: Handshake, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), PacketNumber: 0x1, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:23:58 server      <- &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:58 server      updated RTT: 1.459ms (σ: 912µs)
2019/09/05 08:23:58 server      newly acked packets (1): [0x1]
2019/09/05 08:23:58 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.015114 -0600 MDT m=+16.939611816)
2019/09/05 08:23:58 muxer received a packet with an unexpected connection ID 0x331f2e59
2019/09/05 08:23:58 server Queueing packet (161 bytes) for later decryption
2019/09/05 08:23:58 server Queueing packet (27 bytes) for later decryption
2019/09/05 08:23:59 server <- Reading packet 0x3 (37 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:59 server      Long Header{Type: Handshake, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), PacketNumber: 0x3, PacketNumberLen: 4, Length: 25, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x3, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:59 server      newly acked packets (1): [0x2]
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.015114 -0600 MDT m=+16.939611816)
2019/09/05 08:23:59 server Loss detection alarm fired in PTO mode. PTO count: 0
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.046221 -0600 MDT m=+16.970718816)
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.079149 -0600 MDT m=+17.003646054)
2019/09/05 08:23:59 server -> Sending packet 0x1 (160 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, Token: (empty), PacketNumber: 0x1, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000f2600), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.080223 -0600 MDT m=+17.004720310)
2019/09/05 08:23:59 server -> Sending packet 0x2 (160 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, Token: (empty), PacketNumber: 0x2, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0000f2600), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server <- Reading packet 0x7 (1200 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0x7, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:59 server <- Reading packet 0x8 (1200 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0x8, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x2, LowestAcked: 0x0, DelayTime: 0s}
2019/09/05 08:23:59 server      updated RTT: 4.735ms (σ: 7.236ms)
2019/09/05 08:23:59 server      newly acked packets (1): [0x2]
2019/09/05 08:23:59 server setLossDetectionTimer: canceling. Bytes in flight: 0
2019/09/05 08:23:59 server Loss detection alarm fired in PTO mode. PTO count: 0
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.384442 -0600 MDT m=+17.308939925)
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.584758 -0600 MDT m=+17.509251689)
2019/09/05 08:23:59 server -> Sending packet 0x1 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x1, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.584879 -0600 MDT m=+17.509373007)
2019/09/05 08:23:59 server -> Sending packet 0x2 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x2, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server Loss detection alarm fired in PTO mode. PTO count: 1
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.984879 -0600 MDT m=+17.909373007)
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:00.386473 -0600 MDT m=+18.310958476)
2019/09/05 08:23:59 server -> Sending packet 0x3 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x3, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:00.386533 -0600 MDT m=+18.311018243)
2019/09/05 08:23:59 server -> Sending packet 0x4 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x4, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server <- Reading packet 0x9 (1200 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0x9, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x16e, Offset + Data length: 0x16e}
2019/09/05 08:23:59 server Handled crypto frame at level Initial. encLevelChanged: false
2019/09/05 08:23:59 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:23:59 server      Setting ACK timer to 1/8 min-RTT: 47.868µs (-147.886µs from now)
2019/09/05 08:23:59 server Sending ACK because the ACK timer expired.
2019/09/05 08:23:59 server -> Sending packet 0x3 (40 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, Token: (empty), PacketNumber: 0x3, PacketNumberLen: 4, Length: 27, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0x9, LowestAcked: 0x4, AckRanges: {{Largest: 0x9, Smallest: 0x7}, {Largest: 0x4, Smallest: 0x4}}, DelayTime: 0s}
2019/09/05 08:23:59 server <- Reading packet 0xa (1200 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), Token: 0x3c32149ead8f2b0413bbebf3629b3df306983314ce373456656081ace12f95ba04532f4505a7b5d8eff8ddd41024a57a7ece602f0bcd6c1d98370080e6890a3fdf98268bccacbd391422876dfd15424cde1434ba93799f08a0de7de00d17d43b1a1fbe4f13, PacketNumber: 0xa, PacketNumberLen: 4, Length: 1084, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x16e, Offset + Data length: 0x16e}
2019/09/05 08:23:59 server Handled crypto frame at level Initial. encLevelChanged: false
2019/09/05 08:23:59 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:23:59 server Sending ACK because the ACK timer expired.
2019/09/05 08:23:59 server -> Sending packet 0x4 (40 bytes) for connection 0x331f2e59, Initial
2019/09/05 08:23:59 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, Token: (empty), PacketNumber: 0x4, PacketNumberLen: 4, Length: 27, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0xa, LowestAcked: 0x4, AckRanges: {{Largest: 0xa, Smallest: 0x7}, {Largest: 0x4, Smallest: 0x4}}, DelayTime: 0s}
2019/09/05 08:23:59 muxer received a packet with an unexpected connection ID 0x331f2e59
2019/09/05 08:23:59 server <- Reading packet 0x4 (71 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:59 server      Long Header{Type: Handshake, DestConnectionID: 0x331f2e59, SrcConnectionID: (empty), PacketNumber: 0x4, PacketNumberLen: 4, Length: 59, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      <- &wire.CryptoFrame{Offset: 0x0, Data length: 0x24, Offset + Data length: 0x24}
2019/09/05 08:23:59 server Received Finished message (36 bytes, encryption level: Handshake)
2019/09/05 08:23:59 server Installed 1-RTT Read keys
2019/09/05 08:23:59 server Handled crypto frame at level Handshake. encLevelChanged: true
2019/09/05 08:23:59 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:23:59 server      Setting ACK timer to 1/8 min-RTT: 47.868µs (-341.503µs from now)
2019/09/05 08:23:59 server Sending ACK because the ACK timer expired.
2019/09/05 08:23:59 server -> Sending packet 0x4 (39 bytes) for connection 0x331f2e59, Handshake
2019/09/05 08:23:59 server      Long Header{Type: Handshake, DestConnectionID: (empty), SrcConnectionID: 0x331f2e59, PacketNumber: 0x4, PacketNumberLen: 4, Length: 27, Version: TLS dev version (WIP)}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0x4, LowestAcked: 0x0, AckRanges: {{Largest: 0x4, Smallest: 0x3}, {Largest: 0x1, Smallest: 0x0}}, DelayTime: 0s}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.968227 -0600 MDT m=+17.892706139)
2019/09/05 08:23:59 server -> Sending packet 0x0 (121 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x0, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc000484d20), OnLost:(func(wire.Frame))(0x15bd430), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.968704 -0600 MDT m=+17.893183207)
2019/09/05 08:23:59 server -> Sending packet 0x1 (111 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x1, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.NewTokenFrame)(0xc0004768a0), OnLost:(func(wire.Frame))(0x15bd430), OnAcked:(func())(nil)}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0004e0510), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server <- Reading packet 0x0 (161 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x0, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.StreamFrame{StreamID: 2, FinBit: false, Offset: 0x0, Data length: 0x3, Offset + Data length: 0x3}
2019/09/05 08:23:59 server      <- &wire.StreamFrame{StreamID: 0, FinBit: false, Offset: 0x0, Data length: 0x82, Offset + Data length: 0x82}
2019/09/05 08:23:59 server      Queueing ACK because the first packet should be acknowledged.
2019/09/05 08:23:59 server -> Sending packet 0x2 (27 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x2, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 913.893925ms}
2019/09/05 08:23:59 server GET example.local:2443/, on stream 0
2019/09/05 08:23:59 server <- Reading packet 0x1 (27 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x1, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.StreamFrame{StreamID: 0, FinBit: true, Offset: 0x82, Data length: 0x0, Offset + Data length: 0x82}
2019/09/05 08:23:59 server Responding with 200
2019/09/05 08:23:59 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:23:59 server      Setting ACK timer to 1/8 min-RTT: 47.868µs (-914.050784ms from now)
2019/09/05 08:23:59 server Sending ACK because the ACK timer expired.
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.96926 -0600 MDT m=+17.893739082)
2019/09/05 08:23:59 server -> Sending packet 0x3 (31 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x3, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0x1, LowestAcked: 0x0, DelayTime: 914.114389ms}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc00014d620), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.969472 -0600 MDT m=+17.893950817)
2019/09/05 08:23:59 server -> Sending packet 0x4 (50 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x4, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc00014d710), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.969549 -0600 MDT m=+17.894028012)
2019/09/05 08:23:59 server -> Sending packet 0x5 (25 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0004e07b0), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.970578 -0600 MDT m=+17.895056804)
2019/09/05 08:23:59 server -> Sending packet 0x6 (95 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x6, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc0002824e0), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.970643 -0600 MDT m=+17.895122222)
2019/09/05 08:23:59 server -> Sending packet 0x7 (23 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x7, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> ackhandler.Frame{Frame:(*wire.StreamFrame)(0xc000282540), OnLost:(func(wire.Frame))(0x15bd560), OnAcked:(func())(0x15bd5b0)}
2019/09/05 08:23:59 server <- Reading packet 0x2 (28 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x2, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x0, LowestAcked: 0x0, DelayTime: 72µs}
2019/09/05 08:23:59 server      updated RTT: 4.225ms (σ: 6.445ms)
2019/09/05 08:23:59 server      newly acked packets (1): [0x0]
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.966969 -0600 MDT m=+17.891448222)
2019/09/05 08:23:59 server Dropping Initial keys.
2019/09/05 08:23:59 server Dropping Handshake keys.
2019/09/05 08:23:59 server <- Reading packet 0x3 (28 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x3, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x3, LowestAcked: 0x0, DelayTime: 64µs}
2019/09/05 08:23:59 server      updated RTT: 3.752ms (σ: 5.777ms)
2019/09/05 08:23:59 server      newly acked packets (2): [0x1 0x3]
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.963824 -0600 MDT m=+17.888303222)
2019/09/05 08:23:59 server      Ignoring all packets below 0x2.
2019/09/05 08:23:59 server <- Reading packet 0x4 (28 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x4, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.AckFrame{LargestAcked: 0x6, LowestAcked: 0x0, DelayTime: 32µs}
2019/09/05 08:23:59 server      updated RTT: 3.317ms (σ: 5.201ms)
2019/09/05 08:23:59 server      newly acked packets (3): [0x4 0x5 0x6]
2019/09/05 08:23:59 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:23:59.961085 -0600 MDT m=+17.885564222)
2019/09/05 08:23:59 server <- Reading packet 0x5 (27 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: 0x331f2e59, PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      <- &wire.ConnectionCloseFrame{IsApplicationError:false, ErrorCode:0x0, FrameType:0x0, ReasonPhrase:""}
2019/09/05 08:23:59 server Peer closed session with error: NO_ERROR
2019/09/05 08:23:59 server      Setting ACK timer to max ack delay: 25ms
2019/09/05 08:23:59 server      Setting ACK timer to 1/8 min-RTT: 34.609µs (-301.363µs from now)
2019/09/05 08:23:59 server Sending ACK because the ACK timer expired.
2019/09/05 08:23:59 server -> Sending packet 0x8 (24 bytes) for connection 0x331f2e59, 1-RTT
2019/09/05 08:23:59 server      Short Header{DestConnectionID: (empty), PacketNumber: 0x8, PacketNumberLen: 2, KeyPhase: 0}
2019/09/05 08:23:59 server      -> &wire.AckFrame{LargestAcked: 0x5, LowestAcked: 0x2, DelayTime: 343.982µs}
2019/09/05 08:23:59 server Connection 0x331f2e59 closed.
2019/09/05 08:23:59 server Accepting stream failed: NO_ERROR
2019/09/05 08:24:00 server Loss detection alarm fired in PTO mode. PTO count: 2
2019/09/05 08:24:00 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:01.186533 -0600 MDT m=+19.111018243)
2019/09/05 08:24:00 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:01.986884 -0600 MDT m=+19.911353409)
2019/09/05 08:24:00 server -> Sending packet 0x5 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:00 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x5, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:00 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:00 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:01.986944 -0600 MDT m=+19.911413785)
2019/09/05 08:24:00 server -> Sending packet 0x6 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:00 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x6, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:00 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:01 server Loss detection alarm fired in PTO mode. PTO count: 3
2019/09/05 08:24:01 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:03.586944 -0600 MDT m=+21.511413785)
2019/09/05 08:24:01 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:05.192373 -0600 MDT m=+23.116810293)
2019/09/05 08:24:01 server -> Sending packet 0x7 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:01 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x7, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:01 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:01 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:05.192609 -0600 MDT m=+23.117045937)
2019/09/05 08:24:01 server -> Sending packet 0x8 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:01 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x8, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:01 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:05 server Loss detection alarm fired in PTO mode. PTO count: 4
2019/09/05 08:24:05 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:08.392609 -0600 MDT m=+26.317045937)
2019/09/05 08:24:05 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:11.597329 -0600 MDT m=+29.521701345)
2019/09/05 08:24:05 server -> Sending packet 0x9 (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:05 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0x9, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:05 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:05 server setLossDetectionTimer: setting to%!(EXTRA time.Time=2019-09-05 08:24:11.597376 -0600 MDT m=+29.521747754)
2019/09/05 08:24:05 server -> Sending packet 0xa (160 bytes) for connection 0x8580a74d, Initial
2019/09/05 08:24:05 server      Long Header{Type: Initial, DestConnectionID: (empty), SrcConnectionID: 0x8580a74d, Token: (empty), PacketNumber: 0xa, PacketNumberLen: 4, Length: 146, Version: TLS dev version (WIP)}
2019/09/05 08:24:05 server      -> ackhandler.Frame{Frame:(*wire.CryptoFrame)(0xc0004760c0), OnLost:(func(wire.Frame))(0x15bd0a0), OnAcked:(func())(nil)}
2019/09/05 08:24:08 server Destroying session (empty): NO_ERROR: Handshake did not complete in time
2019/09/05 08:24:08 server Connection 0x8580a74d closed.

You'll notice that in the second case, first the server reports an unexpected connection ID, and does considerably more work than the first requests before the reload. (The second request, after the reload, takes several seconds -- noticeably slower than the first.)

I hope the difference between these logs will be helpful.

It is still difficult to reproduce the bug with debug mode enabled, but it happens pretty much every time for me with the server's debug mode off.

@mholt

This comment has been minimized.

Copy link
Member Author

commented Sep 5, 2019

WAIT A SECOND. I forgot to apply my git stash, which had a crucial replace in go.mod to use my GOPATH copy of the quic-go dependency. 😱 After applying that stash and doing more trials, it WORKS. So far. Every time. With and without debug mode. 🤞

Considering how easily and often I was able to reproduce the bug, it seems that I can't reproduce it anymore.

Nice work, yo. 😎 Whatever you committed to master last night must have made things better. Thank you!!

UPDATE: Okay actually I've been able to reproduce it twice. 🤔But it took a lot more trials.

I've updated this PR/branch with my latest code. The current commit does not close the servers, for better or for worse.

mholt added 2 commits Sep 5, 2019
@mholt mholt referenced this pull request Sep 10, 2019
mholt added 2 commits Sep 10, 2019
# Conflicts:
#	go.mod
#	go.sum
@mholt

This comment has been minimized.

Copy link
Member Author

commented Sep 10, 2019

@marten-seemann To summarize: the issue persists, but by not closing the http3.Server, the issue is either resolved or it hides itself.

I will make HTTP/3 off by default but configurable in a commit later this morning, and then merge this in, however, before HTTP/3 can be on by default we'll need to get to the bottom of what is causing the issue that I think we've made some progress on but is still not totally resolved.

Thanks for your hard work! Let me know how I can help.

@mholt mholt changed the title WIP: IETF-standard HTTP/3 support Experimental IETF-standard HTTP/3 support Sep 10, 2019
@mholt mholt merged commit 0c8ad52 into v2 Sep 10, 2019
1 check passed
1 check passed
license/cla Contributor License Agreement is signed.
Details
@mholt mholt deleted the http3 branch Sep 10, 2019
@escholtz escholtz referenced this pull request Sep 14, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.