HTTP: added route logging.

-  Configuration: added "/config/settings/http/log_route".

   Type: bool
   Default: false

   This adds configurability to the error log.  It allows enabling and
   disabling logs related to how the router performs selection of the
   routes.

-  HTTP: logging request line.

   Log level: [notice]

   The request line is essential to understand which logs correspond to
   which request when reading the logs.

-  HTTP: logging route that's been discarded.

   Log level: [info]

-  HTTP: logging route whose action is selected.

   Log level: [notice]

-  HTTP: logging when "fallback" action is taken.

   Log level: [notice]

Closes: <https://github.com/nginx/unit/issues/758>
Link: <https://github.com/nginx/unit/pull/824>
Link: <https://github.com/nginx/unit/pull/839>
Suggested-by: Timo Stark <t.stark@nginx.com>
Suggested-by: Mark L Wood-Patrick <mwoodpatrick@gmail.com>
Suggested-by: Liam Crilly <liam@nginx.com>
Tested-by: Liam Crilly <liam@nginx.com>
Acked-by: Artem Konev <a.konev@f5.com>
Cc: Andrew Clayton <a.clayton@nginx.com>
Cc: Andrei Zeliankou <zelenkov@nginx.com>
Reviewed-by: Zhidao Hong <z.hong@f5.com>
Signed-off-by: Alejandro Colomar <alx@nginx.com>

8 files changed, 43 insertions, 0 deletions

diff --git a/docs/changes.xml b/docs/changes.xml
index fa60a965..740a51a5 100644
--- a/docs/changes.xml
+++ b/docs/changes.xml
@@ -34,6 +34,12 @@ NGINX Unit updated to 1.30.0.
 
 <change type="feature">
 <para>
+added conditional logging of route selection for HTTP requests.
+</para>
+</change>
+
+<change type="feature">
+<para>
 support the keys API on the request objects in NJS.
 </para>
 </change>
diff --git a/src/nxt_conf_validation.c b/src/nxt_conf_validation.c
index 537a3fb7..9169bcc9 100644
--- a/src/nxt_conf_validation.c
+++ b/src/nxt_conf_validation.c
@@ -344,6 +344,9 @@ static nxt_conf_vldt_object_t  nxt_conf_vldt_http_members[] = {
         .type       = NXT_CONF_VLDT_OBJECT,
         .validator  = nxt_conf_vldt_object,
         .u.members  = nxt_conf_vldt_static_members,
+    }, {
+        .name       = nxt_string("log_route"),
+        .type       = NXT_CONF_VLDT_BOOLEAN,
     },
 
     NXT_CONF_VLDT_END
diff --git a/src/nxt_h1proto.c b/src/nxt_h1proto.c
index 1e37273f..40b10af0 100644
--- a/src/nxt_h1proto.c
+++ b/src/nxt_h1proto.c
@@ -507,6 +507,7 @@ nxt_h1p_conn_request_init(nxt_task_t *task, void *obj, void *data)
 
             r->conf = joint;
             skcf = joint->socket_conf;
+            r->log_route = skcf->log_route;
 
             if (c->local == NULL) {
                 c->local = skcf->sockaddr;
@@ -653,6 +654,11 @@ nxt_h1p_header_process(nxt_task_t *task, nxt_h1proto_t *h1p,
     r->path = &h1p->parser.path;
     r->args = &h1p->parser.args;
 
+    if (nxt_slow_path(r->log_route)) {
+        nxt_log(task, NXT_LOG_NOTICE, "http request line \"%V %V %V\"",
+                r->method, &r->target, &r->version);
+    }
+
     r->fields = h1p->parser.fields;
 
     ret = nxt_http_fields_process(r->fields, &nxt_h1p_fields_hash, r);
diff --git a/src/nxt_http.h b/src/nxt_http.h
index a8725d9f..ffd3f601 100644
--- a/src/nxt_http.h
+++ b/src/nxt_http.h
@@ -189,6 +189,8 @@ struct nxt_http_request_s {
 
     nxt_http_status_t               status:16;
 
+    uint8_t                         log_route;    /* 1 bit */
+
     uint8_t                         pass_count;   /* 8 bits */
     uint8_t                         app_target;
     nxt_http_protocol_t             protocol:8;   /* 2 bits */
diff --git a/src/nxt_http_route.c b/src/nxt_http_route.c
index a4dd8f4a..f439c957 100644
--- a/src/nxt_http_route.c
+++ b/src/nxt_http_route.c
@@ -1548,6 +1548,18 @@ nxt_http_route_handler(nxt_task_t *task, nxt_http_request_t *r,
 
     for (i = 0; i < route->items; i++) {
         action = nxt_http_route_match(task, r, route->match[i]);
+
+        if (nxt_slow_path(r->log_route)) {
+            uint32_t    lvl = (action == NULL) ? NXT_LOG_INFO : NXT_LOG_NOTICE;
+            const char  *sel = (action == NULL) ? "discarded" : "selected";
+
+            if (route->name.length == 0) {
+                nxt_log(task, lvl, "\"routes/%z\" %s", i, sel);
+            } else {
+                nxt_log(task, lvl, "\"routes/%V/%z\" %s", &route->name, i, sel);
+            }
+        }
+
         if (action != NULL) {
             return action;
         }
diff --git a/src/nxt_http_static.c b/src/nxt_http_static.c
index 68174b9d..5e44aab4 100644
--- a/src/nxt_http_static.c
+++ b/src/nxt_http_static.c
@@ -196,6 +196,9 @@ nxt_http_static(nxt_task_t *task, nxt_http_request_t *r,
 
         if (!nxt_str_eq(r->method, "HEAD", 4)) {
             if (action->fallback != NULL) {
+                if (nxt_slow_path(r->log_route)) {
+                    nxt_log(task, NXT_LOG_NOTICE, "\"fallback\" taken");
+                }
                 return action->fallback;
             }
 
@@ -690,6 +693,9 @@ nxt_http_static_next(nxt_task_t *task, nxt_http_request_t *r,
     }
 
     if (action->fallback != NULL) {
+        if (nxt_slow_path(r->log_route)) {
+            nxt_log(task, NXT_LOG_NOTICE, "\"fallback\" taken");
+        }
         nxt_http_request_action(task, r, action->fallback);
         return;
     }
diff --git a/src/nxt_router.c b/src/nxt_router.c
index baede83b..992cc039 100644
--- a/src/nxt_router.c
+++ b/src/nxt_router.c
@@ -1513,6 +1513,12 @@ static nxt_conf_map_t  nxt_router_http_conf[] = {
         NXT_CONF_MAP_INT8,
         offsetof(nxt_socket_conf_t, discard_unsafe_fields),
     },
+
+    {
+        nxt_string("log_route"),
+        NXT_CONF_MAP_INT8,
+        offsetof(nxt_socket_conf_t, log_route),
+    },
 };
 
 
diff --git a/src/nxt_router.h b/src/nxt_router.h
index 11094960..64095b69 100644
--- a/src/nxt_router.h
+++ b/src/nxt_router.h
@@ -197,6 +197,8 @@ typedef struct {
 
     nxt_str_t              body_temp_path;
 
+    uint8_t                log_route;  /* 1 bit */
+
     uint8_t                discard_unsafe_fields;  /* 1 bit */
 
     nxt_http_forward_t     *forwarded;