HTTP test server: Improve connection management and logging

Reviewed-by: Tomas Mraz <tomas@openssl.org>
(Merged from https://github.com/openssl/openssl/pull/15053)

3 files changed, 54 insertions, 28 deletions

diff --git a/apps/cmp.c b/apps/cmp.c
index f64cb8c813..d0d18c69ca 100644
--- a/apps/cmp.c
+++ b/apps/cmp.c
@@ -2540,6 +2540,7 @@ int cmp_main(int argc, char **argv)
     X509 *newcert = NULL;
     ENGINE *engine = NULL;
     char mock_server[] = "mock server:1";
+    OSSL_CMP_CTX *srv_cmp_ctx = NULL;
     int ret = 0; /* default: failure */
 
     prog = opt_appname(argv[0]);
@@ -2651,12 +2652,13 @@ int cmp_main(int argc, char **argv)
 
         if ((srv_ctx = setup_srv_ctx(engine)) == NULL)
             goto err;
+        srv_cmp_ctx = OSSL_CMP_SRV_CTX_get0_cmp_ctx(srv_ctx);
         OSSL_CMP_CTX_set_transfer_cb_arg(cmp_ctx, srv_ctx);
-        if (!OSSL_CMP_CTX_set_log_cb(OSSL_CMP_SRV_CTX_get0_cmp_ctx(srv_ctx),
-                                     print_to_bio_out)) {
+        if (!OSSL_CMP_CTX_set_log_cb(srv_cmp_ctx, print_to_bio_out)) {
             CMP_err1("cannot set up error reporting and logging for %s", prog);
             goto err;
         }
+        OSSL_CMP_CTX_set_log_verbosity(srv_cmp_ctx, opt_verbosity);
     }
 
 
@@ -2667,6 +2669,7 @@ int cmp_main(int argc, char **argv)
         BIO *acbio;
         BIO *cbio = NULL;
         int msgs = 0;
+        int retry = 1;
 
         if ((acbio = http_server_init_bio(prog, opt_port)) == NULL)
             goto err;
@@ -2678,10 +2681,17 @@ int cmp_main(int argc, char **argv)
             ret = http_server_get_asn1_req(ASN1_ITEM_rptr(OSSL_CMP_MSG),
                                            (ASN1_VALUE **)&req, &path,
                                            &cbio, acbio, prog, 0, 0);
-            if (ret == 0)
-                continue;
-            if (ret++ == -1)
-                break; /* fatal error */
+            if (ret == 0) { /* no request yet */
+                if (retry) {
+                    sleep(1);
+                    retry = 0;
+                    continue;
+                }
+                ret = 0;
+                goto next;
+            }
+            if (ret++ == -1) /* fatal error */
+                break;
 
             ret = 0;
             msgs++;
@@ -2692,7 +2702,7 @@ int cmp_main(int argc, char **argv)
                              path);
                     OPENSSL_free(path);
                     OSSL_CMP_MSG_free(req);
-                    goto cont;
+                    goto next;
                 }
                 OPENSSL_free(path);
                 resp = OSSL_CMP_CTX_server_perform(cmp_ctx, req);
@@ -2708,10 +2718,12 @@ int cmp_main(int argc, char **argv)
                 OSSL_CMP_MSG_free(resp);
                 if (!ret)
                     break; /* treated as fatal error */
-            } else {
-                (void)http_server_send_status(cbio, 400, "Bad Request");
             }
-        cont:
+        next:
+            if (!ret) { /* on transmission error, cancel CMP transaction */
+                (void)OSSL_CMP_CTX_set1_transactionID(srv_cmp_ctx, NULL);
+                (void)OSSL_CMP_CTX_set1_senderNonce(srv_cmp_ctx, NULL);
+            }
             BIO_free_all(cbio);
             cbio = NULL;
         }
diff --git a/apps/include/http_server.h b/apps/include/http_server.h
index 1264753899..9520eb4dac 100644
--- a/apps/include/http_server.h
+++ b/apps/include/http_server.h
@@ -35,12 +35,14 @@
 #  include <signal.h>
 #  define MAXERRLEN 1000 /* limit error text sent to syslog to 1000 bytes */
 # else
+#  undef LOG_DEBUG
 #  undef LOG_INFO
 #  undef LOG_WARNING
 #  undef LOG_ERR
-#  define LOG_INFO      0
-#  define LOG_WARNING   1
-#  define LOG_ERR       2
+#  define LOG_DEBUG     7
+#  define LOG_INFO      6
+#  define LOG_WARNING   4
+#  define LOG_ERR       3
 # endif
 
 /*-
diff --git a/apps/lib/http_server.c b/apps/lib/http_server.c
index 7626ca9aa4..0bdc4bc316 100644
--- a/apps/lib/http_server.c
+++ b/apps/lib/http_server.c
@@ -30,6 +30,7 @@
 # endif
 #endif
 
+static int verbosity = LOG_INFO;
 #ifdef HTTP_DAEMON
 int multi = 0; /* run multiple responder processes */
 int acfd = (int) INVALID_SOCKET;
