From: William Lallemand Date: Tue, 29 Jul 2025 15:12:33 +0000 (+0200) Subject: MINOR: acme: implement traces X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=83a335f9253e1956d80660ebd23e4098966d1a9c;p=thirdparty%2Fhaproxy.git MINOR: acme: implement traces Implement traces for the ACME protocol. -dt acme:data:complete will dump every input and output buffers, including decoded buffers before being converted to JWS. It will also dump certificates in the traces. -dt acme:user:complete will only dump the state of the task handler. --- diff --git a/include/haproxy/acme-t.h b/include/haproxy/acme-t.h index 2e775fb39..c37b5a220 100644 --- a/include/haproxy/acme-t.h +++ b/include/haproxy/acme-t.h @@ -81,4 +81,20 @@ struct acme_ctx { struct ist certificate; struct mt_list el; }; + +#define ACME_EV_SCHED (1ULL << 0) /* scheduling wakeup */ +#define ACME_EV_NEW (1ULL << 1) /* new task */ +#define ACME_EV_TASK (1ULL << 2) /* Task handler */ +#define ACME_EV_REQ (1ULL << 3) /* HTTP Request */ +#define ACME_EV_RES (1ULL << 4) /* HTTP Response */ + +#define ACME_VERB_CLEAN 1 +#define ACME_VERB_MINIMAL 2 +#define ACME_VERB_SIMPLE 3 +#define ACME_VERB_ADVANCED 4 +#define ACME_VERB_COMPLETE 5 + +#define TRACE_SOURCE &trace_acme + + #endif diff --git a/src/acme.c b/src/acme.c index 9668e06ff..81452bf9b 100644 --- a/src/acme.c +++ b/src/acme.c @@ -34,9 +34,109 @@ #include #include #include +#include #if defined(HAVE_ACME) +static void acme_trace(enum trace_level level, uint64_t mask, const struct trace_source *src, + const struct ist where, const struct ist func, + const void *a1, const void *a2, const void *a3, const void *a4); + +static const struct trace_event acme_trace_events[] = { + { .mask = ACME_EV_SCHED, .name = "acme_sched", .desc = "Wakeup scheduled ACME task" }, + { .mask = ACME_EV_NEW, .name = "acme_new", .desc = "New ACME task" }, + { .mask = ACME_EV_TASK, .name = "acme_task", .desc = "ACME task" }, + { } +}; + + +static const struct name_desc acme_trace_lockon_args[4] = { + /* arg1 */ { .name="acme_ctx", .desc="ACME context" }, + /* arg2 */ { }, + /* arg3 */ { }, + /* arg4 */ { } +}; + +static const struct name_desc acme_trace_decoding[] = { + { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" }, + { .name="minimal", .desc="report only conn, no real decoding" }, + { .name="simple", .desc="add error messages" }, + { .name="advanced", .desc="add handshake-related details" }, + { .name="complete", .desc="add full data dump when available" }, + { /* end */ } +}; + + +struct trace_source trace_acme = { + .name = IST("acme"), + .desc = "ACME", + .arg_def = TRC_ARG_PRIV, + .default_cb = acme_trace, + .known_events = acme_trace_events, + .lockon_args = acme_trace_lockon_args, + .decoding = acme_trace_decoding, + .report_events = ~0, /* report everything by default */ +}; + +INITCALL1(STG_REGISTER, trace_register_source, &trace_acme); + +static void acme_trace(enum trace_level level, uint64_t mask, const struct trace_source *src, + const struct ist where, const struct ist func, + const void *a1, const void *a2, const void *a3, const void *a4) +{ + const struct acme_ctx *ctx = a1; + + if (src->verbosity <= ACME_VERB_CLEAN) + return; + + chunk_appendf(&trace_buf, " :"); + + if (mask >= ACME_EV_NEW) + chunk_appendf(&trace_buf, " acme_ctx=%p", ctx); + + + if (mask == ACME_EV_NEW) + chunk_appendf(&trace_buf, ", crt=%s", ctx->store->path); + + if (mask >= ACME_EV_TASK) { + + switch (ctx->http_state) { + case ACME_HTTP_REQ: + chunk_appendf(&trace_buf, ", http_st: ACME_HTTP_REQ"); + break; + case ACME_HTTP_RES: + chunk_appendf(&trace_buf, ", http_st: ACME_HTTP_RES"); + break; + } + chunk_appendf(&trace_buf, ", st: "); + switch (ctx->state) { + case ACME_RESOURCES: chunk_appendf(&trace_buf, "ACME_RESOURCES"); break; + case ACME_NEWNONCE: chunk_appendf(&trace_buf, "ACME_NEWNONCE"); break; + case ACME_CHKACCOUNT: chunk_appendf(&trace_buf, "ACME_CHKACCOUNT"); break; + case ACME_NEWACCOUNT: chunk_appendf(&trace_buf, "ACME_NEWACCOUNT"); break; + case ACME_NEWORDER: chunk_appendf(&trace_buf, "ACME_NEWORDER"); break; + case ACME_AUTH: chunk_appendf(&trace_buf, "ACME_AUTH"); break; + case ACME_CHALLENGE: chunk_appendf(&trace_buf, "ACME_CHALLENGE"); break; + case ACME_CHKCHALLENGE: chunk_appendf(&trace_buf, "ACME_CHKCHALLENGE"); break; + case ACME_FINALIZE: chunk_appendf(&trace_buf, "ACME_FINALIZE"); break; + case ACME_CHKORDER: chunk_appendf(&trace_buf, "ACME_CHKORDER"); break; + case ACME_CERTIFICATE: chunk_appendf(&trace_buf, "ACME_CERTIFICATE"); break; + case ACME_END: chunk_appendf(&trace_buf, "ACME_END"); break; + } + } + if (mask & (ACME_EV_REQ|ACME_EV_RES)) { + const struct ist *url = a2; + const struct buffer *buf = a3; + + if (mask & ACME_EV_REQ) + chunk_appendf(&trace_buf, " url: %.*s", (int)url->len, url->ptr); + + if (src->verbosity >= ACME_VERB_COMPLETE && level >= TRACE_LEVEL_DATA) { + chunk_appendf(&trace_buf, " Buffer Dump:\n"); + chunk_appendf(&trace_buf, "%.*s", (int)buf->data, buf->area); + } + } +} struct mt_list acme_tasks = MT_LIST_HEAD_INIT(acme_tasks); @@ -930,6 +1030,8 @@ int acme_res_certificate(struct task *task, struct acme_ctx *ctx, char **errmsg) } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + if (hc->res.status < 200 || hc->res.status >= 300) { if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.detail", t1->area, t1->size)) > -1) t1->data = ret; @@ -1001,6 +1103,8 @@ int acme_res_chkorder(struct task *task, struct acme_ctx *ctx, char **errmsg) } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + if (hc->res.status < 200 || hc->res.status >= 300) { if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.detail", t1->area, t1->size)) > -1) t1->data = ret; @@ -1130,6 +1234,8 @@ int acme_res_finalize(struct task *task, struct acme_ctx *ctx, char **errmsg) } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + if (hc->res.status < 200 || hc->res.status >= 300) { if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.detail", t1->area, t1->size)) > -1) t1->data = ret; @@ -1174,9 +1280,13 @@ int acme_req_challenge(struct task *task, struct acme_ctx *ctx, struct acme_auth chunk_printf(req_in, "{}"); + TRACE_DATA("REQ challenge dec", ACME_EV_REQ, ctx, &auth->chall, req_in); + if (acme_jws_payload(req_in, ctx->nonce, auth->chall, ctx->cfg->account.pkey, ctx->kid, req_out, errmsg) != 0) goto error; + TRACE_DATA("REQ challenge enc", ACME_EV_REQ, ctx, &auth->chall, req_out); + if (acme_http_req(task, ctx, auth->chall, HTTP_METH_POST, hdrs, ist2(req_out->area, req_out->data))) goto error; @@ -1211,6 +1321,8 @@ enum acme_ret acme_res_challenge(struct task *task, struct acme_ctx *ctx, struct hdrs = hc->res.hdrs; + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + for (hdr = hdrs; isttest(hdr->v); hdr++) { if (isteqi(hdr->n, ist("Replay-Nonce"))) { istfree(&ctx->nonce); @@ -1284,10 +1396,14 @@ int acme_post_as_get(struct task *task, struct acme_ctx *ctx, struct ist url, ch if ((req_out = alloc_trash_chunk()) == NULL) goto error_alloc; + TRACE_USER("POST-as-GET ", ACME_EV_REQ, ctx, &url); + /* empty payload */ if (acme_jws_payload(req_in, ctx->nonce, url, ctx->cfg->account.pkey, ctx->kid, req_out, errmsg) != 0) goto error_jws; + TRACE_DATA("POST-as-GET enc", ACME_EV_REQ, ctx, &url, req_out); + if (acme_http_req(task, ctx, url, HTTP_METH_POST, hdrs, ist2(req_out->area, req_out->data))) goto error_http; @@ -1342,6 +1458,7 @@ int acme_res_auth(struct task *task, struct acme_ctx *ctx, struct acme_auth *aut } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); if (hc->res.status < 200 || hc->res.status >= 300) { /* XXX: need a generic URN error parser */ @@ -1455,10 +1572,13 @@ int acme_req_neworder(struct task *task, struct acme_ctx *ctx, char **errmsg) chunk_appendf(req_in, " ] }"); + TRACE_DATA("NewOrder Decode", ACME_EV_REQ, ctx, &ctx->resources.newOrder, req_in); + if (acme_jws_payload(req_in, ctx->nonce, ctx->resources.newOrder, ctx->cfg->account.pkey, ctx->kid, req_out, errmsg) != 0) goto error; + TRACE_DATA("NewOrder JWS ", ACME_EV_REQ, ctx, &ctx->resources.newOrder, req_out); if (acme_http_req(task, ctx, ctx->resources.newOrder, HTTP_METH_POST, hdrs, ist2(req_out->area, req_out->data))) goto error; @@ -1507,6 +1627,7 @@ int acme_res_neworder(struct task *task, struct acme_ctx *ctx, char **errmsg) ctx->order = istdup(hdr->v); } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); if (hc->res.status < 200 || hc->res.status >= 300) { if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.detail", t1->area, t1->size)) > -1) @@ -1610,6 +1731,8 @@ int acme_req_account(struct task *task, struct acme_ctx *ctx, int newaccount, ch else chunk_printf(req_in, "%s", accountreq); + TRACE_DATA("newAccount Decoded", ACME_EV_REQ, ctx, &ctx->resources.newAccount, req_in); + if (acme_jws_payload(req_in, ctx->nonce, ctx->resources.newAccount, ctx->cfg->account.pkey, ctx->kid, req_out, errmsg) != 0) goto error; @@ -1659,6 +1782,8 @@ int acme_res_account(struct task *task, struct acme_ctx *ctx, int newaccount, ch } } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + if (hc->res.status < 200 || hc->res.status >= 300) { if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.detail", t1->area, t1->size)) > -1) t1->data = ret; @@ -1705,6 +1830,8 @@ int acme_nonce(struct task *task, struct acme_ctx *ctx, char **errmsg) goto error; } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + hdrs = hc->res.hdrs; for (hdr = hdrs; isttest(hdr->v); hdr++) { @@ -1743,6 +1870,8 @@ int acme_directory(struct task *task, struct acme_ctx *ctx, char **errmsg) goto error; } + TRACE_DATA(__FUNCTION__, ACME_EV_RES, ctx, NULL, &hc->res.buf); + if ((ret = mjson_get_string(hc->res.buf.area, hc->res.buf.data, "$.newNonce", trash.area, trash.size)) <= 0) { memprintf(errmsg, "couldn't get newNonce URL from the directory URL"); goto error; @@ -1806,6 +1935,7 @@ struct task *acme_process(struct task *task, void *context, unsigned int state) struct mt_list tmp = MT_LIST_LOCK_FULL(&ctx->el); re: + TRACE_USER("ACME Task Handle", ACME_EV_TASK, ctx, &st); switch (st) { case ACME_RESOURCES: @@ -1999,6 +2129,8 @@ nextreq: /* this is called when changing step in the state machine */ http_st = ACME_HTTP_REQ; ctx->retries = ACME_RETRY; /* reinit the retries */ + ctx->http_state = http_st; + ctx->state = st; if (ctx->retryafter == 0) goto re; /* optimize by not leaving the task for the next httpreq to init */ @@ -2006,8 +2138,6 @@ nextreq: /* if we have a retryafter, wait before next request (usually finalize) */ task->expire = tick_add(now_ms, ctx->retryafter * 1000); ctx->retryafter = 0; - ctx->http_state = http_st; - ctx->state = st; MT_LIST_UNLOCK_FULL(&ctx->el, tmp); return task; @@ -2133,6 +2263,7 @@ struct task *acme_scheduler(struct task *task, void *context, unsigned int state if (store->conf.acme.id) { if (acme_will_expire(store)) { + TRACE_USER("ACME Scheduling start", ACME_EV_SCHED); if (acme_start_task(store, &errmsg) != 0) { send_log(NULL, LOG_NOTICE,"acme: %s: %s Aborting.\n", store->path, errmsg ? errmsg : ""); ha_free(&errmsg); @@ -2327,6 +2458,7 @@ static int acme_start_task(struct ckch_store *store, char **errmsg) send_log(NULL, LOG_NOTICE, "acme: %s: Starting update of the certificate.\n", ctx->store->path); + TRACE_USER("ACME Task start", ACME_EV_NEW, ctx); task_wakeup(task, TASK_WOKEN_INIT); return 0;