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>

docs/changes.xml

@@ -32,6 +32,12 @@ NGINX Unit updated to 1.30.0.
          date="" time=""
          packager="Nginx Packaging <nginx-packaging@f5.com>">
 
+<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.

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

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

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 */

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;
         }

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;
     }

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),
+    },
 };
 
 

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;