@@ -49,6 +50,9 @@ void log_message(const char *prog, int level, const char *fmt, ...)
 {
     va_list ap;
 
+    if (verbosity < level)
+        return;
+
     va_start(ap, fmt);
 #ifdef HTTP_DAEMON
     if (multi) {
@@ -56,7 +60,7 @@ void log_message(const char *prog, int level, const char *fmt, ...)
 
         if (vsnprintf(buf, sizeof(buf), fmt, ap) > 0)
             syslog(level, "%s", buf);
-        if (level >= LOG_ERR)
+        if (level <= LOG_ERR)
             ERR_print_errors_cb(print_syslog, &level);
     } else
 #endif
@@ -64,6 +68,7 @@ void log_message(const char *prog, int level, const char *fmt, ...)
         BIO_printf(bio_err, "%s: ", prog);
         BIO_vprintf(bio_err, fmt, ap);
         BIO_printf(bio_err, "\n");
+        (void)BIO_flush(bio_err);
     }
     va_end(ap);
 }
@@ -266,19 +271,19 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
     char reqbuf[2048], inbuf[2048];
     char *meth, *url, *end;
     ASN1_VALUE *req;
-    int ret = 1;
+    int ret = 0;
 
     *preq = NULL;
     if (ppath != NULL)
         *ppath = NULL;
     *pcbio = NULL;
 
-    /* Connection loss before accept() is routine, ignore silently */
+    log_message(prog, LOG_DEBUG, "Awaiting next request...");
+/* Connection loss before accept() is routine, ignore silently */
     if (BIO_do_accept(acbio) <= 0)
-        return 0;
+        return ret;
 
-    cbio = BIO_pop(acbio);
-    *pcbio = cbio;
+    *pcbio = cbio = BIO_pop(acbio);
     if (cbio == NULL) {
         /* Cannot call http_server_send_status(cbio, ...) */
         ret = -1;
@@ -294,12 +299,18 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
 
     /* Read the request line. */
     len = BIO_gets(cbio, reqbuf, sizeof(reqbuf));
-    if (len <= 0) {
-        log_message(prog, LOG_INFO,
-                    "Request line read error or empty request");
+    if (len == 0)
+        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");
         goto out;
     }
+    if ((end = strchr(reqbuf, '\r')) != NULL
+            || (end = strchr(reqbuf, '\n')) != NULL)
+        *end = '\0';
+    log_message(prog, LOG_INFO, "Received request, 1st line: %s", reqbuf);
 
     meth = reqbuf;
     url = meth + 3;
@@ -310,7 +321,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
         while (*url == ' ')
             url++;
         if (*url != '/') {
-            log_message(prog, LOG_INFO,
+            log_message(prog, LOG_WARNING,
                         "Invalid %s -- URL does not begin with '/': %s",
                         meth, url);
             (void)http_server_send_status(cbio, 400, "Bad Request");
@@ -323,7 +334,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
             if (*end == ' ')
                 break;
         if (strncmp(end, " HTTP/1.", 7) != 0) {
-            log_message(prog, LOG_INFO,
+            log_message(prog, LOG_WARNING,
                         "Invalid %s -- bad HTTP/version string: %s",
                         meth, end + 1);
             (void)http_server_send_status(cbio, 400, "Bad Request");
@@ -343,7 +354,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
 
         len = urldecode(url);
         if (len < 0) {
-            log_message(prog, LOG_INFO,
+            log_message(prog, LOG_WARNING,
                         "Invalid %s request -- bad URL encoding: %s",
                         meth, url);
             (void)http_server_send_status(cbio, 400, "Bad Request");
@@ -361,7 +372,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
             getbio = BIO_push(b64, getbio);
         }
     } else {
-        log_message(prog, LOG_INFO,
+        log_message(prog, LOG_WARNING,
                     "HTTP request does not start with GET/POST: %s", reqbuf);
         /* TODO provide better diagnosis in case client tries TLS */
         (void)http_server_send_status(cbio, 400, "Bad Request");
@@ -379,7 +390,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
     for (;;) {
         len = BIO_gets(cbio, inbuf, sizeof(inbuf));
         if (len <= 0) {
-            log_message(prog, LOG_ERR,
+            log_message(prog, LOG_WARNING,
                         "Error skipping remaining HTTP headers");
             (void)http_server_send_status(cbio, 400, "Bad Request");
             goto out;
@@ -397,7 +408,8 @@ 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_ERR, "Error parsing request");
+        log_message(prog, LOG_WARNING, "Error parsing DER-encoded request content");
+        (void)http_server_send_status(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);