Skip to content

Commit e367131

Browse files
pimterrypimterry
committed
Add more detailed ACME logging including trace ids
1 parent 7b53ce5 commit e367131

File tree

3 files changed

+64
-46
lines changed

3 files changed

+64
-46
lines changed

‎src/http-handler.ts‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import { TLSSocket } from 'tls';
22
import * as http from 'http';
33
import * as http2 from 'http2';
4+
import { MaybePromise } from '@httptoolkit/util';
45

56
import { clearArray } from './util.js';
67

@@ -33,7 +34,7 @@ type RequestHandler = (
3334
) => Promise<void>;
3435

3536
function createHttpRequestHandler(options: {
36-
acmeChallengeCallback: (token: string) => string | undefined,
37+
acmeChallengeCallback: (token: string) => MaybePromise<string | undefined>,
3738
rootDomain: string
3839
}): RequestHandler {
3940
return async function handleRequest(req, res) {
@@ -47,7 +48,7 @@ function createHttpRequestHandler(options: {
4748
if (path.startsWith('/.well-known/acme-challenge/')) {
4849
console.log("Got ACME challenge request", path);
4950
const token = path.split('/')[3];
50-
const response = options.acmeChallengeCallback(token);
51+
const response = await options.acmeChallengeCallback(token);
5152
if (response) {
5253
res.writeHead(200);
5354
res.end(response);
@@ -112,7 +113,7 @@ function createHttpRequestHandler(options: {
112113
}
113114

114115
export function createHttp1Handler(options: {
115-
acmeChallengeCallback: (token: string) => string | undefined,
116+
acmeChallengeCallback: (token: string) => MaybePromise<string | undefined>,
116117
rootDomain: string
117118
}) {
118119
const handleRequest = createHttpRequestHandler(options);
@@ -143,7 +144,7 @@ export function createHttp1Handler(options: {
143144
}
144145

145146
export function createHttp2Handler(options: {
146-
acmeChallengeCallback: (token: string) => string | undefined,
147+
acmeChallengeCallback: (token: string) => MaybePromise<string | undefined>,
147148
rootDomain: string
148149
}) {
149150
const handleRequest = createHttpRequestHandler(options);

‎src/tls-certificates/acme.ts‎

Lines changed: 55 additions & 39 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
import * as crypto from 'node:crypto';
12
import * as ACME from 'acme-client';
23
import { PersistentCertCache } from './cert-cache.js';
34

@@ -43,33 +44,48 @@ export class AcmeCA {
4344
})
4445
);
4546

46-
getChallengeResponse(token: string) {
47-
return this.pendingAcmeChallenges[token];
47+
async getChallengeResponse(token: string) {
48+
return (await this.acmeClient).getChallengeKeyAuthorization({
49+
token,
50+
type: 'http-01',
51+
url: '',
52+
status: 'pending'
53+
});
4854
}
4955

5056
tryGetCertificateSync(domain: string) {
5157
const cachedCert = this.certCache.getCert(domain);
5258

59+
if (cachedCert) {
60+
console.log(`Found cached cert for ${domain} (hash:${crypto.hash('sha256', cachedCert.cert)}, expiry: ${new Date(cachedCert.expiry).toISOString()})`);
61+
}
62+
5363
if (!cachedCert || cachedCert.expiry - Date.now() < ONE_WEEK) {
54-
this.getCertificate(domain); // Trigger a cert refresh
64+
const attemptId = Math.random().toString(16).slice(2);
65+
console.log(`Starting async cert update (${attemptId}) for domain ${domain}`);
66+
this.getCertificate(domain, { attemptId }); // Trigger a cert refresh
5567
}
5668

5769
return cachedCert;
5870
}
5971

6072
private async getCertificate(
6173
domain: string,
62-
options: { forceRegenerate?: boolean } = {}
74+
options: { forceRegenerate?: boolean, attemptId: string }
6375
): Promise<AcmeGeneratedCertificate> {
76+
if (!options.attemptId) {
77+
options.attemptId = Math.random().toString(16).slice(2);
78+
}
79+
6480
const cachedCert = this.certCache.getCert(domain);
6581
if (cachedCert && !options.forceRegenerate) {
6682
// If we have this cert in the cache, we generally want to use that.
6783

6884
if (cachedCert.expiry <= Date.now() - ONE_MINUTE) {
6985
// Expired - clear this data and get a new certificate somehow
70-
console.log(`Renewing totally expired certificate for ${domain}`);
86+
console.log(`Renewing totally expired certificate for ${domain} (${options.attemptId})`);
7187
this.certCache.clearCache(domain);
72-
return this.getCertificate(domain);
88+
return this.getCertificate(domain, { attemptId: options.attemptId });
7389
}
7490

7591
if (
@@ -78,50 +94,52 @@ export class AcmeCA {
7894
) {
7995
// Not yet expired, but expiring soon - we want to refresh this certificate, but
8096
// we're OK to do it async and keep using the current one for now.
81-
console.log(`Renewing near-expiry certificate for ${domain}`);
97+
console.log(`Renewing near-expiry certificate for ${domain} (${options.attemptId})`);
8298

8399
this.pendingCertRenewals[domain] = this.getCertificate(domain, {
84-
forceRegenerate: true
100+
forceRegenerate: true,
101+
attemptId: options.attemptId
85102
});
86103
}
87104

88105
return cachedCert;
89106
}
90107

91-
if (!cachedCert) console.log(`No cached cert for ${domain}`);
92-
else if (options.forceRegenerate) console.log(`Force regenerating cert for ${domain}`);
108+
if (!cachedCert) console.log(`No cached cert for ${domain} (${options.attemptId})`);
109+
else if (options.forceRegenerate) console.log(`Force regenerating cert for ${domain} (${options.attemptId})`);
93110

94111
if (this.pendingCertRenewals[domain] && !options.forceRegenerate) {
95112
// Coalesce updates for pending certs into one
96113
return this.pendingCertRenewals[domain]!;
97114
}
98115

99-
const refreshPromise: Promise<AcmeGeneratedCertificate> = this.requestNewCertificate(domain)
100-
.then((certData) => {
101-
if (
102-
this.pendingCertRenewals[domain] &&
103-
this.pendingCertRenewals[domain] !== refreshPromise
104-
) {
105-
// Don't think this should happen, but if we're somehow ever not the current cert
106-
// update, delegate to the 'real' cert update instead.
107-
return this.pendingCertRenewals[domain]!;
108-
}
116+
const refreshPromise: Promise<AcmeGeneratedCertificate> = this.requestNewCertificate(domain, {
117+
attemptId: options.attemptId
118+
}).then((certData) => {
119+
if (
120+
this.pendingCertRenewals[domain] &&
121+
this.pendingCertRenewals[domain] !== refreshPromise
122+
) {
123+
// Don't think this should happen, but if we're somehow ever not the current cert
124+
// update, delegate to the 'real' cert update instead.
125+
return this.pendingCertRenewals[domain]!;
126+
}
109127

110-
delete this.pendingCertRenewals[domain];
111-
this.certCache.cacheCert({ ...certData, domain });
112-
return certData;
113-
})
114-
.catch((e) => {
115-
console.log('Cert request failed', e);
116-
return this.getCertificate(domain, { forceRegenerate: true });
117-
})
128+
delete this.pendingCertRenewals[domain];
129+
this.certCache.cacheCert({ ...certData, domain });
130+
console.log(`Cert refresh completed for domain ${domain} (${options.attemptId}), hash:${crypto.hash('sha256', certData.cert)}`);
131+
return certData;
132+
}).catch((e) => {
133+
console.log(`Cert refresh failed (${options.attemptId})`, e);
134+
return this.getCertificate(domain, { forceRegenerate: true, attemptId: options.attemptId });
135+
});
118136

119137
this.pendingCertRenewals[domain] = refreshPromise;
120138
return refreshPromise;
121139
}
122140

123-
private async requestNewCertificate(domain: string): Promise<AcmeGeneratedCertificate> {
124-
console.log(`Requesting new certificate for ${domain}`);
141+
private async requestNewCertificate(domain: string, options: { attemptId: string }): Promise<AcmeGeneratedCertificate> {
142+
console.log(`Requesting new certificate for ${domain} (${options.attemptId})`);
125143

126144
const [key, csr] = await ACME.crypto.createCsr({
127145
commonName: domain
@@ -134,33 +152,31 @@ export class AcmeCA {
134152
skipChallengeVerification: true,
135153
challengeCreateFn: async (_authz, challenge, keyAuth) => {
136154
if (challenge.type !== 'http-01') {
137-
throw new Error(`Unexpected ${challenge.type} challenge`);
155+
throw new Error(`Unexpected ${challenge.type} challenge (${options.attemptId})`);
138156
}
139157

140-
console.log(`Preparing for ${challenge.type} ACME challenge`);
158+
console.log(`Preparing for ${challenge.type} ACME challenge ${challenge.token} (${options.attemptId})`);
141159

142160
this.pendingAcmeChallenges[challenge.token] = keyAuth;
143161
},
144162
challengeRemoveFn: async (_authz, challenge) => {
145163
if (challenge.type !== 'http-01') {
146-
throw new Error(`Unexpected ${challenge.type} challenge`);
164+
throw new Error(`Unexpected ${challenge.type} challenge (${options.attemptId})`);
147165
}
148166

149167
console.log(`Removing ACME ${
150168
challenge.status
151169
} ${
152170
challenge.type
153-
} challenge (validated: ${
154-
challenge.validated
155-
}, error: ${
156-
JSON.stringify(challenge.error)
157-
})`)
171+
} challenge ${
172+
JSON.stringify(challenge)
173+
}) (${options.attemptId})`);
158174

159175
delete this.pendingAcmeChallenges[challenge.token];
160176
}
161177
});
162178

163-
console.log(`Successfully ACMEd new certificate for ${domain}`);
179+
console.log(`Successfully ACMEd new certificate for ${domain} (${options.attemptId})`);
164180

165181
return {
166182
key: key.toString(),

‎src/tls-certificates/cert-cache.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
1-
import * as path from 'path';
2-
import * as fs from 'fs/promises';
1+
import * as path from 'node:path';
2+
import * as fs from 'node:fs/promises';
3+
import * as crypto from 'node:crypto';
34

45
interface CachedCertificate {
56
domain: string;
@@ -75,7 +76,7 @@ export class PersistentCertCache {
7576
console.warn(`Failed to cache to disk certificate data for ${domain}`);
7677
});
7778

78-
console.log(`Cached cert for ${domain}`);
79+
console.log(`Cached cert for ${domain}, hash:${crypto.hash('sha256', cert.cert)}`);
7980
return this.cache[domain];
8081
}
8182

0 commit comments

Comments
 (0)