Upstream: improved subrequest logging.

To ensure proper logging make sure to set current_request in all event
handlers, including resolve, ssl handshake, cache lock wait timer and
aio read handlers.  A macro ngx_http_set_log_request() introduced to
simplify this.
This commit is contained in:
Maxim Dounin 2014-12-02 05:54:54 +03:00
parent 778cc4b42e
commit 10345663c8
4 changed files with 45 additions and 21 deletions

View File

@ -14,6 +14,8 @@
static ngx_int_t ngx_http_file_cache_lock(ngx_http_request_t *r,
ngx_http_cache_t *c);
static void ngx_http_file_cache_lock_wait_handler(ngx_event_t *ev);
static void ngx_http_file_cache_lock_wait(ngx_http_request_t *r,
ngx_http_cache_t *c);
static ngx_int_t ngx_http_file_cache_read(ngx_http_request_t *r,
ngx_http_cache_t *c);
static ssize_t ngx_http_file_cache_aio_read(ngx_http_request_t *r,
@ -448,25 +450,35 @@ ngx_http_file_cache_lock(ngx_http_request_t *r, ngx_http_cache_t *c)
static void
ngx_http_file_cache_lock_wait_handler(ngx_event_t *ev)
{
ngx_uint_t wait;
ngx_msec_t now, timer;
ngx_http_cache_t *c;
ngx_http_request_t *r;
ngx_http_file_cache_t *cache;
ngx_connection_t *c;
ngx_http_request_t *r;
r = ev->data;
c = r->cache;
c = r->connection;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http file cache wait: \"%V?%V\"", &r->uri, &r->args);
ngx_http_file_cache_lock_wait(r, r->cache);
}
static void
ngx_http_file_cache_lock_wait(ngx_http_request_t *r, ngx_http_cache_t *c)
{
ngx_uint_t wait;
ngx_msec_t now, timer;
ngx_http_file_cache_t *cache;
now = ngx_current_msec;
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, ev->log, 0,
"http file cache wait handler wt:%M cur:%M",
c->wait_time, now);
timer = c->wait_time - now;
if ((ngx_msec_int_t) timer <= 0) {
ngx_log_error(NGX_LOG_INFO, ev->log, 0, "cache lock timeout");
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"cache lock timeout");
c->lock_timeout = 0;
goto wakeup;
}
@ -485,7 +497,7 @@ ngx_http_file_cache_lock_wait_handler(ngx_event_t *ev)
ngx_shmtx_unlock(&cache->shpool->mutex);
if (wait) {
ngx_add_timer(ev, (timer > 500) ? 500 : timer);
ngx_add_timer(&c->wait_event, (timer > 500) ? 500 : timer);
return;
}
@ -665,10 +677,17 @@ static void
ngx_http_cache_aio_event_handler(ngx_event_t *ev)
{
ngx_event_aio_t *aio;
ngx_connection_t *c;
ngx_http_request_t *r;
aio = ev->data;
r = aio->data;
c = r->connection;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http file cache aio: \"%V?%V\"", &r->uri, &r->args);
r->main->blocked--;
r->aio = 0;

View File

@ -2169,13 +2169,11 @@ ngx_http_request_handler(ngx_event_t *ev)
{
ngx_connection_t *c;
ngx_http_request_t *r;
ngx_http_log_ctx_t *ctx;
c = ev->data;
r = c->data;
ctx = c->log->data;
ctx->current_request = r;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http run request: \"%V?%V\"", &r->uri, &r->args);
@ -2195,7 +2193,6 @@ void
ngx_http_run_posted_requests(ngx_connection_t *c)
{
ngx_http_request_t *r;
ngx_http_log_ctx_t *ctx;
ngx_http_posted_request_t *pr;
for ( ;; ) {
@ -2215,8 +2212,7 @@ ngx_http_run_posted_requests(ngx_connection_t *c)
r = pr->request;
ctx = c->log->data;
ctx->current_request = r;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http posted request: \"%V?%V\"", &r->uri, &r->args);

View File

@ -595,4 +595,8 @@ extern ngx_http_header_out_t ngx_http_headers_out[];
}
#define ngx_http_set_log_request(log, r) \
((ngx_http_log_ctx_t *) log->data)->current_request = r
#endif /* _NGX_HTTP_REQUEST_H_INCLUDED_ */

View File

@ -942,6 +942,11 @@ ngx_http_upstream_resolve_handler(ngx_resolver_ctx_t *ctx)
u = r->upstream;
ur = u->resolved;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http upstream resolve: \"%V?%V\"", &r->uri, &r->args);
if (ctx->state) {
ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
"%V could not be resolved (%i: %s)",
@ -1003,7 +1008,6 @@ ngx_http_upstream_handler(ngx_event_t *ev)
{
ngx_connection_t *c;
ngx_http_request_t *r;
ngx_http_log_ctx_t *ctx;
ngx_http_upstream_t *u;
c = ev->data;
@ -1012,8 +1016,7 @@ ngx_http_upstream_handler(ngx_event_t *ev)
u = r->upstream;
c = r->connection;
ctx = c->log->data;
ctx->current_request = r;
ngx_http_set_log_request(c->log, r);
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
"http upstream request: \"%V?%V\"", &r->uri, &r->args);
@ -1447,6 +1450,8 @@ ngx_http_upstream_ssl_handshake(ngx_connection_t *c)
r = c->data;
u = r->upstream;
ngx_http_set_log_request(c->log, r);
if (c->ssl->handshaked) {
if (u->conf->ssl_verify) {