search

iv-org / lsquic.cr

Crystal bindings to LiteSpeed QUIC
MIT License
22 stars 6 forks source link

Example does not work with OpenBSD #1

Open ledeuns opened 4 years ago

ledeuns commented 4 years ago

Hi,

I am trying to get lsquic.cr to work on OpenBSD but the example is failing on me. When I start crystal example.cr I get no return from https://github.com/omarroth/lsquic.cr/blob/de2c945a2efaec85f0dfcb5a730fb976431fbb0c/src/lsquic/client.cr#L403

I use :

$ crystal -v
Crystal 0.34.0 (2020-04-26)

LLVM: 8.0.1 Default target: x86_64-unknown-openbsd6.7

I don't know if it is a Crystal, a liblsquic or a lsquic.cr problem. Can you help with debugging this issue ?

example.cr :


require "lsquic" 

client = QUIC::Client.new("www.youtube.com")
client.get("/")```
omarroth commented 4 years ago

You might try building the static objects in src/lsquic/ext/ from source. The instructions to build them are here. After building, you should have a liblsquic.a from lsquic and a libssl.a and libcrypto.a from boringssl.

ledeuns commented 4 years ago

I forgot to mention that I did it before posting :)

omarroth commented 4 years ago

In that case you might check that lsquic is working correctly. After building lsquic you should have a ./http_client binary you can test with.

Check that the following command returns a valid response, which would confirm the issue is in this library:

$ ./http_client -4 -s google.com -p '/' -o version=Q046 -l conn=debug
ledeuns commented 4 years ago

I have to change the code in test_common.c to make it work : https://github.com/litespeedtech/lsquic/blob/b78e44eec5aaa0a56c5a8fd54f1da825d6427418/test/test_common.c#L84 #define MAX_PACKET_SZ 1500

omarroth commented 4 years ago

Try building from the dev branch instead and replace the static library liblsquic.a with something like:

$ ar -x libssl.a
$ ar -x libcrypto.a
$ ar -x liblsquic.a
$ rm liblsquic.a
$ ar rc liblsquic.a *.o
$ rm *.o
$ strip --strip-unneeded liblsquic.a
$ ranlib liblsquic.a
ledeuns commented 4 years ago

Thank you.

It builds fine but still no return from https://github.com/omarroth/lsquic.cr/blob/de2c945a2efaec85f0dfcb5a730fb976431fbb0c/src/lsquic/client.cr#L403

omarroth commented 4 years ago

I'd recommend uncommenting these lines, which should enable verbose debugging information.

Out of curiosity, does ./http_client work if you use the -z BYTES option instead of redefining MAX_PACKET_SZ?

If either freezes at a particular point the previous 10-20 lines logged would be helpful.

ledeuns commented 4 years ago

Here are some tests :

./http_client -4 -s google.com -p '/' -o version=Q046 -l conn=debug -z 1500
20:06:28.747 [DEBUG] [QUIC:15C2C8D8282CDF5E] conn: negotiating version Q046
20:06:28.748 [INFO] [QUIC:15C2C8D8282CDF5E] conn: Created new client connection
20:06:28.748 [DEBUG] [QUIC:15C2C8D8282CDF5E] conn: delayed stream creation.  Backlog size: 1
20:06:28.748 [DEBUG] [QUIC:15C2C8D8282CDF5E] conn: memory used: 8930 bytes
packout buf size too large: 1500Abort trap (core dumped) 

o4# ./http_client -4 -s google.com -p '/' -o version=Q046 -l conn=debug -z 1280 
20:06:34.827 [DEBUG] [QUIC:D3CC54CA3C12FD5C] conn: negotiating version Q046
20:06:34.828 [INFO] [QUIC:D3CC54CA3C12FD5C] conn: Created new client connection
20:06:34.828 [DEBUG] [QUIC:D3CC54CA3C12FD5C] conn: delayed stream creation.  Backlog size: 1
20:06:34.828 [DEBUG] [QUIC:D3CC54CA3C12FD5C] conn: memory used: 8930 bytes
20:06:34.829 [DEBUG] [QUIC:D3CC54CA3C12FD5C] conn: not tickable
[hangs here]

o4# ./http_client -4 -s google.com -p '/' -o version=Q046 -l conn=debug -z 100  
20:06:42.828 [DEBUG] [QUIC:9448AC61E994D036] conn: negotiating version Q046
20:06:42.829 [INFO] [QUIC:9448AC61E994D036] conn: Created new client connection
20:06:42.829 [DEBUG] [QUIC:9448AC61E994D036] conn: delayed stream creation.  Backlog size: 1
20:06:42.829 [DEBUG] [QUIC:9448AC61E994D036] conn: memory used: 8930 bytes
20:06:42.831 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:42.987 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:43.295 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:43.901 [DEBUG] [QUIC:9448AC61E994D036] conn: memory used: 11238 bytes
20:06:43.903 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:45.105 [DEBUG] [QUIC:9448AC61E994D036] conn: memory used: 11302 bytes
20:06:45.106 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:47.523 [DEBUG] [QUIC:9448AC61E994D036] conn: memory used: 11302 bytes
20:06:47.524 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:52.339 [DEBUG] [QUIC:9448AC61E994D036] conn: memory used: 11366 bytes
20:06:52.340 [DEBUG] [QUIC:9448AC61E994D036] conn: not tickable
20:06:52.836 [DEBUG] [QUIC:9448AC61E994D036] conn: connection timed out: handshake timed out
20:06:52.836 [DEBUG] [QUIC:9448AC61E994D036] conn: destroy connection

With reduced MAX_PACKET_SZ :

o4# ./http_client -4 -s google.com -p '/' -o version=Q046 -l conn=debug         
20:12:55.960 [DEBUG] [QUIC:49143524780131D3] conn: negotiating version Q046
20:12:55.961 [INFO] [QUIC:49143524780131D3] conn: Created new client connection
20:12:55.961 [DEBUG] [QUIC:49143524780131D3] conn: delayed stream creation.  Backlog size: 1
20:12:55.961 [DEBUG] [QUIC:49143524780131D3] conn: memory used: 8930 bytes
20:12:55.962 [DEBUG] [QUIC:49143524780131D3] conn: not tickable
20:12:55.993 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 1
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: end of version negotiation: agreed upon Q046
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 3, packno: 1, max: 0) to 1
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: Saved ACK
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #1
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: ACK alarm set to 604463843
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 2
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 3, packno: 2, max: 1) to 2
20:12:55.994 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #1
20:12:55.996 [DEBUG] [QUIC:49143524780131D3] conn: ACK queued: ackable: 2; had_miss: 0; was_missing: 0; n_stop_waiting: 0
20:12:55.996 [DEBUG] [QUIC:49143524780131D3] conn: Processing ACK
20:12:55.996 [DEBUG] [QUIC:49143524780131D3] conn: Put 6 bytes of ACK frame into packet on outgoing queue
20:12:55.996 [DEBUG] [QUIC:49143524780131D3] conn: ACK state reset
20:12:55.999 [DEBUG] [QUIC:49143524780131D3] conn: not tickable
20:12:56.023 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 3
20:12:56.023 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 3, packno: 3, max: 2) to 3
20:12:56.024 [DEBUG] [QUIC:49143524780131D3] conn: Saved ACK
20:12:56.024 [DEBUG] [QUIC:49143524780131D3] conn: Processing ACK
20:12:56.024 [DEBUG] [QUIC:49143524780131D3] conn: not tickable
20:12:56.031 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 4
20:12:56.031 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 3, packno: 4, max: 3) to 4
20:12:56.031 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #1
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: peer settings: CFCW: 196608; SFCW: 131072; MIDS: 100
20:12:56.033 [INFO] [QUIC:49143524780131D3] conn: Applying peer config: cfcw: 196608; sfcw: 131072; # streams: 100
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: not sending any settings
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: creating delayed streams
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: created 1 delayed stream
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: ACK alarm set to 604501163
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 5
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 0, packno: 5, max: 4) to 5
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: Saved ACK
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: ACK alarm set to 604503247
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: Processing ACK
20:12:56.033 [DEBUG] [QUIC:49143524780131D3] conn: not tickable
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 6
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 0, packno: 6, max: 5) to 6
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: Saved ACK
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #3
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #5
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: ACK queued: ackable: 2; had_miss: 0; was_missing: 0; n_stop_waiting: 0
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: Processing packet 7
20:12:56.069 [DEBUG] [QUIC:49143524780131D3] conn: reconstructed (bits: 0, packno: 7, max: 6) to 7
20:12:56.070 [DEBUG] [QUIC:49143524780131D3] conn: Got stream frame for stream #5
20:12:56.070 [DEBUG] [QUIC:49143524780131D3] conn: Processing ACK
20:12:56.070 [DEBUG] [QUIC:49143524780131D3] conn: incoming headers for stream 5
HTTP/1.1 301 Moved Permanently
location: https://www.google.com/
content-type: text/html; charset=UTF-8
date: Thu, 21 May 2020 18:12:48 GMT
expires: Sat, 20 Jun 2020 18:12:48 GMT
cache-control: public, max-age=2592000
server: gws
content-length: 220
x-xss-protection: 0
x-frame-options: SAMEORIGIN
alt-svc: h3-27=":443"; ma=2592000,h3-25=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"

<HTML><HEAD><meta http-equiv="content-type" content="text/html;charset=utf-8">
<TITLE>301 Moved</TITLE></HEAD><BODY>
<H1>301 Moved</H1>
The document has moved
<A HREF="https://www.google.com/">here</A>.
</BODY></HTML>
20:12:56.070 [DEBUG] [QUIC:49143524780131D3] conn: Put 6 bytes of ACK frame into packet on outgoing queue
20:12:56.071 [DEBUG] [QUIC:49143524780131D3] conn: ACK state reset
20:12:56.071 [DEBUG] [QUIC:49143524780131D3] conn: wrote GOAWAY frame: stream id: 0
20:12:56.071 [DEBUG] [QUIC:49143524780131D3] conn: connection is OK to close
20:12:56.071 [DEBUG] [QUIC:49143524780131D3] conn: generated CONNECTION_CLOSE frame in its own packet
20:12:56.071 [DEBUG] [QUIC:49143524780131D3] conn: destroy connection

The example with debug enabled :

o4# ./test-lsquiccr
20:36:31.555 [DEBUG] tokgen: TOKGEN1 does not exist: generate
20:36:31.557 [INFO] tokgen: inserted TOKGEN1 of size 110
20:36:31.557 [DEBUG] tokgen: initialized
20:36:31.558 [INFO] engine: instantiated engine
20:36:31.597 [DEBUG] engine: grew heaps to 4 elements
20:36:31.597 [DEBUG] [QUIC:FEC6A01A2F1F65F7] cfcw: recv_off changed: read_off: 0; recv_off: 15728640
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7] cubic: lsquic_cubic_init(cubic, $conn)
20:36:31.598 [INFO] [QUIC:FEC6A01A2F1F65F7] cubic: initialized
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7] rechist: instantiated received packet history
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] di: initialized
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] sfcw: recv_off changed: read_off: 0; recv_off: 6291456
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] stream: created stream
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] stream: calling on_new_stream
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7] headers: stream created
20:36:31.598 [DEBUG] [QUIC:FEC6A01A2F1F65F7] frame-reader: reset state
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] conn: negotiating version Q050
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] di: initialized
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] sfcw: recv_off changed: read_off: 0; recv_off: 6291456
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: created stream
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: calling on_new_stream
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] hsk-adapter: stream created
20:36:31.599 [INFO] [QUIC:FEC6A01A2F1F65F7] conn: Created new client connection
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: created full connection
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: connection created
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] qlog: [2020044748,"CONNECTIVITY","NEW_CONNECTION","LINE",{"ip_version":"4","srcip":"192.168.255.43","dstip":"172.217.19.238","srcport":"13774","dstport":"443"}]
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: version negotiation: proposed version Q050
20:36:31.599 [DEBUG] [QUIC:FEC6A01A2F1F65F7] qlog: [2020044872,"CONNECTIVITY","VERNEG","LINE",{"proposed_version":"Q050"}]
20:36:31.599 [DEBUG] engine: incref conn FEC6A01A2F1F65F7, 'H' -> 'HT'
20:36:31.600 [DEBUG] [QUIC:FEC6A01A2F1F65F7] conn: delayed stream creation.  Backlog size: 1
20:36:31.600 [DEBUG] engine: decref conn FEC6A01A2F1F65F7, 'HT' -> 'H'
20:36:31.600 [DEBUG] [QUIC:FEC6A01A2F1F65F7] conn: memory used: 8935 bytes
20:36:31.600 [DEBUG] [QUIC:FEC6A01A2F1F65F7] pacer: lsquic_pacer_can_schedule: 1
20:36:31.600 [DEBUG] [QUIC:FEC6A01A2F1F65F7] handshake: lsquic_enc_session_gen_chlo called, return 0, buf_len 1024.
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: buffered 1024 bytes; 1024 bytes are now in buffer
20:36:31.601 [INFO] [QUIC:FEC6A01A2F1F65F7] hsk-adapter: wrote 1024 bytes of CHLO to stream
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: will flush up to offset 1024
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 46720
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] pacer: lsquic_pacer_can_schedule: 1
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] sendctl: created packet 1
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: created packet 1; flags: version=1, nonce=0, conn_id=1
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] pacer: lsquic_pacer_packet_scheduled: replenish tokens: 10
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] pacer: lsquic_pacer_packet_scheduled: tokens: 9
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: generated CRYPTO frame: offset: 0, size: 1024
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: flushed to or past required offset 1024
20:36:31.601 [DEBUG] engine: incref conn FEC6A01A2F1F65F7, 'H' -> 'HO'
20:36:31.601 [DEBUG] engine: incref conn FEC6A01A2F1F65F7, 'HO' -> 'HOK'
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] sendctl: packet size 1370 larger than 1200-byte limit: not zero-padding
20:36:31.601 [DEBUG] [QUIC:FEC6A01A2F1F65F7] handshake: apply header protection using mask 8E2E4A5B60
20:36:31.601 [DEBUG] engine: batched packet 1 for connection FEC6A01A2F1F65F7
20:36:31.602 [DEBUG] engine: batched all outgoing packets for full conn FEC6A01A2F1F65F7
20:36:31.603 [DEBUG] engine: cannot send packets
20:36:31.603 [DEBUG] event: cannot send packets
20:36:31.603 [WARN] engine: error sending packet for regular connection FEC6A01A2F1F65F7 - close it; src: 192.168.255.43:13774; dst: 172.217.19.238:443; errno: 56
20:36:31.604 [DEBUG] engine: incref conn FEC6A01A2F1F65F7, 'HOK' -> 'CHOK'
20:36:31.604 [DEBUG] engine: decref conn FEC6A01A2F1F65F7, 'CHOK' -> 'COK'
20:36:31.604 [DEBUG] engine: decref conn FEC6A01A2F1F65F7, 'COK' -> 'CO'
20:36:31.604 [DEBUG] engine: packets out returned 0 (out of 1)
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: unsent packet 1, size 1370, frame types: PADDING CRYPTO
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] sendctl: packet 1 has been delayed
20:36:31.604 [DEBUG] engine: decref conn FEC6A01A2F1F65F7, 'CO' -> 'C'
20:36:31.604 [DEBUG] engine: send_packets_out: sent 0 packets
20:36:31.604 [DEBUG] engine: decref conn FEC6A01A2F1F65F7, 'C' -> ''
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] conn: destroy connection
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] headers: stream closed
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] sfcw: read_off goes from 0 to 0
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] stream: destroyed stream
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-1] stream: history: [CN1]
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] hsk-adapter: stream closed
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] sfcw: read_off goes from 0 to 0
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: destroyed stream
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7-18446744073709551615] stream: history: [CN32w1]
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] pacer: scheduled calls: 1
20:36:31.604 [NOTICE] [QUIC:FEC6A01A2F1F65F7] sendctl: stats: n_total_sent: 0; n_resent: 0; n_delayed: 1
20:36:31.604 [DEBUG] [QUIC:FEC6A01A2F1F65F7] event: full connection destroyed

Note that tcpdump shows only the dns resolution with this example (no traffic going to port 443) while with http_client :

20:22:49.572559 192.168.255.43.18075 > 216.58.204.142.443: udp 1200
20:22:49.592904 216.58.204.142.443 > 192.168.255.43.18075: udp 1200 (DF)
20:22:49.593395 216.58.204.142.443 > 192.168.255.43.18075: udp 1200 (DF)
20:22:49.593431 216.58.204.142.443 > 192.168.255.43.18075: udp 1200 (DF)
20:22:49.598731 192.168.255.43.18075 > 216.58.204.142.443: udp 1200
20:22:49.621799 216.58.204.142.443 > 192.168.255.43.18075: udp 1200 (DF)
20:22:49.624539 192.168.255.43.18075 > 216.58.204.142.443: udp 68
20:22:49.650161 216.58.204.142.443 > 192.168.255.43.18075: udp 620 (DF)
20:22:49.650164 216.58.204.142.443 > 192.168.255.43.18075: udp 27 (DF)
20:22:49.651824 192.168.255.43.18075 > 216.58.204.142.443: udp 44
20:22:49.652071 192.168.255.43.18075 > 216.58.204.142.443: udp 33
omarroth commented 4 years ago

Would you mind checking with the latest version to see if the issue is fixed?

ledeuns commented 4 years ago

No changes with the latest version of lsquic.cr. The good news though is _httpclient works without any changes to MAX_PACKET_SZ. Thank you.

$ ./test-lsquiccr
18:00:05.604 [DEBUG] tokgen: TOKGEN2 does not exist: generate
18:00:05.606 [INFO] tokgen: inserted TOKGEN2 of size 110
18:00:05.606 [DEBUG] tokgen: initialized
18:00:05.606 [INFO] engine: instantiated engine
18:00:05.677 [DEBUG] engine: grew heaps to 4 elements
18:00:05.677 [DEBUG] [QUIC:A8B19FEEB91D10A4] cfcw: recv_off changed: read_off: 0; recv_off: 15728640
18:00:05.677 [DEBUG] [QUIC:A8B19FEEB91D10A4] cubic: lsquic_cubic_init(cubic, $conn)
18:00:05.677 [INFO] [QUIC:A8B19FEEB91D10A4] cubic: initialized
18:00:05.677 [DEBUG] [QUIC:A8B19FEEB91D10A4] rechist: instantiated received packet history
18:00:05.677 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] di: initialized
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] sfcw: recv_off changed: read_off: 0; recv_off: 6291456
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] stream: created stream
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] stream: calling on_new_stream
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4] headers: stream created
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4] frame-reader: reset state
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] di: get_frame: no frame at read offset 0
18:00:05.678 [DEBUG] [QUIC:A8B19FEEB91D10A4] conn: negotiating version Q050
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] di: initialized
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] sfcw: recv_off changed: read_off: 0; recv_off: 6291456
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: created stream
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: calling on_new_stream
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] hsk-adapter: stream created
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 46720
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] pacer: lsquic_pacer_can_schedule: 1
18:00:05.679 [DEBUG] engine: incref conn A8B19FEEB91D10A4, '' -> 'T'
18:00:05.679 [INFO] [QUIC:A8B19FEEB91D10A4] conn: Created new client connection
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: created full connection
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: connection created
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] qlog: [34678538187,"CONNECTIVITY","NEW_CONNECTION","LINE",{"ip_version":"4","srcip":"192.168.10.10","dstip":"216.58.209.46","srcport":"17707","dstport":"443"}]
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: version negotiation: proposed version Q050
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] qlog: [34678538306,"CONNECTIVITY","VERNEG","LINE",{"proposed_version":"Q050"}]
18:00:05.679 [DEBUG] [QUIC:A8B19FEEB91D10A4] conn: delayed stream creation.  Backlog size: 1
18:00:05.679 [DEBUG] engine: decref conn A8B19FEEB91D10A4, 'HT' -> 'H'
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] conn: memory used: 8327 bytes
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] pacer: lsquic_pacer_can_schedule: 1
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] handshake: lsquic_enc_session_gen_chlo called, return 0, buf_len 1024.
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: buffered 1024 bytes; 1024 bytes are now in buffer
18:00:05.680 [INFO] [QUIC:A8B19FEEB91D10A4] hsk-adapter: wrote 1024 bytes of CHLO to stream
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: will flush up to offset 1024
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 46720
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] pacer: lsquic_pacer_can_schedule: 1
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] sendctl: created packet 1
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: created packet 1; flags: version=1, nonce=0, conn_id=1
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] pacer: lsquic_pacer_packet_scheduled: replenish tokens: 10
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] pacer: lsquic_pacer_packet_scheduled: tokens: 9
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: generated CRYPTO frame: offset: 0, size: 1024
18:00:05.680 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: flushed to or past required offset 1024
18:00:05.680 [DEBUG] engine: incref conn A8B19FEEB91D10A4, 'H' -> 'HO'
18:00:05.680 [DEBUG] engine: incref conn A8B19FEEB91D10A4, 'HO' -> 'HOK'
18:00:05.681 [DEBUG] [QUIC:A8B19FEEB91D10A4] sendctl: packet size 1370 larger than 1200-byte limit: not zero-padding
18:00:05.681 [DEBUG] [QUIC:A8B19FEEB91D10A4] handshake: apply header protection using mask CFDA2FD9CA
18:00:05.681 [DEBUG] engine: batched packet 1 for connection A8B19FEEB91D10A4
18:00:05.681 [DEBUG] engine: batched all outgoing packets for full conn A8B19FEEB91D10A4
18:00:05.682 [DEBUG] engine: cannot send packets
18:00:05.683 [DEBUG] event: cannot send packets
18:00:05.683 [WARN] engine: error sending packet for regular connection A8B19FEEB91D10A4 - close it; src: 192.168.10.10:17707; dst: 216.58.209.46:443; errno: 56
18:00:05.683 [DEBUG] engine: incref conn A8B19FEEB91D10A4, 'HOK' -> 'CHOK'
18:00:05.683 [DEBUG] engine: decref conn A8B19FEEB91D10A4, 'CHOK' -> 'COK'
18:00:05.683 [DEBUG] engine: decref conn A8B19FEEB91D10A4, 'COK' -> 'CO'
18:00:05.683 [DEBUG] engine: packets out returned 0 (out of 1)
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: unsent packet 1, size 1370, frame types: PADDING CRYPTO
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] sendctl: packet 1 has been delayed
18:00:05.683 [DEBUG] engine: decref conn A8B19FEEB91D10A4, 'CO' -> 'C'
18:00:05.683 [DEBUG] engine: send_packets_out: sent 0 packets
18:00:05.683 [DEBUG] engine: decref conn A8B19FEEB91D10A4, 'C' -> ''
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] conn: destroy connection
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] headers: stream closed
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] sfcw: read_off goes from 0 to 0
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4-1] stream: destroyed stream
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] hsk-adapter: stream closed
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] sfcw: read_off goes from 0 to 0
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4-18446744073709551615] stream: destroyed stream
18:00:05.683 [NOTICE] [QUIC:A8B19FEEB91D10A4] sendctl: stats: n_total_sent: 0; n_resent: 0; n_delayed: 1
18:00:05.683 [DEBUG] [QUIC:A8B19FEEB91D10A4] event: full connection destroyed