From 8aff29f020752c96cc2ab7d111d9c33aaf55c671 Mon Sep 17 00:00:00 2001 From: "Dr. David von Oheimb" Date: Sat, 28 May 2022 18:44:02 +0200 Subject: APPS HTTP server: trace requests and responses when enabled Reviewed-by: Tomas Mraz Reviewed-by: Dmitry Belyavskiy Reviewed-by: David von Oheimb (Merged from https://github.com/openssl/openssl/pull/18434) --- apps/cmp.c | 6 +- apps/include/http_server.h | 21 +++-- apps/lib/http_server.c | 229 ++++++++++++++++++++++++++++----------------- apps/ocsp.c | 12 ++- doc/man1/openssl.pod | 2 +- 5 files changed, 168 insertions(+), 102 deletions(-) diff --git a/apps/cmp.c b/apps/cmp.c index f3624aa94a..ccfd7fcc23 100644 --- a/apps/cmp.c +++ b/apps/cmp.c @@ -2729,7 +2729,7 @@ static int cmp_server(OSSL_CMP_CTX *srv_cmp_ctx) msgs++; if (req != NULL) { if (strcmp(path, "") != 0 && strcmp(path, "pkix/") != 0) { - (void)http_server_send_status(cbio, 404, "Not Found"); + (void)http_server_send_status(prog, cbio, 404, "Not Found"); CMP_err1("expecting empty path or 'pkix/' but got '%s'", path); OPENSSL_free(path); @@ -2740,11 +2740,11 @@ static int cmp_server(OSSL_CMP_CTX *srv_cmp_ctx) resp = OSSL_CMP_CTX_server_perform(cmp_ctx, req); OSSL_CMP_MSG_free(req); if (resp == NULL) { - (void)http_server_send_status(cbio, + (void)http_server_send_status(prog, cbio, 500, "Internal Server Error"); break; /* treated as fatal error */ } - ret = http_server_send_asn1_resp(cbio, keep_alive, + ret = http_server_send_asn1_resp(prog, cbio, keep_alive, "application/pkixcmp", ASN1_ITEM_rptr(OSSL_CMP_MSG), (const ASN1_VALUE *)resp); diff --git a/apps/include/http_server.h b/apps/include/http_server.h index 060cf281bb..df4eba9238 100644 --- a/apps/include/http_server.h +++ b/apps/include/http_server.h @@ -48,13 +48,19 @@ # define LOG_ERR 3 /*- - * Log a message to syslog if multi-threaded HTTP_DAEMON, else to bio_err - * prog: the name of the current app + * Output a message using the trace API with the given category + * if the category is >= 0 and tracing is enabled. + * Log the message to syslog if multi-threaded HTTP_DAEMON, else to bio_err + * if the verbosity is sufficient for the given level of severity. + * category: trace category as defined in trace.h, or -1 + * prog: the name of the current app, or NULL * level: the severity of the message, e.g., LOG_ERR - * fmt: message with potential extra parameters like with printf() + * fmt: message format, which should not include a trailing newline + * ...: potential extra parameters like with printf() * returns nothing */ -void log_message(const char *prog, int level, const char *fmt, ...); +void trace_log_message(int category, + const char *prog, int level, const char *fmt, ...); # ifndef OPENSSL_NO_SOCK /*- @@ -92,6 +98,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, /*- * Send an ASN.1-formatted HTTP response + * prog: the name of the current app, for diagnostics only * cbio: destination BIO (typically as returned by http_server_get_asn1_req()) * note: cbio should not do an encoding that changes the output length * keep_alive: grant persistent connection @@ -100,18 +107,20 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, * resp: the response to send * returns 1 on success, 0 on failure */ -int http_server_send_asn1_resp(BIO *cbio, int keep_alive, +int http_server_send_asn1_resp(const char *prog, BIO *cbio, int keep_alive, const char *content_type, const ASN1_ITEM *it, const ASN1_VALUE *resp); /*- * Send a trivial HTTP response, typically to report an error or OK + * prog: the name of the current app, for diagnostics only * cbio: destination BIO (typically as returned by http_server_get_asn1_req()) * status: the status code to send * reason: the corresponding human-readable string * returns 1 on success, 0 on failure */ -int http_server_send_status(BIO *cbio, int status, const char *reason); +int http_server_send_status(const char *prog, BIO *cbio, + int status, const char *reason); # endif diff --git a/apps/lib/http_server.c b/apps/lib/http_server.c index 8783221e39..ba72a6c14a 100644 --- a/apps/lib/http_server.c +++ b/apps/lib/http_server.c @@ -21,6 +21,7 @@ #include "http_server.h" #include "internal/sockets.h" #include +#include #include #include "s_apps.h" @@ -40,7 +41,7 @@ static int verbosity = LOG_INFO; #ifdef HTTP_DAEMON -int multi = 0; /* run multiple responder processes */ +int multi = 0; /* run multiple responder processes, set by ocsp.c */ int acfd = (int) INVALID_SOCKET; static int print_syslog(const char *str, size_t len, void *levPtr) @@ -54,33 +55,59 @@ static int print_syslog(const char *str, size_t len, void *levPtr) } #endif -void log_message(const char *prog, int level, const char *fmt, ...) +static void log_with_prefix(const char *prog, const char *fmt, va_list ap) { - va_list ap; + char prefix[80]; + BIO *bio, *pre = BIO_new(BIO_f_prefix()); + + (void)snprintf(prefix, sizeof(prefix), "%s: ", prog); + (void)BIO_set_prefix(pre, prefix); + bio = BIO_push(pre, bio_err); + (void)BIO_vprintf(bio, fmt, ap); + (void)BIO_printf(bio, "\n"); + (void)BIO_flush(bio); + (void)BIO_pop(pre); + BIO_free(pre); +} - if (verbosity < level) - return; +void trace_log_message(int category, + const char *prog, int level, const char *fmt, ...) +{ + va_list ap; va_start(ap, fmt); + if (category >= 0 && OSSL_trace_enabled(category)) { + va_list ap_copy; + BIO *out = OSSL_trace_begin(category); + + va_copy(ap_copy, ap); + (void)BIO_vprintf(out, fmt, ap_copy); + (void)BIO_printf(out, "\n"); + va_end(ap_copy); + OSSL_trace_end(category, out); + } + if (verbosity < level) { + va_end(ap); + return; + } #ifdef HTTP_DAEMON - if (multi) { - char buf[1024]; - - if (vsnprintf(buf, sizeof(buf), fmt, ap) > 0) - syslog(level, "%s", buf); + if (multi != 0) { + vsyslog(level, fmt, ap); if (level <= LOG_ERR) ERR_print_errors_cb(print_syslog, &level); } else #endif - { - BIO_printf(bio_err, "%s: ", prog); - BIO_vprintf(bio_err, fmt, ap); - BIO_printf(bio_err, "\n"); - (void)BIO_flush(bio_err); - } + log_with_prefix(prog, fmt, ap); va_end(ap); } +#define log_HTTP(prog, level, text) \ + trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, "%s", text) +#define log_HTTP1(prog, level, fmt, arg) \ + trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, fmt, arg) +#define log_HTTP2(prog, level, fmt, arg1, arg2) \ + trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, fmt, arg1, arg2) + #ifdef HTTP_DAEMON void socket_timeout(int signum) { @@ -152,7 +179,7 @@ void spawn_loop(const char *prog) if (i >= multi) { syslog(LOG_ERR, "fatal: internal error: " "no matching child slot for pid: %ld", - (long) fpid); + (long)fpid); killall(1, kidpids); } if (status != 0) { @@ -224,8 +251,8 @@ BIO *http_server_init(const char *prog, const char *port, int verb) if (verb >= 0) { if (verb > LOG_TRACE) { - log_message(prog, LOG_ERR, - "Logging verbosity level %d too high", verb); + log_HTTP1(prog, LOG_ERR, + "Logging verbosity level %d too high", verb); return NULL; } verbosity = verb; @@ -237,14 +264,14 @@ BIO *http_server_init(const char *prog, const char *port, int verb) if (acbio == NULL || BIO_set_bind_mode(acbio, BIO_BIND_REUSEADDR) < 0 || BIO_set_accept_port(acbio, port /* may be "0" */) < 0) { - log_message(prog, LOG_ERR, "Error setting up accept BIO"); + log_HTTP(prog, LOG_ERR, "Error setting up accept BIO"); goto err; } BIO_set_accept_bios(acbio, bufbio); bufbio = NULL; if (BIO_do_accept(acbio) <= 0) { - log_message(prog, LOG_ERR, "Error starting accept"); + log_HTTP(prog, LOG_ERR, "Error starting accept"); goto err; } @@ -252,7 +279,7 @@ BIO *http_server_init(const char *prog, const char *port, int verb) BIO_get_fd(acbio, &asock); port_num = report_server_accept(bio_out, asock, 1, 1); if (port_num == 0) { - log_message(prog, LOG_ERR, "Error printing ACCEPT string"); + log_HTTP(prog, LOG_ERR, "Error printing ACCEPT string"); goto err; } @@ -311,11 +338,11 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, get_sock_info_address(BIO_get_fd(acbio, NULL), NULL, &port); if (port == NULL) { - log_message(prog, LOG_ERR, "Cannot get port listening on"); + log_HTTP(prog, LOG_ERR, "Cannot get port listening on"); goto fatal; } - log_message(prog, LOG_DEBUG, - "Awaiting new connection on port %s ...", port); + log_HTTP1(prog, LOG_DEBUG, + "Awaiting new connection on port %s ...", port); OPENSSL_free(port); if (BIO_do_accept(acbio) <= 0) @@ -324,10 +351,10 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, *pcbio = cbio = BIO_pop(acbio); } else { - log_message(prog, LOG_DEBUG, "Awaiting next request ..."); + log_HTTP(prog, LOG_DEBUG, "Awaiting next request ..."); } if (cbio == NULL) { - /* Cannot call http_server_send_status(cbio, ...) */ + /* Cannot call http_server_send_status(..., cbio, ...) */ ret = -1; goto out; } @@ -345,14 +372,25 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, return ret; ret = 1; if (len < 0) { - log_message(prog, LOG_WARNING, "Request line read error"); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP(prog, LOG_WARNING, "Request line read error"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } - if ((end = strchr(reqbuf, '\r')) != NULL + + if (((end = strchr(reqbuf, '\r')) != NULL && end[1] == '\n') || (end = strchr(reqbuf, '\n')) != NULL) *end = '\0'; - log_message(prog, LOG_INFO, "Received request, 1st line: %s", reqbuf); + if (verbosity < LOG_TRACE) + trace_log_message(-1, prog, LOG_INFO, + "Received request, 1st line: %s", reqbuf); + log_HTTP(prog, LOG_TRACE, "Received request header:"); + log_HTTP1(prog, LOG_TRACE, "%s", reqbuf); + if (end == NULL) { + log_HTTP(prog, LOG_WARNING, + "Error parsing HTTP header: missing end of line"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); + goto out; + } url = meth = reqbuf; if ((accept_get && CHECK_AND_SKIP_PREFIX(url, "GET ")) @@ -363,10 +401,10 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, while (*url == ' ') url++; if (*url != '/') { - log_message(prog, LOG_WARNING, - "Invalid %s -- URL does not begin with '/': %s", - meth, url); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP2(prog, LOG_WARNING, + "Invalid %s -- URL does not begin with '/': %s", + meth, url); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } url++; @@ -376,10 +414,10 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, if (*end == ' ') break; if (!HAS_PREFIX(end, HTTP_VERSION_STR)) { - log_message(prog, LOG_WARNING, - "Invalid %s -- bad HTTP/version string: %s", - meth, end + 1); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP2(prog, LOG_WARNING, + "Invalid %s -- bad HTTP/version string: %s", + meth, end + 1); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } *end = '\0'; @@ -393,34 +431,32 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, * the leading slash, so in case 'GET / ' it is now an empty string. */ if (strlen(meth) == 3 && url[0] == '\0') { - (void)http_server_send_status(cbio, 200, "OK"); + (void)http_server_send_status(prog, cbio, 200, "OK"); goto out; } len = urldecode(url); if (len < 0) { - log_message(prog, LOG_WARNING, - "Invalid %s request -- bad URL encoding: %s", - meth, url); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP2(prog, LOG_WARNING, + "Invalid %s request -- bad URL encoding: %s", meth, url); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } if (strlen(meth) == 3) { /* GET */ if ((getbio = BIO_new_mem_buf(url, len)) == NULL || (b64 = BIO_new(BIO_f_base64())) == NULL) { - log_message(prog, LOG_ERR, - "Could not allocate base64 bio with size = %d", - len); + log_HTTP1(prog, LOG_ERR, + "Could not allocate base64 bio with size = %d", len); goto fatal; } BIO_set_flags(b64, BIO_FLAGS_BASE64_NO_NL); getbio = BIO_push(b64, getbio); } } else { - log_message(prog, LOG_WARNING, - "HTTP request does not begin with %sPOST: %s", - accept_get ? "GET or " : "", reqbuf); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP2(prog, LOG_WARNING, + "HTTP request does not begin with %sPOST: %s", + accept_get ? "GET or " : "", reqbuf); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } @@ -433,40 +469,41 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, /* Read and skip past the headers. */ for (;;) { - char *key, *value, *line_end = NULL; + char *key, *value; len = BIO_gets(cbio, inbuf, sizeof(inbuf)); if (len <= 0) { - log_message(prog, LOG_WARNING, "Error reading HTTP header"); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP(prog, LOG_WARNING, "Error reading HTTP header"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); + goto out; + } + + if (((end = strchr(inbuf, '\r')) != NULL && end[1] == '\n') + || (end = strchr(inbuf, '\n')) != NULL) + *end = '\0'; + log_HTTP1(prog, LOG_TRACE, "%s", *inbuf == '\0' ? + " " /* workaround for "" getting ignored */ : inbuf); + if (end == NULL) { + log_HTTP(prog, LOG_WARNING, + "Error parsing HTTP header: missing end of line"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } - if (inbuf[0] == '\r' || inbuf[0] == '\n') + if (inbuf[0] == '\0') break; key = inbuf; value = strchr(key, ':'); if (value == NULL) { - log_message(prog, LOG_WARNING, - "Error parsing HTTP header: missing ':'"); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP(prog, LOG_WARNING, + "Error parsing HTTP header: missing ':'"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); goto out; } *(value++) = '\0'; while (*value == ' ') value++; - line_end = strchr(value, '\r'); - if (line_end == NULL) { - line_end = strchr(value, '\n'); - if (line_end == NULL) { - log_message(prog, LOG_WARNING, - "Error parsing HTTP header: missing end of line"); - (void)http_server_send_status(cbio, 400, "Bad Request"); - goto out; - } - } - *line_end = '\0'; /* https://tools.ietf.org/html/rfc7230#section-6.3 Persistence */ if (found_keep_alive != NULL && OPENSSL_strcasecmp(key, "Connection") == 0) { @@ -486,12 +523,12 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, /* Try to read and parse request */ req = ASN1_item_d2i_bio(it, getbio != NULL ? getbio : cbio, NULL); if (req == NULL) { - log_message(prog, LOG_WARNING, - "Error parsing DER-encoded request content"); - (void)http_server_send_status(cbio, 400, "Bad Request"); + log_HTTP(prog, LOG_WARNING, + "Error parsing DER-encoded request content"); + (void)http_server_send_status(prog, cbio, 400, "Bad Request"); } else if (ppath != NULL && (*ppath = OPENSSL_strdup(url)) == NULL) { - log_message(prog, LOG_ERR, - "Out of memory allocating %zu bytes", strlen(url) + 1); + log_HTTP1(prog, LOG_ERR, + "Out of memory allocating %zu bytes", strlen(url) + 1); ASN1_item_free(req, it); goto fatal; } @@ -508,7 +545,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, return ret; fatal: - (void)http_server_send_status(cbio, 500, "Internal Server Error"); + (void)http_server_send_status(prog, cbio, 500, "Internal Server Error"); if (ppath != NULL) { OPENSSL_free(*ppath); *ppath = NULL; @@ -520,28 +557,46 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq, } /* assumes that cbio does not do an encoding that changes the output length */ -int http_server_send_asn1_resp(BIO *cbio, int keep_alive, +int http_server_send_asn1_resp(const char *prog, BIO *cbio, int keep_alive, const char *content_type, const ASN1_ITEM *it, const ASN1_VALUE *resp) { - int ret = BIO_printf(cbio, HTTP_1_0" 200 OK\r\n%s" - "Content-type: %s\r\n" - "Content-Length: %d\r\n\r\n", - keep_alive ? "Connection: keep-alive\r\n" : "", - content_type, - ASN1_item_i2d(resp, NULL, it)) > 0 - && ASN1_item_i2d_bio(it, cbio, resp) > 0; + char buf[200], *p; + int ret = snprintf(buf, sizeof(buf), HTTP_1_0" 200 OK\r\n%s" + "Content-type: %s\r\n" + "Content-Length: %d\r\n", + keep_alive ? "Connection: keep-alive\r\n" : "", + content_type, + ASN1_item_i2d(resp, NULL, it)); + + if (ret < 0 || (size_t)ret >= sizeof(buf)) + return 0; + if (verbosity < LOG_TRACE && (p = strchr(buf, '\r')) != NULL) + trace_log_message(-1, prog, LOG_INFO, + "Sending response, 1st line: %.*s", (int)(p - buf), + buf); + log_HTTP1(prog, LOG_TRACE, "Sending response header:\n%s", buf); + + ret = BIO_printf(cbio, "%s\r\n", buf) > 0 + && ASN1_item_i2d_bio(it, cbio, resp) > 0; (void)BIO_flush(cbio); return ret; } -int http_server_send_status(BIO *cbio, int status, const char *reason) +int http_server_send_status(const char *prog, BIO *cbio, + int status, const char *reason) { - int ret = BIO_printf(cbio, HTTP_1_0" %d %s\r\n\r\n", - /* This implicitly cancels keep-alive */ - status, reason) > 0; + char buf[200]; + int ret = snprintf(buf, sizeof(buf), HTTP_1_0" %d %s\r\n\r\n", + /* This implicitly cancels keep-alive */ + status, reason); + + if (ret < 0 || (size_t)ret >= sizeof(buf)) + return 0; + log_HTTP1(prog, LOG_TRACE, "Sending response header:\n%s", buf); + ret = BIO_printf(cbio, "%s\r\n", buf) > 0; (void)BIO_flush(cbio); return ret; } diff --git a/apps/ocsp.c b/apps/ocsp.c index b1a86dcf5b..297b10c861 100644 --- a/apps/ocsp.c +++ b/apps/ocsp.c @@ -633,14 +633,15 @@ int ocsp_main(int argc, char **argv) } #ifdef HTTP_DAEMON - if (multi && acbio != NULL) + if (multi != 0 && acbio != NULL) spawn_loop(prog); if (acbio != NULL && req_timeout > 0) signal(SIGALRM, socket_timeout); #endif if (acbio != NULL) - log_message(prog, LOG_INFO, "waiting for OCSP client connections..."); + trace_log_message(-1, prog, + LOG_INFO, "waiting for OCSP client connections..."); redo_accept: @@ -654,8 +655,9 @@ redo_accept: rdb = newrdb; } else { free_index(newrdb); - log_message(prog, LOG_ERR, "error reloading updated index: %s", - ridx_filename); + trace_log_message(-1, prog, + LOG_ERR, "error reloading updated index: %s", + ridx_filename); } } #endif @@ -1217,7 +1219,7 @@ static int do_responder(OCSP_REQUEST **preq, BIO **pcbio, BIO *acbio, static int send_ocsp_response(BIO *cbio, const OCSP_RESPONSE *resp) { #ifndef OPENSSL_NO_SOCK - return http_server_send_asn1_resp(cbio, + return http_server_send_asn1_resp(prog, cbio, 0 /* no keep-alive */, "application/ocsp-response", ASN1_ITEM_rptr(OCSP_RESPONSE), diff --git a/doc/man1/openssl.pod b/doc/man1/openssl.pod index ce24fa6141..3129967307 100644 --- a/doc/man1/openssl.pod +++ b/doc/man1/openssl.pod @@ -769,7 +769,7 @@ Traces decrementing certain ASN.1 structure references. =item B -Traces the HTTP client, such as message headers being sent and received. +Traces the HTTP client and server, such as messages being sent and received. =back -- cgit v1.2.3