Don't reconstruct a new string for the $request_line from the parsed
method, target, and HTTP version, but rather keep a pointer to the
original memory where the request line was received.
This will be necessary for implementing URI rewrites, since we want to
log the original request line, and not one constructed from the
rewritten target.
This implementation changes behavior (only for invalid requests) in the
following way:
Previous behavior was to log as many tokens from the request line as
were parsed validly, thus:
Request -> access log ; error log
"GET / HTTP/1.1" -> "GET / HTTP/1.1" OK ; =
"GET / HTTP/1.1" -> "GET / HTTP/1.1" [1] ; =
"GET / HTTP/2.1" -> "GET / HTTP/2.1" OK ; =
"GET / HTTP/1." -> "GET / HTTP/1." [2] ; "GET / HTTP/1. [null]"
"GET / food" -> "GET / food" [2] ; "GET / food [null]"
"GET / / HTTP/1.1" -> "GET / / HTTP/1.1" [2] ; =
"GET / / HTTP/1.1" -> "GET / / HTTP/1.1" [2] ; =
"GET food HTTP/1.1" -> "GET" ; "GET [null] [null]"
"OPTIONS * HTTP/1.1" -> "OPTIONS" [3] ; "OPTIONS [null] [null]"
"FOOBAR baz HTTP/1.1"-> "FOOBAR" ; "FOOBAR [null] [null]"
"FOOBAR / HTTP/1.1" -> "FOOBAR / HTTP/1.1" ; =
"get / HTTP/1.1" -> "-" ; " [null] [null]"
"" -> "-" ; " [null] [null]"
This behavior was rather inconsistent. We have several options to go
forward with this patch:
- NGINX behavior.
Log the entire request line, up to '\r' | '\n', even if it was
invalid.
This is the most informative alternative. However, RFC-complying
requests will probably not send invalid requests.
This information would be interesting to users where debugging
requests constructed manually via netcat(1) or a similar tool, or
maybe for debugging a client, are important. It might be interesting
to support this in the future if our users are interested; for now,
since this approach requires looping over invalid requests twice,
that's an overhead that we better avoid.
- Previous Unit behavior
This is relatively fast (almost as fast as the next alternative, the
one we chose), but the implementation is ugly, in that we need to
perform the same operation in many places around the code.
If we want performance, probably the next alternative is better; if
we want to be informative, then the first one is better (maybe in
combination with the third one too).
- Chosen behavior
Only logging request lines when the request is valid. For any
invalid request, or even unsupported ones, the request line will be
logged as "-". Thus:
Request -> access log [4]
"GET / HTTP/1.1" -> "GET / HTTP/1.1" OK
"GET / HTTP/1.1" -> "GET / HTTP/1.1" [1]
"GET / HTTP/2.1" -> "-" [3]
"GET / HTTP/1." -> "-"
"GET / food" -> "-"
"GET / / HTTP/1.1" -> "GET / / HTTP/1.1" [2]
"GET / / HTTP/1.1" -> "GET / / HTTP/1.1" [2]
"GET food HTTP/1.1" -> "-"
"OPTIONS * HTTP/1.1" -> "-"
"FOOBAR baz HTTP/1.1"-> "-"
"FOOBAR / HTTP/1.1" -> "FOOBAR / HTTP/1.1"
"get / HTTP/1.1" -> "-"
"" -> "-"
This is less informative than previous behavior, but considering how
inconsistent it was, and that RFC-complying agents will probably not
send us such requests, we're ready to lose that information in the
log. This is of course the fastest and simplest implementation we
can get.
We've chosen to implement this alternative in this patch. Since we
modified the behavior, this patch also changes the affected tests.
[1]: Multiple successive spaces as a token delimiter is allowed by the
RFC, but it is discouraged, and considered a security risk. It is
currently supported by Unit, but we will probably drop support for
it in the future.
[2]: Unit currently supports spaces in the request-target. This is
a violation of the relevant RFC (linked below), and will be fixed
in the future, and consider those targets as invalid, returning
a 400 (Bad Request), and thus the log lines with the previous
inconsistent behavior would be changed.
[3]: Not yet supported.
[4]: In the error log, regarding the "log_routes" conditional logging
of the request line, we only need to log the request line if it
was valid. It doesn't make sense to log "" or "-" in case that
the request was invalid, since this is only useful for
understanding decisions of the router. In this case, the access
log is more appropriate, which shows that the request was invalid,
and a 400 was returned. When the request line is valid, it is
printed in the error log exactly as in the access log.
Link: <https://datatracker.ietf.org/doc/html/rfc9112#section-3>
Suggested-by: Liam Crilly <liam@nginx.com>
Reviewed-by: Zhidao Hong <z.hong@f5.com>
Cc: Timo Stark <t.stark@nginx.com>
Cc: Andrei Zeliankou <zelenkov@nginx.com>
Cc: Andrew Clayton <a.clayton@nginx.com>
Cc: Artem Konev <a.konev@f5.com>
Signed-off-by: Alejandro Colomar <alx@nginx.com>
488 lines
11 KiB
C
488 lines
11 KiB
C
|
|
/*
|
|
* Copyright (C) NGINX, Inc.
|
|
*/
|
|
|
|
#include <nxt_router.h>
|
|
#include <nxt_http.h>
|
|
|
|
|
|
static nxt_int_t nxt_http_var_dollar(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_request_time(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_method(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_request_uri(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_uri(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field);
|
|
static nxt_int_t nxt_http_var_host(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field);
|
|
static nxt_int_t nxt_http_var_remote_addr(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_time_local(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static u_char *nxt_http_log_date(u_char *buf, nxt_realtime_t *now,
|
|
struct tm *tm, size_t size, const char *format);
|
|
static nxt_int_t nxt_http_var_request_line(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_status(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_body_bytes_sent(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_referer(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_user_agent(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_arg(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field);
|
|
static nxt_int_t nxt_http_var_header(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
static nxt_int_t nxt_http_var_cookie(nxt_task_t *task, nxt_str_t *str,
|
|
void *ctx, uint16_t field);
|
|
|
|
|
|
static nxt_var_decl_t nxt_http_vars[] = {
|
|
{
|
|
.name = nxt_string("dollar"),
|
|
.handler = nxt_http_var_dollar,
|
|
}, {
|
|
.name = nxt_string("request_time"),
|
|
.handler = nxt_http_var_request_time,
|
|
}, {
|
|
.name = nxt_string("method"),
|
|
.handler = nxt_http_var_method,
|
|
}, {
|
|
.name = nxt_string("request_uri"),
|
|
.handler = nxt_http_var_request_uri,
|
|
}, {
|
|
.name = nxt_string("uri"),
|
|
.handler = nxt_http_var_uri,
|
|
}, {
|
|
.name = nxt_string("host"),
|
|
.handler = nxt_http_var_host,
|
|
}, {
|
|
.name = nxt_string("remote_addr"),
|
|
.handler = nxt_http_var_remote_addr,
|
|
}, {
|
|
.name = nxt_string("time_local"),
|
|
.handler = nxt_http_var_time_local,
|
|
}, {
|
|
.name = nxt_string("request_line"),
|
|
.handler = nxt_http_var_request_line,
|
|
}, {
|
|
.name = nxt_string("status"),
|
|
.handler = nxt_http_var_status,
|
|
}, {
|
|
.name = nxt_string("body_bytes_sent"),
|
|
.handler = nxt_http_var_body_bytes_sent,
|
|
}, {
|
|
.name = nxt_string("header_referer"),
|
|
.handler = nxt_http_var_referer,
|
|
}, {
|
|
.name = nxt_string("header_user_agent"),
|
|
.handler = nxt_http_var_user_agent,
|
|
}, {
|
|
.name = nxt_string("arg"),
|
|
.handler = nxt_http_var_arg,
|
|
.field_hash = nxt_http_argument_hash,
|
|
}, {
|
|
.name = nxt_string("header"),
|
|
.handler = nxt_http_var_header,
|
|
.field_hash = nxt_http_header_hash,
|
|
}, {
|
|
.name = nxt_string("cookie"),
|
|
.handler = nxt_http_var_cookie,
|
|
.field_hash = nxt_http_cookie_hash,
|
|
},
|
|
};
|
|
|
|
|
|
nxt_int_t
|
|
nxt_http_register_variables(void)
|
|
{
|
|
return nxt_var_register(nxt_http_vars, nxt_nitems(nxt_http_vars));
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_dollar(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_str_set(str, "$");
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_request_time(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
u_char *p;
|
|
nxt_msec_t ms;
|
|
nxt_nsec_t now;
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
now = nxt_thread_monotonic_time(task->thread);
|
|
ms = (now - r->start_time) / 1000000;
|
|
|
|
str->start = nxt_mp_nget(r->mem_pool, NXT_TIME_T_LEN + 4);
|
|
if (nxt_slow_path(str->start == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
p = nxt_sprintf(str->start, str->start + NXT_TIME_T_LEN, "%T.%03M",
|
|
(nxt_time_t) ms / 1000, ms % 1000);
|
|
|
|
str->length = p - str->start;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_method(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
*str = *r->method;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_request_uri(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
*str = r->target;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_uri(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
*str = *r->path;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_host(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
*str = r->host;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_remote_addr(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
str->length = r->remote->address_length;
|
|
str->start = nxt_sockaddr_address(r->remote);
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_time_local(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
static nxt_time_string_t date_cache = {
|
|
(nxt_atomic_uint_t) -1,
|
|
nxt_http_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,
|
|
};
|
|
|
|
r = ctx;
|
|
|
|
str->length = date_cache.size;
|
|
|
|
str->start = nxt_mp_nget(r->mem_pool, str->length);
|
|
if (nxt_slow_path(str->start == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
str->length = nxt_thread_time_string(task->thread, &date_cache, str->start)
|
|
- str->start;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static u_char *
|
|
nxt_http_log_date(u_char *buf, nxt_realtime_t *now, struct tm *tm,
|
|
size_t size, const char *format)
|
|
{
|
|
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);
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_request_line(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
*str = r->request_line;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_body_bytes_sent(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_off_t bytes;
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
str->start = nxt_mp_nget(r->mem_pool, NXT_OFF_T_LEN);
|
|
if (nxt_slow_path(str->start == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
bytes = nxt_http_proto[r->protocol].body_bytes_sent(task, r->proto);
|
|
|
|
str->length = nxt_sprintf(str->start, str->start + NXT_OFF_T_LEN, "%O",
|
|
bytes) - str->start;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_status(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
str->start = nxt_mp_nget(r->mem_pool, 3);
|
|
if (nxt_slow_path(str->start == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
str->length = nxt_sprintf(str->start, str->start + 3, "%03d", r->status)
|
|
- str->start;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_referer(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
if (r->referer != NULL) {
|
|
str->start = r->referer->value;
|
|
str->length = r->referer->value_length;
|
|
|
|
} else {
|
|
nxt_str_null(str);
|
|
}
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_user_agent(nxt_task_t *task, nxt_str_t *str, void *ctx,
|
|
uint16_t field)
|
|
{
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
if (r->user_agent != NULL) {
|
|
str->start = r->user_agent->value;
|
|
str->length = r->user_agent->value_length;
|
|
|
|
} else {
|
|
nxt_str_null(str);
|
|
}
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_arg(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_array_t *args;
|
|
nxt_var_field_t *vf;
|
|
nxt_router_conf_t *rtcf;
|
|
nxt_http_request_t *r;
|
|
nxt_http_name_value_t *nv, *start;
|
|
|
|
r = ctx;
|
|
|
|
rtcf = r->conf->socket_conf->router_conf;
|
|
|
|
vf = nxt_var_field_get(rtcf->tstr_state->var_fields, field);
|
|
|
|
args = nxt_http_arguments_parse(r);
|
|
if (nxt_slow_path(args == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
start = args->elts;
|
|
nv = start + args->nelts - 1;
|
|
|
|
while (nv >= start) {
|
|
|
|
if (vf->hash == nv->hash
|
|
&& vf->name.length == nv->name_length
|
|
&& memcmp(vf->name.start, nv->name, nv->name_length) == 0)
|
|
{
|
|
str->start = nv->value;
|
|
str->length = nv->value_length;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
nv--;
|
|
}
|
|
|
|
nxt_str_null(str);
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_header(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_var_field_t *vf;
|
|
nxt_http_field_t *f;
|
|
nxt_router_conf_t *rtcf;
|
|
nxt_http_request_t *r;
|
|
|
|
r = ctx;
|
|
|
|
rtcf = r->conf->socket_conf->router_conf;
|
|
|
|
vf = nxt_var_field_get(rtcf->tstr_state->var_fields, field);
|
|
|
|
nxt_list_each(f, r->fields) {
|
|
|
|
if (vf->hash == f->hash
|
|
&& vf->name.length == f->name_length
|
|
&& nxt_strncasecmp(vf->name.start, f->name, f->name_length) == 0)
|
|
{
|
|
str->start = f->value;
|
|
str->length = f->value_length;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
} nxt_list_loop;
|
|
|
|
nxt_str_null(str);
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
|
|
static nxt_int_t
|
|
nxt_http_var_cookie(nxt_task_t *task, nxt_str_t *str, void *ctx, uint16_t field)
|
|
{
|
|
nxt_array_t *cookies;
|
|
nxt_var_field_t *vf;
|
|
nxt_router_conf_t *rtcf;
|
|
nxt_http_request_t *r;
|
|
nxt_http_name_value_t *nv, *end;
|
|
|
|
r = ctx;
|
|
|
|
rtcf = r->conf->socket_conf->router_conf;
|
|
|
|
vf = nxt_var_field_get(rtcf->tstr_state->var_fields, field);
|
|
|
|
cookies = nxt_http_cookies_parse(r);
|
|
if (nxt_slow_path(cookies == NULL)) {
|
|
return NXT_ERROR;
|
|
}
|
|
|
|
nv = cookies->elts;
|
|
end = nv + cookies->nelts;
|
|
|
|
while (nv < end) {
|
|
|
|
if (vf->hash == nv->hash
|
|
&& vf->name.length == nv->name_length
|
|
&& memcmp(vf->name.start, nv->name, nv->name_length) == 0)
|
|
{
|
|
str->start = nv->value;
|
|
str->length = nv->value_length;
|
|
|
|
return NXT_OK;
|
|
}
|
|
|
|
nv++;
|
|
}
|
|
|
|
nxt_str_null(str);
|
|
|
|
return NXT_OK;
|
|
}
|