Skip to content

Commit c717066

Browse files
tegefaulkestegefaulkes
committed
wip: debugging connection failure with generated TLS
I've cleaned up a bunch of the debugging so the logs are clearer now. I've narrowed the timeout problem down to the generated certificates. Something about them is preventing the connection from being fully established. Likely rejected in some way but as for why is inscrutable. More digging to follow. But I know that If I load the cert files from memory then it works. So I know it's the generated certs. * Related #8 [ci skip]
1 parent 0b9a6dc commit c717066

File tree

8 files changed

+253
-228
lines changed

8 files changed

+253
-228
lines changed

‎src/QUICClient.ts

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -160,14 +160,14 @@ class QUICClient extends EventTarget {
160160
port
161161
},
162162
config: quicConfig,
163-
logger: logger.getChild(`${QUICConnection.name} ${scid}`)
163+
logger: logger.getChild(`${QUICConnection.name} ${scid.toString().slice(32)}`)
164164
});
165165
connection.addEventListener(
166166
'error',
167167
handleConnectionError,
168168
{ once: true }
169169
);
170-
console.log('CLIENT TRIGGER SEND');
170+
logger.debug('CLIENT TRIGGER SEND');
171171
// This will not raise an error
172172
await connection.send();
173173
// This will wait to be established, while also rejecting on error

‎src/QUICConnection.ts

