openssl
/
openssl
mirror of https://github.com/openssl/openssl
1
0
Fork 0
Code Issues Releases Wiki Activity

APPS HTTP server: trace requests and responses when enabled 

Reviewed-by: Tomas Mraz <tomas@openssl.org>
Reviewed-by: Dmitry Belyavskiy <beldmit@gmail.com>
Reviewed-by: David von Oheimb <david.von.oheimb@siemens.com>
(Merged from https://github.com/openssl/openssl/pull/18434)
This commit is contained in:
Dr. David von Oheimb 2022-05-28 18:44:02 +02:00 committed by Dr. David von Oheimb
parent 5d0a327020
commit 8aff29f020
5 changed files with 168 additions and 102 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
apps/cmp.c
View File

@ -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);

21
apps/include/http_server.h
View File

@ -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

229
apps/lib/http_server.c
View File

@ -21,6 +21,7 @@
#include "http_server.h"
#include "internal/sockets.h"
#include <openssl/err.h>
#include <openssl/trace.h>
#include <openssl/rand.h>
#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)
{
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);
}
void trace_log_message(int category,
const char *prog, int level, const char *fmt, ...)
{
va_list ap;
if (verbosity < level)
return;
va_start(ap, fmt);
#ifdef HTTP_DAEMON
if (multi) {
char buf[1024];
if (category >= 0 && OSSL_trace_enabled(category)) {
va_list ap_copy;
BIO *out = OSSL_trace_begin(category);
if (vsnprintf(buf, sizeof(buf), fmt, ap) > 0)
syslog(level, "%s", buf);
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 != 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 (inbuf[0] == '\r' || inbuf[0] == '\n')
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] == '\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;
}

12
apps/ocsp.c
View File

@ -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),

2
doc/man1/openssl.pod
View File

@ -769,7 +769,7 @@ Traces decrementing certain ASN.1 structure references.
=item B<HTTP>
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