Skip to content
This repository has been archived by the owner on Jul 21, 2024. It is now read-only.

Example does not work with OpenBSD #1

Open
ledeuns opened this issue Apr 28, 2020 · 10 comments
Open

Example does not work with OpenBSD #1

ledeuns opened this issue Apr 28, 2020 · 10 comments
Labels
bug Something isn't working

Comments

@ledeuns
Copy link

ledeuns commented Apr 28, 2020 •
edited
Loading

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
Copy link
Contributor

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
Copy link
Author

ledeuns commented May 14, 2020

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

@omarroth
Copy link
Contributor

omarroth commented May 16, 2020 •
edited
Loading

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
Copy link
Author

ledeuns commented May 17, 2020

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
Copy link
Contributor

omarroth commented May 20, 2020 •
edited
Loading

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

@omarroth omarroth added the bug Something isn't working label May 20, 2020
@ledeuns
Copy link
Author

ledeuns commented May 21, 2020

Thank you.

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

@omarroth
Copy link
Contributor

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
Copy link
Author

ledeuns commented May 21, 2020

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
Copy link
Contributor

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

@ledeuns
Copy link
Author

ledeuns commented Jul 20, 2020

No changes with the latest version of lsquic.cr. The good news though is http_client 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

@vhuynh3000 vhuynh3000 mentioned this issue Oct 23, 2020
Open
@nemunaire nemunaire mentioned this issue Jun 12, 2021
Merged
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ledeuns @omarroth