Lines changed: 32 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -312,7 +312,7 @@ class QUICConnection extends EventTarget {
312312
*/
313313
@ready(new errors.ErrorQUICConnectionDestroyed(), false, ['destroying'])
314314
public async recv(data: Uint8Array, remoteInfo: RemoteInfo) {
315-
console.log('RECV CALLED');
315+
this.logger.debug('RECV CALLED');
316316

317317
try {
318318
if (this.conn.isClosed()) {
@@ -336,7 +336,7 @@ class QUICConnection extends EventTarget {
336336
},
337337
};
338338
try {
339-
// console.log('Did a recv', data.byteLength);
339+
this.logger.debug(`Did a recv ${data.byteLength}`);
340340
this.conn.recv(data, recvInfo);
341341
} catch (e) {
342342
// Depending on the exception, the `this.conn.recv`
@@ -382,7 +382,7 @@ class QUICConnection extends EventTarget {
382382
}
383383
} finally {
384384

385-
// console.log('RECV FINALLY');
385+
this.logger.debug('RECV FINALLY');
386386

387387
// Set the timeout
388388
this.setTimeout();
@@ -397,7 +397,7 @@ class QUICConnection extends EventTarget {
397397
)
398398
) {
399399

400-
console.log('CALLING DESTROY 2');
400+
this.logger.debug('CALLING DESTROY 2');
401401
await this.destroy();
402402
}
403403
}
@@ -423,7 +423,7 @@ class QUICConnection extends EventTarget {
423423
@ready(new errors.ErrorQUICConnectionDestroyed(), false, ['destroying'])
424424
public async send(): Promise<void> {
425425

426-
console.log('SEND CALLED');
426+
this.logger.debug('SEND CALLED');
427427

428428
try {
429429
if (this.conn.isClosed()) {
@@ -439,11 +439,12 @@ class QUICConnection extends EventTarget {
439439
let sendInfo: SendInfo;
440440
while (true) {
441441
try {
442-
// console.log('Did a send');
442+
this.logger.debug('Did a send');
443443
[sendLength, sendInfo] = this.conn.send(sendBuffer);
444444
} catch (e) {
445+
this.logger.debug(`SEND FAILED WITH ${e.message}`);
445446
if (e.message === 'Done') {
446-
// console.log('SEND IS DONE');
447+
this.logger.debug('SEND IS DONE');
447448
return;
448449
}
449450
try {
@@ -470,8 +471,7 @@ class QUICConnection extends EventTarget {
470471
}
471472
try {
472473

473-
// console.log('ATTEMPTING SEND', sendBuffer, 0, sendLength, sendInfo.to.port, sendInfo.to.host);
474-
console.log('SEND UDP PACKET');
474+
this.logger.debug(`ATTEMPTING SEND ${sendLength} bytes to ${sendInfo.to.port}:${sendInfo.to.host}`);
475475

476476
await this.socket.send(
477477
sendBuffer,
@@ -481,21 +481,22 @@ class QUICConnection extends EventTarget {
481481
sendInfo.to.host
482482
);
483483
} catch (e) {
484+
console.error(e);
484485
this.dispatchEvent(new events.QUICConnectionErrorEvent({ detail: e }));
485486
return;
486487
}
487488
}
488489
} finally {
489490

490-
// console.log('SEND FINALLY');
491+
this.logger.debug('SEND FINALLY');
491492

492493
this.setTimeout();
493494
if (
494495
this[status] !== 'destroying' &&
495496
(this.conn.isClosed() || this.conn.isDraining())
496497
) {
497498

498-
console.log('CALLING DESTROY');
499+
this.logger.debug('CALLING DESTROY');
499500

500501
await this.destroy();
501502
} else if (
@@ -598,55 +599,55 @@ class QUICConnection extends EventTarget {
598599
// the time given becomes 1 second
599600
// Why did it reduce to 1000 ms?
600601

601-
// console.log('Time given:', time);
602+
// this.logger.debug('Time given:', time);
602603

603-
// console.log('IS DRAINING', this.conn.isDraining());
604+
// this.logger.debug('IS DRAINING', this.conn.isDraining());
604605

605606
// Do note there is a change in one of our methods
606607
// I think I remember, we still need to change over to that
607608
// To enusre that exceptions mean `Done`
608-
// console.log('PATH STATS', this.conn.pathStats());
609+
// this.logger.debug('PATH STATS', this.conn.pathStats());
609610

610611
if (time != null) {
611-
// console.log('Resetting the timeout');
612+
// this.logger.debug('Resetting the timeout');
612613

613614
clearTimeout(this.timer);
614615
this.timer = setTimeout(
615616
async () => {
616617

617-
// console.log('TIMEOUT HANDLER CALLED');
618-
// console.log('draining', this.conn.isDraining());
619-
// console.log('closed', this.conn.isClosed());
620-
// console.log('timed out', this.conn.isTimedOut());
621-
// console.log('established', this.conn.isEstablished());
622-
// console.log('in early data', this.conn.isInEarlyData());
623-
// console.log('resumed', this.conn.isResumed());
618+
// this.logger.debug('TIMEOUT HANDLER CALLED');
619+
// this.logger.debug('draining', this.conn.isDraining());
620+
// this.logger.debug('closed', this.conn.isClosed());
621+
// this.logger.debug('timed out', this.conn.isTimedOut());
622+
// this.logger.debug('established', this.conn.isEstablished());
623+
// this.logger.debug('in early data', this.conn.isInEarlyData());
624+
// this.logger.debug('resumed', this.conn.isResumed());
624625

625626
// This would only run if the `recv` and `send` is not called
626627
// Otherwise this handler would be cleared each time and be reset
627628
this.conn.onTimeout();
628629

629-
// console.log('AFTER ON TIMEOUT');
630+
// this.logger.debug('AFTER ON TIMEOUT');
630631
// DRAINING IS FALSE
631-
// console.log('draining', this.conn.isDraining());
632+
// this.logger.debug('draining', this.conn.isDraining());
632633
// CLOSED IS TRUE
633-
// console.log('closed', this.conn.isClosed());
634+
// this.logger.debug('closed', this.conn.isClosed());
634635
// TIMEDOUT IS TRUE
635-
// console.log('timed out', this.conn.isTimedOut());
636-
// console.log('established', this.conn.isEstablished());
637-
// console.log('in early data', this.conn.isInEarlyData());
638-
// console.log('resumed', this.conn.isResumed());
636+
// this.logger.debug('timed out', this.conn.isTimedOut());
637+
// this.logger.debug('established', this.conn.isEstablished());
638+
// this.logger.debug('in early data', this.conn.isInEarlyData());
639+
// this.logger.debug('resumed', this.conn.isResumed());
639640

640641
// Trigger a send, this will also set the timeout again at the end
641642

642-
console.log('TIMEOUT TRIGGER SEND');
643+
this.logger.debug('TIMEOUT TRIGGER SEND');
643644

644645
await this.send();
645646
},
646647
time
647648
);
648649
} else {
649-
// console.log('Clearing the timeout');
650+
this.logger.debug('Clearing the timeout');
650651
clearTimeout(this.timer);
651652
delete this.timer;
652653
if (this.conn.isClosed() || this.conn.isDraining()) {

‎src/QUICServer.ts

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ class QUICServer extends EventTarget {
7272
// We can force it
7373
config: Partial<QUICConfig> & Pick<
7474
QUICConfig,
75-
'certChainPem' | 'privKeyPem'
75+
'tlsConfig'
7676
>;
7777
resolveHostname?: (hostname: Hostname) => Host | PromiseLike<Host>;
7878
logger?: Logger;
@@ -261,14 +261,14 @@ class QUICServer extends EventTarget {
261261
}
262262
// Here we shall re-use the originally-derived DCID as the SCID
263263
scid = new QUICConnectionId(header.dcid);
264-
this.logger.debug(`Accepting new connection from QUIC packet`);
264+
this.logger.debug(`Accepting new connection from QUIC packet from ${remoteInfo.host}:${remoteInfo.port}`);
265265
const connection = await QUICConnection.acceptQUICConnection({
266266
scid,
267267
dcid: dcidOriginal,
268268
socket: this.socket,
269269
remoteInfo,
270270
config: this.config,
271-
logger: this.logger.getChild(`${QUICConnection.name} ${scid}`)
271+
logger: this.logger.getChild(`${QUICConnection.name} ${scid.toString().slice(32)}`)
272272
});
273273

274274
this.dispatchEvent(new events.QUICServerConnectionEvent({ detail: connection }));

‎src/QUICStream.ts

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -256,10 +256,10 @@ class QUICStream extends EventTarget implements ReadableWritablePair<Uint8Array,
256256
// or through an exception here where the stream reports an error
257257
// Since we don't call this method unless it is readable
258258
// This should never be reported... (this branch should be dead code)
259-
console.log('Stream reported: done');
259+
this.logger.debug('Stream reported: done');
260260
return;
261261
} else {
262-
console.log('Stream reported: error');
262+
this.logger.debug('Stream reported: error');
263263
const match = e.message.match(/StreamReset\((.+)\)/);
264264
if (match != null) {
265265
// If it is `StreamReset(u64)` error, then the peer has closed
@@ -284,8 +284,8 @@ class QUICStream extends EventTarget implements ReadableWritablePair<Uint8Array,
284284
}
285285
// If fin is true, then that means, the stream is CLOSED
286286
if (fin) {
287-
console.log('Stream reported: fin');
288287
// This will render `stream.cancel` a noop
288+
this.logger.debug('Stream reported: fin');
289289
this.readableController.close();
290290
await this.closeRecv();
291291
return;

‎src/config.ts

Lines changed: 28 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,16 @@
11
import type { Config as QuicheConfig } from './native/types';
22
import { quiche } from './native';
33

4+
type TlsConfig = {
5+
certChainPem: string | null;
6+
privKeyPem: string | null;
7+
} | {
8+
certChainFromPemFile: string | null;
9+
privKeyFromPemFile: string | null;
10+
}
11+
412
type QUICConfig = {
5-
certChainPem: string | null | undefined;
6-
privKeyPem: string | null | undefined;
13+
tlsConfig: TlsConfig | undefined;
714
verifyPeer: boolean;
815
logKeys: string | undefined;
916
grease: boolean;
@@ -21,8 +28,7 @@ type QUICConfig = {
2128
};
2229

2330
const clientDefault: QUICConfig = {
24-
certChainPem: null,
25-
privKeyPem: null,
31+
tlsConfig: undefined,
2632
logKeys: undefined,
2733
verifyPeer: false,
2834
grease: true,
@@ -46,8 +52,7 @@ const clientDefault: QUICConfig = {
4652
};
4753

4854
const serverDefault: QUICConfig = {
49-
certChainPem: null,
50-
privKeyPem: null,
55+
tlsConfig: undefined,
5156
logKeys: undefined,
5257
verifyPeer: false,
5358
grease: true,
@@ -71,16 +76,29 @@ const serverDefault: QUICConfig = {
7176
};
7277

7378
function buildQuicheConfig(config: QUICConfig): QuicheConfig {
74-
const quicheConfig: QuicheConfig = quiche.Config.withBoringSslCtx(
75-
config.certChainPem != null ? Buffer.from(config.certChainPem) : null,
76-
config.privKeyPem != null ? Buffer.from(config.privKeyPem) : null,
77-
)
79+
let quicheConfig: QuicheConfig;
80+
if (config.tlsConfig != null && 'certChainPem' in config.tlsConfig) {
81+
quicheConfig = quiche.Config.withBoringSslCtx(
82+
config.tlsConfig.certChainPem != null ? Buffer.from(config.tlsConfig.certChainPem) : null,
83+
config.tlsConfig.privKeyPem != null ? Buffer.from(config.tlsConfig.privKeyPem) : null,
84+
)
85+
} else {
86+
quicheConfig = new quiche.Config();
87+
if (config.tlsConfig?.certChainFromPemFile != null) {
88+
quicheConfig.loadCertChainFromPemFile(config.tlsConfig.certChainFromPemFile);
89+
}
90+
if (config.tlsConfig?.privKeyFromPemFile != null) {
91+
quicheConfig.loadPrivKeyFromPemFile(config.tlsConfig.privKeyFromPemFile);
92+
}
93+
}
7894
if (config.logKeys != null) {
7995
quicheConfig.logKeys();
8096
}
8197
if (config.enableEarlyData) {
8298
quicheConfig.enableEarlyData();
8399
}
100+
101+
quicheConfig.verifyPeer(config.verifyPeer);
84102
quicheConfig.grease(config.grease);
85103
quicheConfig.setMaxIdleTimeout(config.maxIdleTimeout);
86104
quicheConfig.setMaxRecvUdpPayloadSize(config.maxRecvUdpPayloadSize);

‎src/native/napi/config.rs

Lines changed: 5 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -56,17 +56,17 @@ impl Config {
5656
).or_else(
5757
|err| Err(Error::from_reason(err.to_string()))
5858
)?;
59-
ssl_ctx_builder.set_verify(
60-
boring::ssl::SslVerifyMode::PEER
61-
);
59+
// ssl_ctx_builder.set_verify(
60+
// boring::ssl::SslVerifyMode::NONE
61+
// );
6262
// Processing and adding the cert chain
6363
if let Some(cert_pem) = cert_pem {
64-
let x509_cet_chain = boring::x509::X509::stack_from_pem(
64+
let x509_cert_chain = boring::x509::X509::stack_from_pem(
6565
&cert_pem.to_vec()
6666
).or_else(
6767
|err| Err(Error::from_reason(err.to_string()))
6868
)?;
69-
for (i, cert) in x509_cet_chain.iter().enumerate() {
69+
for (i, cert) in x509_cert_chain.iter().enumerate() {
7070
if i == 0 {
7171
ssl_ctx_builder.set_certificate(
7272
cert,
@@ -84,12 +84,10 @@ impl Config {
8484
}
8585
// Processing and adding the private key
8686
if let Some(key_pem) = key_pem {
87-
println!("Had key pem");
8887
let private_key = boring::pkey::PKey::private_key_from_pem(&key_pem)
8988
.or_else(
9089
|err| Err(Error::from_reason(err.to_string()))
9190
)?;
92-
println!("{:?}", private_key);
9391
ssl_ctx_builder.set_private_key(&private_key)
9492
.or_else(
9593
|err| Err(Error::from_reason(err.to_string()))

0 commit comments

Comments
 (0)