Log: customizable access log format.

8 files changed, 238 insertions, 130 deletions

diff --git a/docs/changes.xml b/docs/changes.xml
index 3ff434aa..68498278 100644
--- a/docs/changes.xml
+++ b/docs/changes.xml
@@ -62,6 +62,12 @@ variable substitution.
 </para>
 </change>
 
+<change type="feature">
+<para>
+customizable access log format.
+</para>
+</change>
+
 <change type="bugfix">
 <para>
 an index file that didn't contain a file extension was incorrectly
diff --git a/src/nxt_conf_validation.c b/src/nxt_conf_validation.c
index 8c532914..3e89d775 100644
--- a/src/nxt_conf_validation.c
+++ b/src/nxt_conf_validation.c
@@ -202,6 +202,8 @@ static nxt_int_t nxt_conf_vldt_server(nxt_conf_validation_t *vldt,
     nxt_str_t *name, nxt_conf_value_t *value);
 static nxt_int_t nxt_conf_vldt_server_weight(nxt_conf_validation_t *vldt,
     nxt_conf_value_t *value, void *data);
+static nxt_int_t nxt_conf_vldt_access_log(nxt_conf_validation_t *vldt,
+    nxt_conf_value_t *value, void *data);
 
 static nxt_int_t nxt_conf_vldt_isolation(nxt_conf_validation_t *vldt,
     nxt_conf_value_t *value, void *data);
@@ -241,6 +243,7 @@ static nxt_conf_vldt_object_t  nxt_conf_vldt_app_namespaces_members[];
 #if (NXT_HAVE_ISOLATION_ROOTFS)
 static nxt_conf_vldt_object_t  nxt_conf_vldt_app_automount_members[];
 #endif
