updated error log message and make it more readable

chobits · chobits · commit a16dda57405c · 2019-08-07T17:39:30.000+08:00
diff --git a/README.md b/README.md
@@ -18,6 +18,7 @@ Table of Contents
          * [build as a dynamic module](#build-as-a-dynamic-module)
       * [build OpenResty](#build-openresty)
    * [Test Suite](#test-suite)
+   * [Error Log](#error-log)
    * [Directive](#directive)
       * [proxy_connect](#proxy_connect)
       * [proxy_connect_allow](#proxy_connect_allow)
@@ -337,6 +338,18 @@ $ export TEST_NGINX_BINARY=/path/to/nginx/binary
 $ prove -v -I /path/to/nginx-tests/lib /path/to/ngx_http_proxy_connect_module/t/
 ```
 
+Error Log
+=========
+
+This module logs its own error message beginning with `"proxy_connect:"` string.  
+Some typical error logs are shown as following:
+
+* The proxy_connect module tries to establish tunnel connection with backend server, but the TCP connection timeout occurs.
+
+```
+2019/08/07 17:27:20 [error] 19257#0: *1 proxy_connect: upstream connect timed out (peer:216.58.200.4:443) while connecting to upstream, client: 127.0.0.1, server: , request: "CONNECT www.google.com:443 HTTP/1.1", host: "www.google.com:443"
+```
+
 Variables
 =========
 
diff --git a/ngx_http_proxy_connect_module.c b/ngx_http_proxy_connect_module.c
@@ -373,7 +373,7 @@ ngx_http_proxy_connect_test_connect(ngx_connection_t *c)
 
             c->log->action = "connecting to upstream";
             (void) ngx_connection_error(c, err,
-                                    "kevent() reported that connect() failed");
+                              "proxy_connet: upstream connect failed (kevent)");
             return NGX_ERROR;
         }
 
@@ -395,8 +395,9 @@ ngx_http_proxy_connect_test_connect(ngx_connection_t *c)
         }
 
         if (err) {
-            c->log->action = "connecting to upstream (proxy_connect)";
-            (void) ngx_connection_error(c, err, "connect() failed");
+            c->log->action = "connecting to upstream";
+            (void) ngx_connection_error(c, err,
+                                      "proxy_connect: upstream connect failed");
             return NGX_ERROR;
         }
     }
@@ -740,7 +741,8 @@ ngx_http_proxy_connect_read_downstream(ngx_http_request_t *r)
 
     if (r->connection->read->timedout) {
         r->connection->timedout = 1;
-        ngx_connection_error(r->connection, NGX_ETIMEDOUT, "client timed out");
+        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
+                      "proxy_connect: client read timed out");
         ngx_http_proxy_connect_finalize_request(r, ctx->u,
                                                 NGX_HTTP_REQUEST_TIME_OUT);
         return;
@@ -759,7 +761,8 @@ ngx_http_proxy_connect_write_downstream(ngx_http_request_t *r)
 
     if (r->connection->write->timedout) {
         r->connection->timedout = 1;
-        ngx_connection_error(r->connection, NGX_ETIMEDOUT, "client timed out");
+        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
+                      "proxy_connect: client write timed out");
         ngx_http_proxy_connect_finalize_request(r, ctx->u,
                                                 NGX_HTTP_REQUEST_TIME_OUT);
         return;
@@ -784,7 +787,9 @@ ngx_http_proxy_connect_read_upstream(ngx_http_request_t *r,
     c = u->peer.connection;
 
     if (c->read->timedout) {
-        ngx_connection_error(c, NGX_ETIMEDOUT, "upstream timed out");
+        ngx_log_error(NGX_LOG_ERR, c->log, 0,
+                      "proxy_connect: upstream read timed out (peer:%V)",
+                      u->peer.name);
         ngx_http_proxy_connect_finalize_request(r, u, NGX_HTTP_GATEWAY_TIME_OUT);
         return;
     }
@@ -837,8 +842,9 @@ ngx_http_proxy_connect_write_upstream(ngx_http_request_t *r,
                    "proxy_connect upstream write handler");
 
     if (c->write->timedout) {
-        ngx_connection_error(c, NGX_ETIMEDOUT,
-                             "upstream timed out (proxy_connect)");
+        ngx_log_error(NGX_LOG_ERR, c->log, 0,
+                      "proxy_connect: upstream %s timed out (peer:%V)",
+                      u->connected ? "write" : "connect", u->peer.name);
         ngx_http_proxy_connect_finalize_request(r, u,
                                                 NGX_HTTP_GATEWAY_TIME_OUT);
         return;
@@ -890,8 +896,8 @@ ngx_http_proxy_connect_send_handler(ngx_http_request_t *r)
 
     if (c->write->timedout) {
         c->timedout = 1;
-        ngx_connection_error(c, NGX_ETIMEDOUT,
-                             "client timed out (proxy_connect)");
+        ngx_log_error(NGX_LOG_ERR, c->log, 0,
+                      "proxy_connect: client write timed out");
         ngx_http_proxy_connect_finalize_request(r, ctx->u,
                                                 NGX_HTTP_REQUEST_TIME_OUT);
         return;
@@ -947,7 +953,7 @@ ngx_http_proxy_connect_process_connect(ngx_http_request_t *r,
 
     ctx = ngx_http_get_module_ctx(r, ngx_http_proxy_connect_module);
 
-    r->connection->log->action = "connecting to upstream (proxy_connect)";
+    r->connection->log->action = "connecting to upstream";
 
     if (ngx_http_proxy_connect_set_local(r, u, u->conf->local) != NGX_OK) {
         ngx_http_proxy_connect_finalize_request(r, u, NGX_HTTP_INTERNAL_SERVER_ERROR);
@@ -975,13 +981,15 @@ ngx_http_proxy_connect_process_connect(ngx_http_request_t *r,
     }
 
     if (rc == NGX_BUSY) {
-        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, "no live connection");
+        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
+                      "proxy_connect: no live connection");
         ngx_http_proxy_connect_finalize_request(r, u, NGX_HTTP_BAD_GATEWAY);
         return;
     }
 
     if (rc == NGX_DECLINED) {
-        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, "connection error");
+        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
+                      "proxy_connect: connection error");
         ngx_http_proxy_connect_finalize_request(r, u, NGX_HTTP_BAD_GATEWAY);
         return;
     }
@@ -1046,7 +1054,7 @@ ngx_http_proxy_connect_resolve_handler(ngx_resolver_ctx_t *ctx)
 
     if (ctx->state) {
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "%V could not be resolved (%i: %s)",
+                      "proxy_connect: %V could not be resolved (%i: %s)",
                       &ctx->name, ctx->state,
                       ngx_resolver_strerror(ctx->state));
 
@@ -1403,12 +1411,13 @@ ngx_http_proxy_connect_handler(ngx_http_request_t *r)
     url.no_resolve = 1;
 
     ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
-                   "connect handler: parse url: %V" , &url);
+                   "connect handler: parse url: %V" , &url.url);
 
     if (ngx_parse_url(r->pool, &url) != NGX_OK) {
         if (url.err) {
             ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                          "%s in connect host \"%V\"", url.err, &url.url);
+                          "proxy_connect: %s in connect host \"%V\"",
+                          url.err, &url.url);
             return NGX_HTTP_FORBIDDEN;
         }
 
@@ -1469,13 +1478,14 @@ ngx_http_proxy_connect_handler(ngx_http_request_t *r)
     rctx = ngx_resolve_start(clcf->resolver, &temp);
     if (rctx == NULL) {
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "failed to start the resolver");
+                      "proxy_connect: failed to start the resolver");
         return NGX_HTTP_INTERNAL_SERVER_ERROR;
     }
 
     if (rctx == NGX_NO_RESOLVER) {
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "no resolver defined to resolve %V", &r->connect_host);
+                      "proxy_connect: no resolver defined to resolve %V",
+                      &r->connect_host);
         return NGX_HTTP_BAD_GATEWAY;
     }
 
@@ -1797,7 +1807,7 @@ ngx_http_proxy_connect_set_local(ngx_http_request_t *r,
 
     if (rc != NGX_OK) {
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "invalid local address \"%V\"", &val);
+                      "proxy_connect: invalid local address \"%V\"", &val);
         return NGX_OK;
     }
 
@@ -1960,7 +1970,8 @@ ngx_http_proxy_connect_variable_set_time(ngx_http_request_t *r,
 
     if (ms == (ngx_msec_t) NGX_ERROR) {
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "[proxy_connect] invalid msec \"%V\" (ctx offset=%ui)", &s, data);
+                      "proxy_connect: invalid msec \"%V\" (ctx offset=%ui)",
+                      &s, data);
         return;
     }
 
@@ -1969,7 +1980,7 @@ ngx_http_proxy_connect_variable_set_time(ngx_http_request_t *r,
     if (ctx == NULL) {
 #if 0
         ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
-                      "[proxy_connect] no ctx found");
+                      "proxy_connect: no ctx found");
 #endif
         return;
     }
diff --git a/t/http_proxy_connect_timeout.t b/t/http_proxy_connect_timeout.t
@@ -83,6 +83,7 @@ http {
                        ' c:$proxy_connect_connect_timeout,s:$proxy_connect_send_timeout,r:$proxy_connect_read_timeout';
 
     access_log %%TESTDIR%%/connect.log connect;
+    error_log %%TESTDIR%%/connect_error.log error;
 
     resolver 127.0.0.1:18085 ipv6=off;      # NOTE: cannot connect ipv6 address ::1 in mac os x.
 
@@ -120,6 +121,13 @@ http {
             access_log off;
             root %%TESTDIR%%/;
         }
+
+        # used to output error.log
+        location = /connect_error.log {
+            access_log off;
+            root %%TESTDIR%%/;
+        }
+
     }
 }
 
@@ -144,12 +152,17 @@ if ($@) {
 #}
 
 my $log;
+my $errlog;
 
 TODO: {
     local $TODO = '# This case will pass, if connecting 8.8.8.8 timed out.';
     like(http_connect_request('test-connect-timeout.com', '8888', '/'), qr/504/, 'connect timed out: set $var');
     $log = http_get('/connect.log');
-    like($log, qr/"CONNECT test-connect-timeout.com:8888 HTTP\/1.1" 504 .+ c:1,s:102,r:103/, 'connect timed out log: get $var & status=504');
+    like($log, qr/"CONNECT test-connect-timeout.com:8888 HTTP\/1.1" 504 .+ c:1,s:102,r:103/,
+        'connect timed out log: get $var & status=504');
+    $errlog = http_get('/connect_error.log');
+    like($errlog, qr/proxy_connect: upstream connect timed out \(peer:8\.8\.8\.8:8888\) while connecting to upstream/,
+        'connect timed out error log');
 }
 
 http_connect_request('test-read-timeout.com', '8888', '/');
