# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1417488894 -10800
# Node ID 8dfee01ff0bdd13de01ba5635d58a584d460e172
# Parent  ac2a8e4d8f01e4dee0f8c630a5027e7e2b123279
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.

diff --git a/src/http/ngx_http_file_cache.c b/src/http/ngx_http_file_cache.c
--- a/src/http/ngx_http_file_cache.c
+++ b/src/http/ngx_http_file_cache.c
@@ -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_reques
 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(ng
     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;
diff --git a/src/http/ngx_http_request.c b/src/http/ngx_http_request.c
--- a/src/http/ngx_http_request.c
+++ b/src/http/ngx_http_request.c
@@ -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_connect
 
         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);
diff --git a/src/http/ngx_http_request.h b/src/http/ngx_http_request.h
--- a/src/http/ngx_http_request.h
+++ b/src/http/ngx_http_request.h
@@ -595,4 +595,8 @@ extern ngx_http_header_out_t   ngx_http_
     }
 
 
+#define ngx_http_set_log_request(log, r)                                      \
+    ((ngx_http_log_ctx_t *) log->data)->current_request = r
+
+
 #endif /* _NGX_HTTP_REQUEST_H_INCLUDED_ */
diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -942,6 +942,11 @@ ngx_http_upstream_resolve_handler(ngx_re
     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 *e
 {
     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 *e
     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_conn
     r = c->data;
     u = r->upstream;
 
+    ngx_http_set_log_request(c->log, r);
+
     if (c->ssl->handshaked) {
 
         if (u->conf->ssl_verify) {