+static nxt_conf_vldt_object_t  nxt_conf_vldt_access_log_members[];
 
 
 static nxt_conf_vldt_object_t  nxt_conf_vldt_root_members[] = {
@@ -270,7 +273,8 @@ static nxt_conf_vldt_object_t  nxt_conf_vldt_root_members[] = {
         .u.object   = nxt_conf_vldt_upstream,
     }, {
         .name       = nxt_string("access_log"),
-        .type       = NXT_CONF_VLDT_STRING,
+        .type       = NXT_CONF_VLDT_STRING | NXT_CONF_VLDT_OBJECT,
+        .validator  = nxt_conf_vldt_access_log,
     },
 
     NXT_CONF_VLDT_END
@@ -1205,6 +1209,19 @@ static nxt_conf_vldt_object_t  nxt_conf_vldt_upstream_server_members[] = {
 };
 
 
+static nxt_conf_vldt_object_t  nxt_conf_vldt_access_log_members[] = {
+    {
+        .name       = nxt_string("path"),
+        .type       = NXT_CONF_VLDT_STRING,
+    }, {
+        .name       = nxt_string("format"),
+        .type       = NXT_CONF_VLDT_STRING,
+    },
+
+    NXT_CONF_VLDT_END
+};
+
+
 nxt_int_t
 nxt_conf_validate(nxt_conf_validation_t *vldt)
 {
@@ -3090,3 +3107,65 @@ nxt_conf_vldt_server_weight(nxt_conf_validation_t *vldt,
 
     return NXT_OK;
 }
+
+
+typedef struct {
+    nxt_str_t  path;
+    nxt_str_t  format;
+} nxt_conf_vldt_access_log_conf_t;
+
+
+static nxt_conf_map_t  nxt_conf_vldt_access_log_map[] = {
+    {
+        nxt_string("path"),
+        NXT_CONF_MAP_STR,
+        offsetof(nxt_conf_vldt_access_log_conf_t, path),
+    },
+
+    {
+        nxt_string("format"),
+        NXT_CONF_MAP_STR,
+        offsetof(nxt_conf_vldt_access_log_conf_t, format),
+    },
+};
+
+
+static nxt_int_t
+nxt_conf_vldt_access_log(nxt_conf_validation_t *vldt, nxt_conf_value_t *value,
+    void *data)
+{
+    nxt_int_t                        ret;
+    nxt_conf_vldt_access_log_conf_t  conf;
+
+    static nxt_str_t  format_str = nxt_string("format");
+
+    if (nxt_conf_type(value) == NXT_CONF_STRING) {
+        return NXT_OK;
+    }
+
+    ret = nxt_conf_vldt_object(vldt, value, nxt_conf_vldt_access_log_members);
+    if (ret != NXT_OK) {
+        return ret;
+    }
+
+    nxt_memzero(&conf, sizeof(nxt_conf_vldt_access_log_conf_t));
+
+    ret = nxt_conf_map_object(vldt->pool, value,
+                              nxt_conf_vldt_access_log_map,
+                              nxt_nitems(nxt_conf_vldt_access_log_map),
+                              &conf);
+    if (ret != NXT_OK) {
+        return ret;
+    }
+
+    if (conf.path.length == 0) {
+        return nxt_conf_vldt_error(vldt,
+                                   "The \"path\" string must not be empty.");
+    }
+
+    if (nxt_is_var(&conf.format)) {
+        return nxt_conf_vldt_var(vldt, &format_str, &conf.format);
+    }
+
+    return NXT_OK;
+}
diff --git a/src/nxt_http_request.c b/src/nxt_http_request.c
index 5f8fd8f7..a16340de 100644
--- a/src/nxt_http_request.c
+++ b/src/nxt_http_request.c
@@ -791,6 +791,7 @@ nxt_http_request_error_handler(nxt_task_t *task, void *obj, void *data)
 void
 nxt_http_request_close_handler(nxt_task_t *task, void *obj, void *data)
 {
+    nxt_var_t                *log_format;
     nxt_http_proto_t         proto;
     nxt_http_request_t       *r;
     nxt_http_protocol_t      protocol;
@@ -800,20 +801,22 @@ nxt_http_request_close_handler(nxt_task_t *task, void *obj, void *data)
     r = obj;
     proto.any = data;
 
-    nxt_debug(task, "http request close handler");
-
     conf = r->conf;
 
     if (!r->logged) {
         r->logged = 1;
 
         access_log = conf->socket_conf->router_conf->access_log;
+        log_format = conf->socket_conf->router_conf->log_format;
 
         if (access_log != NULL) {
-            access_log->handler(task, r, access_log);
+            access_log->handler(task, r, access_log, log_format);
+            return;
         }
     }
 
+    nxt_debug(task, "http request close handler");
+
     r->proto.any = NULL;
 
     if (r->body != NULL && nxt_buf_is_file(r->body)
diff --git a/src/nxt_http_static.c b/src/nxt_http_static.c
index 19393f2c..0507e038 100644
--- a/src/nxt_http_static.c
+++ b/src/nxt_http_static.c
@@ -104,7 +104,7 @@ nxt_http_static_init(nxt_task_t *task, nxt_router_temp_conf_t *tmcf,
         cv = nxt_conf_get_array_element_or_itself(acf->share, i);
         nxt_conf_get_string(cv, &str);
 
-        var = nxt_var_compile(&str, mp, rtcf->var_fields, 1);
+        var = nxt_var_compile(&str, mp, rtcf->var_fields, NXT_VAR_STRZ);
         if (nxt_slow_path(var == NULL)) {
             return NXT_ERROR;
         }
@@ -130,7 +130,8 @@ nxt_http_static_init(nxt_task_t *task, nxt_router_temp_conf_t *tmcf,
         nxt_str_t   chr, shr;
         nxt_bool_t  is_const;
 
-        conf->chroot = nxt_var_compile(&acf->chroot, mp, rtcf->var_fields, 1);
+        conf->chroot = nxt_var_compile(&acf->chroot, mp, rtcf->var_fields,
+                                       NXT_VAR_STRZ);
         if (nxt_slow_path(conf->chroot == NULL)) {
             return NXT_ERROR;
         }
diff --git a/src/nxt_router.h b/src/nxt_router.h
index 18fb60b0..a6add219 100644
--- a/src/nxt_router.h
+++ b/src/nxt_router.h
@@ -53,6 +53,7 @@ typedef struct {
     nxt_lvlhsh_t             apps_hash;
 
     nxt_router_access_log_t  *access_log;
+    nxt_var_t                *log_format;
 } nxt_router_conf_t;
 
 
@@ -223,7 +224,8 @@ typedef struct {
 
 struct nxt_router_access_log_s {
     void                   (*handler)(nxt_task_t *task, nxt_http_request_t *r,
-                                      nxt_router_access_log_t *access_log);
+                                      nxt_router_access_log_t *access_log,
+                                      nxt_var_t *format);
     nxt_fd_t               fd;
     nxt_str_t              path;
     uint32_t               count;
diff --git a/src/nxt_router_access_log.c b/src/nxt_router_access_log.c
index d92e80c3..dc2a6687 100644
--- a/src/nxt_router_access_log.c
+++ b/src/nxt_router_access_log.c
@@ -10,10 +10,25 @@
 #include <nxt_http.h>
 
 
+typedef struct {
+    nxt_str_t                 path;
+    nxt_str_t                 format;
+} nxt_router_access_log_conf_t;
+
+
+typedef struct {
+    nxt_str_t                 text;
+    nxt_router_access_log_t   *access_log;
+} nxt_router_access_log_ctx_t;
+
+
 static void nxt_router_access_log_writer(nxt_task_t *task,
-    nxt_http_request_t *r, nxt_router_access_log_t *access_log);
-static u_char *nxt_router_access_log_date(u_char *buf, nxt_realtime_t *now,
-    struct tm *tm, size_t size, const char *format);
+    nxt_http_request_t *r, nxt_router_access_log_t *access_log,
+    nxt_var_t *format);
+static void nxt_router_access_log_write_ready(nxt_task_t *task, void *obj,
+    void *data);
+static void nxt_router_access_log_write_error(nxt_task_t *task, void *obj,
+    void *data);
 static void nxt_router_access_log_ready(nxt_task_t *task,
     nxt_port_recv_msg_t *msg, void *data);
 static void nxt_router_access_log_error(nxt_task_t *task,
@@ -26,26 +41,63 @@ static void nxt_router_access_log_reopen_error(nxt_task_t *task,
     nxt_port_recv_msg_t *msg, void *data);
 
 
+static nxt_conf_map_t  nxt_router_access_log_conf[] = {
+    {
+        nxt_string("path"),
+        NXT_CONF_MAP_STR,
+        offsetof(nxt_router_access_log_conf_t, path),
+    },
+
+    {
+        nxt_string("format"),
+        NXT_CONF_MAP_STR,
+        offsetof(nxt_router_access_log_conf_t, format),
+    },
+};
+
+
 nxt_int_t
 nxt_router_access_log_create(nxt_task_t *task, nxt_router_conf_t *rtcf,
     nxt_conf_value_t *value)
 {
-    nxt_str_t                path;
-    nxt_router_t             *router;
-    nxt_router_access_log_t  *access_log;
+    u_char                        *p;
+    nxt_int_t                     ret;
+    nxt_str_t                     str;
+    nxt_var_t                     *format;
+    nxt_router_t                  *router;
+    nxt_router_access_log_t       *access_log;
+    nxt_router_access_log_conf_t  alcf;
 
-    router = nxt_router;
+    static nxt_str_t  log_format_str = nxt_string("$remote_addr - - "
+        "[$time_local] \"$request_line\" $status $body_bytes_sent "
+        "\"$header_referer\" \"$header_user_agent\"");
+
+    alcf.format = log_format_str;
 
-    nxt_conf_get_string(value, &path);
+    if (nxt_conf_type(value) == NXT_CONF_STRING) {
+        nxt_conf_get_string(value, &alcf.path);
+
+    } else {
+        ret = nxt_conf_map_object(rtcf->mem_pool, value,
+                                  nxt_router_access_log_conf,
+                                  nxt_nitems(nxt_router_access_log_conf),
+                                  &alcf);
+        if (ret != NXT_OK) {
+            nxt_alert(task, "access log map error");
+            return NXT_ERROR;
+        }
+    }
+
+    router = nxt_router;
 
     access_log = router->access_log;
 
-    if (access_log != NULL && nxt_strstr_eq(&path, &access_log->path)) {
+    if (access_log != NULL && nxt_strstr_eq(&alcf.path, &access_log->path)) {
         nxt_router_access_log_use(&router->lock, access_log);
 
     } else {
         access_log = nxt_malloc(sizeof(nxt_router_access_log_t)
-                                + path.length);
+                                + alcf.path.length);
         if (access_log == NULL) {
             nxt_alert(task, "failed to allocate access log structure");
             return NXT_ERROR;
@@ -55,14 +107,32 @@ nxt_router_access_log_create(nxt_task_t *task, nxt_router_conf_t *rtcf,
         access_log->handler = &nxt_router_access_log_writer;
         access_log->count = 1;
 
-        access_log->path.length = path.length;
+        access_log->path.length = alcf.path.length;
         access_log->path.start = (u_char *) access_log
                                  + sizeof(nxt_router_access_log_t);
 
-        nxt_memcpy(access_log->path.start, path.start, path.length);
+        nxt_memcpy(access_log->path.start, alcf.path.start, alcf.path.length);
+    }
+
+    str.length = alcf.format.length + 1;
+
+    str.start = nxt_malloc(str.length);
+    if (str.start == NULL) {
+        nxt_alert(task, "failed to allocate log format structure");
+        return NXT_ERROR;
+    }
+
+    p = nxt_cpymem(str.start, alcf.format.start, alcf.format.length);
+    *p = '\n';
+
+    format = nxt_var_compile(&str, rtcf->mem_pool, rtcf->var_fields,
+                             NXT_VAR_LOGGING);
+    if (nxt_slow_path(format == NULL)) {
+        return NXT_ERROR;
     }
 
     rtcf->access_log = access_log;
+    rtcf->log_format = format;
 
     return NXT_OK;
 }
@@ -70,130 +140,56 @@ nxt_router_access_log_create(nxt_task_t *task, nxt_router_conf_t *rtcf,
 
 static void
 nxt_router_access_log_writer(nxt_task_t *task, nxt_http_request_t *r,
-    nxt_router_access_log_t *access_log)
+    nxt_router_access_log_t *access_log, nxt_var_t *format)
 {
-    size_t     size;
-    u_char     *buf, *p;
-    nxt_off_t  bytes;
-
-    static nxt_time_string_t  date_cache = {
-        (nxt_atomic_uint_t) -1,
-        nxt_router_access_log_date,
-        "%02d/%s/%4d:%02d:%02d:%02d %c%02d%02d",
-        nxt_length("31/Dec/1986:19:40:00 +0300"),
-        NXT_THREAD_TIME_LOCAL,
-        NXT_THREAD_TIME_SEC,
-    };
-
-    size = r->remote->address_length
-           + 6                  /* ' - - [' */
-           + date_cache.size
-           + 3                  /* '] "' */
-           + r->method->length
-           + 1                  /* space */
-           + r->target.length
-           + 1                  /* space */
-           + r->version.length
-           + 2                  /* '" ' */
-           + 3                  /* status */
-           + 1                  /* space */
-           + NXT_OFF_T_LEN
-           + 2                  /* ' "' */
-           + (r->referer != NULL ? r->referer->value_length : 1)
-           + 3                  /* '" "' */
-           + (r->user_agent != NULL ? r->user_agent->value_length : 1)
-           + 2                  /* '"\n' */
-    ;
-
-    buf = nxt_mp_nget(r->mem_pool, size);
-    if (nxt_slow_path(buf == NULL)) {
+    nxt_int_t                    ret;
+    nxt_router_access_log_ctx_t  *ctx;
+
+    ctx = nxt_mp_get(r->mem_pool, sizeof(nxt_router_access_log_ctx_t));
+    if (nxt_slow_path(ctx == NULL)) {
         return;
     }
 
-    p = nxt_cpymem(buf, nxt_sockaddr_address(r->remote),
-                   r->remote->address_length);
+    ctx->access_log = access_log;
 
-    p = nxt_cpymem(p, " - - [", 6);
+    if (nxt_var_is_const(format)) {
+        nxt_var_raw(format, &ctx->text);
 
-    p = nxt_thread_time_string(task->thread, &date_cache, p);
-
-    p = nxt_cpymem(p, "] \"", 3);
-
-    if (r->method->length != 0) {
-        p = nxt_cpymem(p, r->method->start, r->method->length);
-
-        if (r->target.length != 0) {
-            *p++ = ' ';
-            p = nxt_cpymem(p, r->target.start, r->target.length);
-
-            if (r->version.length != 0) {
-                *p++ = ' ';
-                p = nxt_cpymem(p, r->version.start, r->version.length);
-            }
-        }
+        nxt_router_access_log_write_ready(task, r, ctx);
 
     } else {
-        *p++ = '-';
-    }
-
-    p = nxt_cpymem(p, "\" ", 2);
-
-    p = nxt_sprintf(p, p + 3, "%03d", r->status);
-
-    *p++ = ' ';
-
-    bytes = nxt_http_proto[r->protocol].body_bytes_sent(task, r->proto);
-
-    p = nxt_sprintf(p, p + NXT_OFF_T_LEN, "%O", bytes);
-
-    p = nxt_cpymem(p, " \"", 2);
-
-    if (r->referer != NULL) {
-        p = nxt_cpymem(p, r->referer->value, r->referer->value_length);
+        ret = nxt_var_query_init(&r->var_query, r, r->mem_pool);
+        if (nxt_slow_path(ret != NXT_OK)) {
+            return;
+        }
 
-    } else {
-        *p++ = '-';
-    }
+        nxt_var_query(task, r->var_query, format, &ctx->text);
+        nxt_var_query_resolve(task, r->var_query, ctx,
+                              nxt_router_access_log_write_ready,
+                              nxt_router_access_log_write_error);
+     }
+}
 
-    p = nxt_cpymem(p, "\" \"", 3);
 
-    if (r->user_agent != NULL) {
-        p = nxt_cpymem(p, r->user_agent->value, r->user_agent->value_length);
+static void
+nxt_router_access_log_write_ready(nxt_task_t *task, void *obj, void *data)
+{
+    nxt_http_request_t           *r;
+    nxt_router_access_log_ctx_t  *ctx;
 
-    } else {
-        *p++ = '-';
-    }
+    r = obj;
+    ctx = data;
 
-    p = nxt_cpymem(p, "\"\n", 2);
+    nxt_fd_write(ctx->access_log->fd, ctx->text.start, ctx->text.length);
 
-    nxt_fd_write(access_log->fd, buf, p - buf);
+    nxt_http_request_close_handler(task, r, r->proto.any);
 }
 
 
-static u_char *
-nxt_router_access_log_date(u_char *buf, nxt_realtime_t *now, struct tm *tm,
-    size_t size, const char *format)
+static void
+nxt_router_access_log_write_error(nxt_task_t *task, void *obj, void *data)
 {
-    u_char  sign;
-    time_t  gmtoff;
-
-    static const char  *month[] = { "Jan", "Feb", "Mar", "Apr", "May", "Jun",
-                                    "Jul", "Aug", "Sep", "Oct", "Nov", "Dec" };
-
-    gmtoff = nxt_timezone(tm) / 60;
-
-    if (gmtoff < 0) {
-        gmtoff = -gmtoff;
-        sign = '-';
-
-    } else {
-        sign = '+';
-    }
 
-    return nxt_sprintf(buf, buf + size, format,
-                       tm->tm_mday, month[tm->tm_mon], tm->tm_year + 1900,
-                       tm->tm_hour, tm->tm_min, tm->tm_sec,
-                       sign, gmtoff / 60, gmtoff % 60);
 }
 
 
diff --git a/src/nxt_var.c b/src/nxt_var.c
index d3057764..f55a2d30 100644
--- a/src/nxt_var.c
+++ b/src/nxt_var.c
@@ -9,7 +9,7 @@
 struct nxt_var_s {
     size_t              length;
     nxt_uint_t          vars;
-    uint8_t             strz;  /* 1 bit */
+    nxt_var_flags_t     flags;
     u_char              data[];
 
 /*
@@ -331,11 +331,12 @@ nxt_var_index_init(void)
 
 nxt_var_t *
 nxt_var_compile(nxt_str_t *str, nxt_mp_t *mp, nxt_array_t *fields,
-    nxt_bool_t strz)
+    nxt_var_flags_t flags)
 {
     u_char          *p, *end, *next, *src;
     size_t          size;
     uint32_t        index;
+    nxt_bool_t      strz;
     nxt_var_t       *var;
     nxt_str_t       part;
     nxt_uint_t      n;
@@ -343,6 +344,8 @@ nxt_var_compile(nxt_str_t *str, nxt_mp_t *mp, nxt_array_t *fields,
     nxt_var_sub_t   *subs;
     nxt_var_decl_t  *decl;
 
+    strz = (flags & NXT_VAR_STRZ) != 0;
+
     n = 0;
 
     p = str->start;
@@ -368,7 +371,7 @@ nxt_var_compile(nxt_str_t *str, nxt_mp_t *mp, nxt_array_t *fields,
 
     var->length = str->length;
     var->vars = n;
-    var->strz = strz;
+    var->flags = flags;
 
     subs = nxt_var_subs(var);
     src = nxt_var_raw_start(var);
@@ -568,6 +571,7 @@ nxt_var_query(nxt_task_t *task, nxt_var_query_t *query, nxt_var_t *var,
     size_t         length, last, next;
     nxt_str_t      *value, **part;
     nxt_uint_t     i;
+    nxt_bool_t     strz, logging;
     nxt_array_t    parts;
     nxt_var_sub_t  *subs;
 
@@ -583,6 +587,9 @@ nxt_var_query(nxt_task_t *task, nxt_var_query_t *query, nxt_var_t *var,
     nxt_memzero(&parts, sizeof(nxt_array_t));
     nxt_array_init(&parts, query->pool, sizeof(nxt_str_t *));
 
+    strz = (var->flags & NXT_VAR_STRZ) != 0;
+    logging = (var->flags & NXT_VAR_LOGGING) != 0;
+
     subs = nxt_var_subs(var);
 
     length = var->length;
@@ -601,9 +608,13 @@ nxt_var_query(nxt_task_t *task, nxt_var_query_t *query, nxt_var_t *var,
         *part = value;
 
         length += value->length - subs[i].length;
+
+        if (logging && value->start == NULL) {
+            length += 1;
+        }
     }
 
-    p = nxt_mp_nget(query->pool, length + var->strz);
+    p = nxt_mp_nget(query->pool, length + strz);
     if (nxt_slow_path(p == NULL)) {
         goto fail;
     }
@@ -625,6 +636,10 @@ nxt_var_query(nxt_task_t *task, nxt_var_query_t *query, nxt_var_t *var,
 
         p = nxt_cpymem(p, part[i]->start, part[i]->length);
 
+        if (logging && part[i]->start == NULL) {
+            *p++ = '-';
+        }
+
         last = next + subs[i].length;
     }
 
@@ -632,7 +647,7 @@ nxt_var_query(nxt_task_t *task, nxt_var_query_t *query, nxt_var_t *var,
         p = nxt_cpymem(p, &src[last], var->length - last);
     }
 
-    if (var->strz) {
+    if (strz) {
         *p = '\0';
     }
 
diff --git a/src/nxt_var.h b/src/nxt_var.h
index 3c38be36..cc7ff502 100644
--- a/src/nxt_var.h
+++ b/src/nxt_var.h
@@ -32,6 +32,12 @@ typedef struct {
 } nxt_var_field_t;
 
 
+typedef enum {
+    NXT_VAR_STRZ       = 1 << 0,
+    NXT_VAR_LOGGING    = 1 << 1,
+} nxt_var_flags_t;
+
+
 nxt_inline nxt_bool_t
 nxt_is_var(nxt_str_t *str)
 {
@@ -45,7 +51,7 @@ nxt_int_t nxt_var_index_init(void);
 nxt_var_field_t *nxt_var_field_get(nxt_array_t *fields, uint16_t index);
 
 nxt_var_t *nxt_var_compile(nxt_str_t *str, nxt_mp_t *mp, nxt_array_t *fields,
-    nxt_bool_t strz);
+    nxt_var_flags_t flags);
 nxt_int_t nxt_var_test(nxt_str_t *str, nxt_array_t *fields, u_char *error);
 
 nxt_bool_t nxt_var_is_const(nxt_var_t *var);