I run minimal latest nginx version with latest dynami

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

<a class="user-mention notranslate" data-hovercard-type="user" data-hover

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

"the http output chain is empty while connecting to upstream" from subrequest,about nginx/njs

Comments (14)

initproc commented on August 20, 2024 1

I get same problem as him, and I look for some codes and try to fix this.

./nginx -V
nginx version: nginx/1.16.0
built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11) 
built with OpenSSL 1.0.2r  26 Feb 2019
TLS SNI support enabled

--prefix=/home/initproc/apps/nginx-1.16.0
--error-log-path=/dev/stderr
--http-client-body-temp-path=/tmp/client_body_temp
--without-http_fastcgi_module
--without-http_uwsgi_module
--without-http_scgi_module
--without-http_ssi_module
--without-http_userid_module
--without-http_auth_basic_module
--with-http_ssl_module
--with-http_v2_module
--with-http_realip_module
--with-http_gunzip_module
--with-http_gzip_static_module
--with-http_stub_status_module
--with-stream
--with-stream_ssl_module
--with-stream_realip_module
--with-pcre=/home/initproc/srcs/pcre-8.39
--with-pcre-opt=-DSUPPORT_UTF  # if without this option, njs 0.3.1 module doesn't work with javascript vm error internally
--with-openssl=/home/initproc/srcs/openssl-1.0.2r
--with-threads
--with-debug
--with-file-aio
--with-http_realip_module
--add-module=/home/initproc/srcs/njs-0.3.1/nginx

If I change the code as below, problem looks be solved.
However I'm not sure this is a right way, because I'm not familiar with nginx module development.
I refer to the ngx_http_send_special(ngx_http_request_t *r, ngx_uint_t flags) function in ./src/http/ngx_http_request.c and module development guide(http://nginx.org/en/docs/dev/development_guide.html.)

I hope to someone verify this patch.

nginx/ngx_http_js_module.c

--- ./ngx_http_js_module.c	2019-04-30 18:25:15.040252098 +0900
+++ ./ngx_http_js_module_patch.c	2019-04-30 18:25:11.228208023 +0900
@@ -606,7 +606,27 @@
         return;
     }
 
-    if (ngx_http_output_filter(r, NULL) == NGX_ERROR) {
+    ngx_buf_t    *b;
+    ngx_chain_t   out;
+
+    b = ngx_calloc_buf(r->pool);
+    if (b == NULL) {
+        return ;
+    }
+
+    if (r == r->main && !r->post_action) {
+        b->last_buf = 1;
+    } else {
+        b->sync = 1;
+        b->last_in_chain = 1;
+    }
+
+    out.buf = b;
+    out.next = NULL;
+
+    if (ngx_http_output_filter(r, &out) == NGX_ERROR) {

from njs.

xeioex commented on August 20, 2024 1

Fixed in nginx here.
Fixed since nginx-1.17.0.

from njs.

initproc commented on August 20, 2024

@janglapuk
I get same problem. Did you solve this or have any progress?

from njs.

janglapuk commented on August 20, 2024

@janglapuk
I get same problem. Did you solve this or have any progress?

No, I didn't. It's a long time issue. Just forget it, use Lua for nginx for that issue (if I not mistaken).

from njs.

initproc commented on August 20, 2024

@janglapuk
Thank you for your reply.

from njs.

xeioex commented on August 20, 2024

@initproc

Can please you share your debug.log?

from njs.

initproc commented on August 20, 2024

@xeioex

First of all, there is a bug in my patch. If njs sub_request returns over the 'postpone_output' size(default
1460 bytes), njs sub_request returns its body to the client. To avoid this, increasing postpone_output value can be a workaround, but it is not a good solution.
nginx configuration & njs script

worker_processes  1;

error_log  logs/error.log debug;
    
events {
    worker_connections  1024;
}

http {
    include       mime.types;
    default_type  application/octet-stream;

    js_include test.js;

    sendfile        on;

    keepalive_timeout  65;

    gzip  on;

    server {
        listen       8090;
        server_name  localhost;
    
        location / {
            root   html;
            index  index.html index.htm;
        }

        location /subreq {
            # postpone_output 1024000;
            proxy_pass https://www.google.com/;
        }

        location /test_url {
            js_content req_www_google;
        }

        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   html;
        }
    }
}

/// test.js
function req_www_google(r) {
    r.subrequest("/subreq",
        function(res) {
            r.log("return status " + res.status);
            r.log("return body " + res.responseBody);

            r.return(200, "Done");
        });
}

test command and nginx debug log (before patch)

bash> curl http://127.0.0.1:8090/test_url
curl: (52) Empty reply from server

2019/05/02 18:53:43 [debug] 335#335: bind() 0.0.0.0:8090 #6
2019/05/02 18:53:43 [notice] 335#335: using the "epoll" event method
2019/05/02 18:53:43 [debug] 335#335: counter: 00007F5EED041080, 1
2019/05/02 18:53:43 [notice] 335#335: nginx/1.16.0
2019/05/02 18:53:43 [notice] 335#335: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11)
2019/05/02 18:53:43 [notice] 335#335: OS: Linux 4.4.0-146-generic
2019/05/02 18:53:43 [notice] 335#335: getrlimit(RLIMIT_NOFILE): 1024:1048576
2019/05/02 18:53:43 [debug] 336#336: write: 7, 00007FFD81A8BE30, 4, 0
2019/05/02 18:53:43 [debug] 336#336: setproctitle: "nginx: master process ./nginx"
2019/05/02 18:53:43 [notice] 336#336: start worker processes
2019/05/02 18:53:43 [debug] 336#336: channel 3:7
2019/05/02 18:53:43 [notice] 336#336: start worker process 337
2019/05/02 18:53:43 [debug] 336#336: sigsuspend
2019/05/02 18:53:43 [debug] 337#337: add cleanup: 00000000027E3AF0
2019/05/02 18:53:43 [debug] 337#337: malloc: 00000000027E6F10:8
2019/05/02 18:53:43 [debug] 337#337: notify eventfd: 9
2019/05/02 18:53:43 [debug] 337#337: eventfd: 10
2019/05/02 18:53:43 [debug] 337#337: testing the EPOLLRDHUP flag: success
2019/05/02 18:53:43 [debug] 337#337: malloc: 00000000027BA8E0:6144
2019/05/02 18:53:43 [debug] 337#337: malloc: 00007F5EECFD6010:253952
2019/05/02 18:53:43 [debug] 337#337: malloc: 00000000027EA070:98304
2019/05/02 18:53:43 [debug] 337#337: malloc: 0000000002802080:98304
2019/05/02 18:53:43 [debug] 337#337: epoll add event: fd:6 op:1 ev:00002001
2019/05/02 18:53:43 [debug] 337#337: epoll add event: fd:7 op:1 ev:00002001
2019/05/02 18:53:43 [debug] 337#337: setproctitle: "nginx: worker process"
2019/05/02 18:53:43 [debug] 337#337: worker cycle
2019/05/02 18:53:43 [debug] 337#337: epoll timer: -1
2019/05/02 18:53:47 [debug] 337#337: epoll: fd:6 ev:0001 d:00007F5EECFD6010
2019/05/02 18:53:47 [debug] 337#337: accept on 0.0.0.0:8090, ready: 0
2019/05/02 18:53:47 [debug] 337#337: posix_memalign: 00000000027B5420:512 @16
2019/05/02 18:53:47 [debug] 337#337: *1 accept: 127.0.0.1:44860 fd:3
2019/05/02 18:53:47 [debug] 337#337: *1 event timer add: 3: 60000:551449719
2019/05/02 18:53:47 [debug] 337#337: *1 reusable connection: 1
2019/05/02 18:53:47 [debug] 337#337: *1 epoll add event: fd:3 op:1 ev:80002001
2019/05/02 18:53:47 [debug] 337#337: timer delta: 3648
2019/05/02 18:53:47 [debug] 337#337: worker cycle
2019/05/02 18:53:47 [debug] 337#337: epoll timer: 60000
2019/05/02 18:53:47 [debug] 337#337: epoll: fd:3 ev:0001 d:00007F5EECFD6200
2019/05/02 18:53:47 [debug] 337#337: *1 http wait request handler
2019/05/02 18:53:47 [debug] 337#337: *1 malloc: 00000000027E6890:1024
2019/05/02 18:53:47 [debug] 337#337: *1 recv: eof:0, avail:1
2019/05/02 18:53:47 [debug] 337#337: *1 recv: fd:3 86 of 1024
2019/05/02 18:53:47 [debug] 337#337: *1 reusable connection: 0
2019/05/02 18:53:47 [debug] 337#337: *1 posix_memalign: 00000000027BC0F0:4096 @16
2019/05/02 18:53:47 [debug] 337#337: *1 http process request line
2019/05/02 18:53:47 [debug] 337#337: *1 http request line: "GET /test_url HTTP/1.1"
2019/05/02 18:53:47 [debug] 337#337: *1 http uri: "/test_url"
2019/05/02 18:53:47 [debug] 337#337: *1 http args: ""
2019/05/02 18:53:47 [debug] 337#337: *1 http exten: ""
2019/05/02 18:53:47 [debug] 337#337: *1 posix_memalign: 00000000027BD100:4096 @16
2019/05/02 18:53:47 [debug] 337#337: *1 http process request header line
2019/05/02 18:53:47 [debug] 337#337: *1 http header: "Host: 127.0.0.1:8090"
2019/05/02 18:53:47 [debug] 337#337: *1 http header: "User-Agent: curl/7.52.1"
2019/05/02 18:53:47 [debug] 337#337: *1 http header: "Accept: */*"
2019/05/02 18:53:47 [debug] 337#337: *1 http header done
2019/05/02 18:53:47 [debug] 337#337: *1 event timer del: 3: 551449719
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 0
2019/05/02 18:53:47 [debug] 337#337: *1 rewrite phase: 1
2019/05/02 18:53:47 [debug] 337#337: *1 test location: "/"
2019/05/02 18:53:47 [debug] 337#337: *1 test location: "subreq"
2019/05/02 18:53:47 [debug] 337#337: *1 test location: "test_url"
2019/05/02 18:53:47 [debug] 337#337: *1 using configuration "/test_url"
2019/05/02 18:53:47 [debug] 337#337: *1 http cl:-1 max:1048576
2019/05/02 18:53:47 [debug] 337#337: *1 rewrite phase: 3
2019/05/02 18:53:47 [debug] 337#337: *1 post rewrite phase: 4
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 5
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 6
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 7
2019/05/02 18:53:47 [debug] 337#337: *1 access phase: 8
2019/05/02 18:53:47 [debug] 337#337: *1 post access phase: 9
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 10
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 11
2019/05/02 18:53:47 [debug] 337#337: *1 http js content handler
2019/05/02 18:53:47 [debug] 337#337: *1 http js content event handler
2019/05/02 18:53:47 [debug] 337#337: *1 add cleanup: 00000000027BCE40
2019/05/02 18:53:47 [debug] 337#337: *1 http js content call "req_www_google"
2019/05/02 18:53:47 [debug] 337#337: *1 http subrequest "/subreq?"
2019/05/02 18:53:47 [debug] 337#337: *1 http finalize request: -4, "/test_url?" a:1, c:3
2019/05/02 18:53:47 [debug] 337#337: *1 http request count:3 blk:0
2019/05/02 18:53:47 [debug] 337#337: *1 http posted request: "/subreq?"
2019/05/02 18:53:47 [debug] 337#337: *1 rewrite phase: 1
2019/05/02 18:53:47 [debug] 337#337: *1 test location: "/" 
2019/05/02 18:53:47 [debug] 337#337: *1 test location: "subreq"
2019/05/02 18:53:47 [debug] 337#337: *1 using configuration "/subreq"
2019/05/02 18:53:47 [debug] 337#337: *1 http cl:-1 max:1048576
2019/05/02 18:53:47 [debug] 337#337: *1 rewrite phase: 3
2019/05/02 18:53:47 [debug] 337#337: *1 post rewrite phase: 4
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 5
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 6
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 7
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 10
2019/05/02 18:53:47 [debug] 337#337: *1 generic phase: 11
2019/05/02 18:53:47 [debug] 337#337: *1 posix_memalign: 000000000281C110:4096 @16 
2019/05/02 18:53:47 [debug] 337#337: *1 http init upstream, client timer: 0
2019/05/02 18:53:47 [debug] 337#337: *1 epoll add event: fd:3 op:3 ev:80002005
2019/05/02 18:53:47 [debug] 337#337: *1 http script copy: "Host"
2019/05/02 18:53:47 [debug] 337#337: *1 http script var: "www.google.com"
2019/05/02 18:53:47 [debug] 337#337: *1 http script copy: "Connection"
2019/05/02 18:53:47 [debug] 337#337: *1 http script copy: "close"
2019/05/02 18:53:47 [debug] 337#337: *1 http script copy: ""
2019/05/02 18:53:47 [debug] 337#337: *1 http script copy: ""
2019/05/02 18:53:47 [debug] 337#337: *1 http proxy header: "User-Agent: curl/7.52.1"
2019/05/02 18:53:47 [debug] 337#337: *1 http proxy header: "Accept: */*"
2019/05/02 18:53:47 [debug] 337#337: *1 http proxy header:
"GET / HTTP/1.0^M
Host: www.google.com^M
Connection: close^M
User-Agent: curl/7.52.1^M
Accept: */*^M
^M
"
2019/05/02 18:53:47 [debug] 337#337: *1 http cleanup add: 00000000027BE0E8
2019/05/02 18:53:47 [debug] 337#337: *1 get rr peer, try: 2
2019/05/02 18:53:47 [debug] 337#337: *1 get rr peer, current: 00000000027E03B0 -1
2019/05/02 18:53:47 [debug] 337#337: *1 stream socket 11
2019/05/02 18:53:47 [debug] 337#337: *1 epoll add connection: fd:11 ev:80002005
2019/05/02 18:53:47 [debug] 337#337: *1 connect to 216.58.197.196:443, fd:11 #2
2019/05/02 18:53:47 [debug] 337#337: *1 http upstream connect: -2
2019/05/02 18:53:47 [debug] 337#337: *1 posix_memalign: 00000000027E7920:128 @16 
2019/05/02 18:53:47 [debug] 337#337: *1 event timer add: 11: 60000:551449719
2019/05/02 18:53:47 [debug] 337#337: *1 http finalize request: -4, "/subreq?" a:0, c:3 
2019/05/02 18:53:47 [debug] 337#337: *1 http request count:3 blk:0
2019/05/02 18:53:47 [debug] 337#337: timer delta: 0
2019/05/02 18:53:47 [debug] 337#337: worker cycle
2019/05/02 18:53:47 [debug] 337#337: epoll timer: 60000
2019/05/02 18:53:47 [debug] 337#337: epoll: fd:3 ev:0004 d:00007F5EECFD6200
2019/05/02 18:53:47 [debug] 337#337: *1 http run request: "/test_url?"
2019/05/02 18:53:47 [debug] 337#337: *1 http js content write event handler
2019/05/02 18:53:47 [debug] 337#337: *1 http output filter "/test_url?"
2019/05/02 18:53:47 [debug] 337#337: *1 http copy filter: "/test_url?"
2019/05/02 18:53:47 [debug] 337#337: *1 http write filter: l:0 f:0 s:0 
2019/05/02 18:53:47 [alert] 337#337: *1 the http output chain is empty while connecting to upstream, client: 127.0.0.1, server: localhost, request: "GET /test_url HTTP/1.1", host: "127.0.0.1:8090"
2019/05/02 18:53:47 [debug] 337#337: *1 http copy filter: -1 "/test_url?"
2019/05/02 18:53:47 [debug] 337#337: *1 http finalize request: -1, "/test_url?" a:1, c:2 
2019/05/02 18:53:47 [debug] 337#337: *1 http terminate request count:2
2019/05/02 18:53:47 [debug] 337#337: *1 cleanup http upstream request: "/subreq"
2019/05/02 18:53:47 [debug] 337#337: *1 finalize http upstream request: -4
2019/05/02 18:53:47 [debug] 337#337: *1 finalize http proxy request
2019/05/02 18:53:47 [debug] 337#337: *1 free rr peer 2 0 
2019/05/02 18:53:47 [debug] 337#337: *1 close http upstream connection: 11
2019/05/02 18:53:47 [debug] 337#337: *1 free: 00000000027E7920, unused: 48
2019/05/02 18:53:47 [debug] 337#337: *1 event timer del: 11: 551449719
2019/05/02 18:53:47 [debug] 337#337: *1 reusable connection: 0
2019/05/02 18:53:47 [debug] 337#337: *1 http finalize request: -4, "/subreq?" a:0, c:2 
2019/05/02 18:53:47 [debug] 337#337: *1 http request count:2 blk:0
2019/05/02 18:53:47 [debug] 337#337: *1 http terminate cleanup count:1 blk:0
2019/05/02 18:53:47 [debug] 337#337: *1 http posted request: "/test_url?"
2019/05/02 18:53:47 [debug] 337#337: *1 http terminate handler count:1
2019/05/02 18:53:47 [debug] 337#337: *1 http request count:1 blk:0
2019/05/02 18:53:47 [debug] 337#337: *1 http close request
2019/05/02 18:53:47 [debug] 337#337: *1 http log handler
2019/05/02 18:53:47 [debug] 337#337: *1 run cleanup: 00000000027BCE40
2019/05/02 18:53:47 [error] 337#337: *1 pending events while closing request, client: 127.0.0.1, server: 0.0.0.0:8090
2019/05/02 18:53:47 [debug] 337#337: *1 free: 00000000027BC0F0, unused: 0
2019/05/02 18:53:47 [debug] 337#337: *1 free: 00000000027BD100, unused: 0
2019/05/02 18:53:47 [debug] 337#337: *1 free: 000000000281C110, unused: 2576
2019/05/02 18:53:47 [debug] 337#337: *1 close http connection: 3
2019/05/02 18:53:47 [debug] 337#337: *1 reusable connection: 0
2019/05/02 18:53:47 [debug] 337#337: *1 free: 00000000027E6890
2019/05/02 18:53:47 [debug] 337#337: *1 free: 00000000027B5420, unused: 136
2019/05/02 18:53:47 [debug] 337#337: timer delta: 4
2019/05/02 18:53:47 [debug] 337#337: worker cycle
2019/05/02 18:53:47 [debug] 337#337: epoll timer: -1

after patch without postpone_output directive
- command (curl result contains google web page and 'Done' text by njs code)

bash> curl http://127.0.0.1:8090/test_url
<!doctype html><html itemscope="" itemtype="http://schema.org/WebPage" lang="ko"><head><meta content="text/html; charset=UTF-8" http-equiv="Content-Type"><meta content="/images/branding/googleg/1x/googleg_standard_color_128dp.png" itemprop="image"><title>Google</title><script nonce="21qEDWGfFuAcCHnn/oFelg==">(function(){window.google={kEI:'BL_KXKH8Hprm-AbhjZWoCQ',kEXPI:'0,1353747,57,50,1908,2422,697,528,730,224,529,1046,1258,142,1751,57,528,350,667,41,48,137,412,9,2332995,329482,1294,12383,4855,32692,15247,867,12163,5281,9044,2196,364,3319,5505,2442,260,3742,461,904,575,835,284,2,578,728,2431,1362,4323,4967,774,2252,4749,1144,2,1745,220,2595,3601,669,1050,1808,1397,81,7,475,17,619,29,1395,978,7931,1288,2,3107,899,797,1220,38,920,746,7,120,1215,1366,346,1,1264,2736,3061,2,631,732,1671,159,2,4,2,670,44,3745,751,162,125,2607,632,2228,655,21,318,1592,389,142,1247,403,374,1,372,1013,302,606,97,756,98,392,29,77,323,992,1107,10,168,8,290,837,235,78,365,367,450,174,563,167,239,599,11,14,10,413,161,1088,649,187,208,766,9,25,177,129,194,5,1162,90,66,475,154,145,92,1,31,200,65,90,39,444,86,278,90,3,112,58,104,24,160,67,69,26,327,131,145,698,528,84,422,18,33,9,61,13,12,112,641,183,23,165,561,201,151,63,1126,2,7,7,754,393,16,28,304,85,427,42,605,639,132,7,356,117,67,7,179,327,58,151,348,23,72,44,5939389,2920,20,5997495,42,2799863,4,1572,549,333,444,1,2,80,1,900,581,4,311,6,3,1,2,2132,1,1,1,1,1,414,1,748,141,59,726,3,7,563,1,1735,1,105,14,2,48,8,5,13,43,1,13,16',authuser:0,kscs:'c9c918f0_BL_KXKH8Hprm-AbhjZWoCQ',kGL:'KR'};google.sn='webhp';google.kHL='ko';})();(function(){google.lc=[];google.li=0;google.getEI=function(a){for(var b;a&&(!a.getAttribute||!(b=a.getAttribute("eid")));)a=a.parentNode;return b||google.kEI};google.getLEI=function(a){for(var b=null;a&&(!a.getAttribute||!(b=a.getAttribute("leid")));)a=a.parentNode;return b};google.https=function(){return"https:"==window.location.protocol};google.ml=function(){return null};google.time=function(){return(new Date).getTime()};google.log=function(a,b,e,c,g){if(a=google.logUrl(a,b,e,c,g)){b=new Image;var d=google.lc,f=google.li;d[f]=b;b.onerror=b.onload=b.onabort=function(){delete d[f]};google.vel&&google.vel.lu&&google.vel.lu(a);b.src=a;google.li=f+1}};google.logUrl=function(a,b,e,c,g){var d="",f=google.ls||"";e||-1!=b.search("&ei=")||(d="&ei="+google.getEI(c),-1==b.search("&lei=")&&(c=google.getLEI(c))&&(d+="&lei="+c));c="";!e&&google.cshid&&-1==b.search("&cshid=")&&"slh"!=a&&(c="&cshid="+google.cshid);a=e||"/"+(g||"gen_204")+"?atyp=i&ct="+a+"&cad="+b+d+f+"&zx="+google.time()+c;/^http:/i.test(a)&&google.https()&&(google.ml(Error("a"),!1,{src:a,glmm:1}),a="");return a};}).call(this);(function(){google.y={};google.x=function(a,b){if(a)var c=a.id;else{do c=Math.random();while(google.y[c])}google.y[c]=[a,b];return!1};google.lm=[];google.plm=function(a){google.lm.push.apply(google.lm,a)};google.lq=[];google.load=function(a,b,c){google.lq.push([[a],b,c])};google.loadAll=function(a,b){google.lq.push([a,b])};}).call(this);google.f={};var a=window.location,b=a.href.indexOf("#");if(0<=b){var c=a.href.substring(b+1);/(^|&)q=/.test(c)&&-1==c.indexOf("#")&&a.replace("/search?"+c.replace(/(^|&)fp=[^&]*/g,"")+"&cad=h")};</script><style>#gbar,#guser{font-size:13px;padding-top:1px !important;}#gbar{height:22px}#guser{padding-bottom:7px !important;text-align:right}.gbh,.gbd{border-top:1px solid #c9d7f1;font-size:1px}.gbh{height:0;position:absolute;top:24px;width:100%}@media all{.gb1{height:22px;margin-right:.5em;vertical-align:top}#gbar{float:left}}a.gb1,a.gb4{text-decoration:underline !important}a.gb1,a.gb4{color:#00c !important}.gbi .gb4{color:#dd8e27 !important}.gbf .gb4{color:#900 !important}
</style><style>body,td,a,p,.h{font-family:&#44404;&#47548;,&#46027;&#50880;,arial,sans-serif}.ko{font-size:9pt}body{margin:0;overflow-y:scroll}#gog{padding:3px 8px 0}td{line-height:.8em}.gac_m td{line-height:17px}form{margin-bottom:20px}.h{color:#36c}.q{color:#00c}.ts td{padding:0}.ts{border-collapse:collapse}em{font-weight:bold;font-style:normal}.lst{height:25px;width:496px}.gsfi,.lst{font:18px arial,sans-serif}.gsfs{font:17px arial,sans-serif}.ds{display:inline-box;display:inline-block;margin:3px 0 4px;margin-left:4px}input{font-family:inherit}a.gb1,a.gb2,a.gb3,a.gb4{color:#11c !important}body{background:#fff;color:black}a{color:#11c;text-decoration:none}a:hover,a:active{text-decoration:underline}.fl a{color:#36c}a:visited{color:#551a8b}a.gb1,a.gb4{text-decoration:underline}a.gb3:hover{text-decoration:none}#ghead a.gb2:hover{color:#fff !important}.sblc{padding-top:5px}.sblc a{display:block;margin:2px 0;margin-left:13px;font-size:11px}.lsbb{background:#eee;border:solid 1px;border-color:#ccc #999 #999 #ccc;height:30px}.lsbb{display:block}.ftl,#fll a{display:inline-block;margin:0 12px}.lsb{background:url(/images/nav_logo229.png) 0 -261px repeat-x;border:none;color:#000;cursor:pointer;height:30px;margin:0;outline:0;font:15px arial,sans-serif;vertical-align:top}.lsb:active{background:#ccc}.lst:focus{outline:none}.tiah{width:458px}</style><script nonce="21qEDWGfFuAcCHnn/oFelg=="></script></head><body bgcolor="#fff"><script nonce="21qEDWGfFuAcCHnn/oFelg==">(function(){var src='/images/nav_logo229.png';var iesg=false;document.body.onload = function(){window.n && window.n();if (document.images){new Image().src=src;}
if (!iesg){document.f&&document.f.q.focus();document.gbqf&&document.gbqf.q.focus();}
}
})();</script><div id="mngb"> <div id=gbar><nobr><b class=gb1>&#44160;&#49353;</b> <a class=gb1 href="https://www.google.co.kr/imghp?hl=ko&tab=wi">&#51060;&#48120;&#51648;</a> <a class=gb1 href="https://maps.google.co.kr/maps?hl=ko&tab=wl">&#51648;&#46020;</a> <a class=gb1 href="https://play.google.com/?hl=ko&tab=w8">Play</a> <a class=gb1 href="https://www.youtube.com/?gl=KR&tab=w1">YouTube</a> <a class=gb1 href="https://news.google.co.kr/nwshp?hl=ko&tab=wn">&#45684;&#49828;</a> <a class=gb1 href="https://mail.google.com/mail/?tab=wm">Gmail</a> <a class=gb1 href="https://drive.google.com/?tab=wo">&#46300;&#46972;&#51060;&#48652;</a> <a class=gb1 style="text-decoration:none" href="https://www.google.co.kr/intl/ko/about/products?tab=wh"><u>&#45908;&#48372;&#44592;</u> &raquo;</a></nobr></div><div id=guser width=100%><nobr><span id=gbn class=gbi></span><span id=gbf class=gbf></span><span id=gbe></span><a href="http://www.google.co.kr/history/optout?hl=ko" class=gb4>&#50937; &#44592;&#47197;</a> | <a  href="/preferences?hl=ko" class=gb4>&#49444;&#51221;</a> | <a target=_top id=gb_70 href="https://accounts.google.com/ServiceLogin?hl=ko&passive=true&continue=https://www.google.com/" class=gb4>&#47196;&#44536;&#51064;</a></nobr></div><div class=gbh style=left:0></div><div class=gbh style=right:0></div> </div><center><br clear="all" id="lgpd"><div id="lga"><img alt="Google" height="92" src="/images/branding/googlelogo/1x/googlelogo_white_background_color_272x92dp.png" style="padding:28px 0 14px" width="272" id="hplogo" onload="window.lol&&lol()"><br><br></div><form action="/search" name="f"><table cellpadding="0" cellspacing="0"><tr valign="top"><td width="25%">&nbsp;</td><td align="center" nowrap=""><input name="ie" value="ISO-8859-1" type="hidden"><input value="ko" name="hl" type="hidden"><input name="source" type="hidden" value="hp"><input name="biw" type="hidden"><input name="bih" type="hidden"><div class="ds" style="height:32px;margin:4px 0"><div style="position:relative;zoom:1"><input style="color:#000;margin:0;padding:5px 8px 0 6px;vertical-align:top;padding-right:38px" autocomplete="off" class="lst tiah" value="" title="Google &#44160;&#49353;" maxlength="2048" name="q" size="57"><img src="/textinputassistant/tia.png" style="position:absolute;cursor:pointer;right:5px;top:4px;z-index:300" data-script-url="/textinputassistant/11/ko_tia.js" alt="" height="23" onclick="var s=document.createElement('script');s.src=this.getAttribute('data-script-url');(document.getElementById('xjsc')||document.body).appendChild(s);" width="27"></div></div><br style="line-height:0"><span class="ds"><span class="lsbb"><input class="lsb" value="Google &#44160;&#49353;" name="btnG" type="submit"></span></span><span class="ds"><span class="lsbb"><input class="lsb" value="I&#8217;m Feeling Lucky" name="btnI" onclick="if(this.form.q.value)this.checked=1; else top.location='/doodles/'" type="submit"></span></span></td><td class="fl sblc" align="left" nowrap="" width="25%"><a href="/advanced_search?hl=ko&amp;authuser=0">&#44256;&#44553;&#44160;&#49353;</a><a href="/language_tools?hl=ko&amp;authuser=0">&#50616;&#50612;&#46020;&#44396;</a></td></tr></table><input id="gbv" name="gbv" type="hidden" value="1"><script nonce="21qEDWGfFuAcCHnn/oFelg==">(function(){var a,b="1";if(document&&document.getElementById)if("undefined"!=typeof XMLHttpRequest)b="2";else if("undefined"!=typeof ActiveXObject){var c,d,e=["MSXML2.XMLHTTP.6.0","MSXML2.XMLHTTP.3.0","MSXML2.XMLHTTP","Microsoft.XMLHTTP"];for(c=0;d=e[c++];)try{new ActiveXObject(d),b="2"}catch(h){}}a=b;if("2"==a&&-1==location.search.indexOf("&gbv=2")){var f=google.gbvu,g=document.getElementById("gbv");g&&(g.value=a);f&&window.setTimeout(function(){location.href=f},0)};}).call(this);</script></form><div id="gac_scont"></div><div style="font-size:83%;min-height:3.5em"><br></div><span id="footer"><div style="font-size:10pt"><div style="margin:19px auto;text-align:center" id="fll"><a href="/intl/ko/ads/">&#44305;&#44256; &#54532;&#47196;&#44536;&#47016;</a><a href="http://www.google.co.kr/intl/ko/services/">&#48708;&#51592;&#45768;&#49828; &#49556;&#47336;&#49496;</a><a href="/intl/ko/about.html">Google &#51221;&#48372;</a><a href="https://www.google.com/setprefdomain?prefdom=KR&amp;prev=https://www.google.co.kr/&amp;sig=K_bMHi1zNHtKv_X7UFl2T_pVSvJXQ%3D">Google.co.kr</a></div></div><p style="color:#767676;font-size:8pt">&copy; 2019 - <a href="/intl/ko/policies/privacy/">&#44060;&#51064;&#51221;&#48372;&#52376;&#47532;&#48169;&#52840;</a> - <a href="/intl/ko/policies/terms/">&#50557;&#44288;</a></p></span></center><script nonce="21qEDWGfFuAcCHnn/oFelg==">(function(){window.google.cdo={height:0,width:0};(function(){var a=window.innerWidth,b=window.innerHeight;if(!a||!b){var c=window.document,d="CSS1Compat"==c.compatMode?c.documentElement:c.body;a=d.clientWidth;b=d.clientHeight}a&&b&&(a!=google.cdo.width||b!=google.cdo.height)&&google.log("","","/client_204?&atyp=i&biw="+a+"&bih="+b+"&ei="+google.kEI);}).call(this);})();(function(){var u='/xjs/_/js/k\x3dxjs.hp.en.ov32b9Iax-Q.O/m\x3dsb_he,d/am\x3dwKAW/rt\x3dj/d\x3d1/rs\x3dACT90oEm4TcmHtBnN3YUOQfTIMmsoFf_dA';setTimeout(function(){var a=document.createElement("script");a.src=u;google.timers&&google.timers.load&&google.tick&&google.tick("load","xjsls");document.body.appendChild(a)},0);})();(function(){window.google.xjsu='/xjs/_/js/k\x3dxjs.hp.en.ov32b9Iax-Q.O/m\x3dsb_he,d/am\x3dwKAW/rt\x3dj/d\x3d1/rs\x3dACT90oEm4TcmHtBnN3YUOQfTIMmsoFf_dA';})();function _DumpException(e){throw e;}
function _F_installCss(c){}
(function(){google.spjs=false;})();google.sm=1;(function(){var pmc='{\x22Qnk92g\x22:{},\x22RWGcrA\x22:{},\x22U5B21g\x22:{},\x22YFCs/g\x22:{},\x22ZI/YVQ\x22:{},\x22d\x22:{},\x22sb_he\x22:{\x22agen\x22:true,\x22cgen\x22:true,\x22client\x22:\x22heirloom-hp\x22,\x22dh\x22:true,\x22dhqt\x22:true,\x22ds\x22:\x22\x22,\x22ffql\x22:\x22ko\x22,\x22fl\x22:true,\x22host\x22:\x22google.com\x22,\x22isbh\x22:28,\x22jsonp\x22:true,\x22msgs\x22:{\x22cibl\x22:\x22&#44160;&#49353;&#50612; &#51648;&#50864;&#44592;\x22,\x22dym\x22:\x22&#51060;&#44163;&#51012; &#52286;&#51004;&#49512;&#45208;&#50836;?\x22,\x22lcky\x22:\x22I&#8217;m Feeling Lucky\x22,\x22lml\x22:\x22&#51088;&#49464;&#55176; &#50508;&#50500;&#48372;&#44592;\x22,\x22oskt\x22:\x22&#51077;&#47141; &#46020;&#44396;\x22,\x22psrc\x22:\x22&#44160;&#49353;&#50612;&#44032; \\u003Ca href\x3d\\\x22/history\\\x22\\u003E&#50937; &#44592;&#47197;\\u003C/a\\u003E&#50640;&#49436; &#49325;&#51228;&#46104;&#50632;&#49845;&#45768;&#45796;.\x22,\x22psrl\x22:\x22&#49325;&#51228;\x22,\x22sbit\x22:\x22&#51060;&#48120;&#51648;&#47196; &#44160;&#49353;\x22,\x22srch\x22:\x22Google &#44160;&#49353;\x22},\x22ovr\x22:{},\x22pq\x22:\x22\x22,\x22refpd\x22:true,\x22refspre\x22:true,\x22rfs\x22:[],\x22sbpl\x22:24,\x22sbpr\x22:24,\x22scd\x22:10,\x22sce\x22:5,\x22stok\x22:\x22LOWRO50ZOV6xq-wqNcBXwFhuzEw\x22,\x22uhde\x22:false}}';google.pmc=JSON.parse(pmc);})();</script>        </body></html>HTTP/1.1 200 OK
Server: nginx/1.16.0
Date: Thu, 02 May 2019 09:57:24 GMT
Content-Type: application/octet-stream
Content-Length: 4
Connection: keep-alive

error log

2019/05/02 18:57:21 [debug] 544#544: bind() 0.0.0.0:8090 #6
2019/05/02 18:57:21 [notice] 544#544: using the "epoll" event method
2019/05/02 18:57:21 [debug] 544#544: counter: 00007F201509C080, 1
2019/05/02 18:57:21 [notice] 544#544: nginx/1.16.0
2019/05/02 18:57:21 [notice] 544#544: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11)
2019/05/02 18:57:21 [notice] 544#544: OS: Linux 4.4.0-146-generic
2019/05/02 18:57:21 [notice] 544#544: getrlimit(RLIMIT_NOFILE): 1024:1048576
2019/05/02 18:57:21 [debug] 545#545: write: 7, 00007FFE8BAF4190, 4, 0
2019/05/02 18:57:21 [debug] 545#545: setproctitle: "nginx: master process ./nginx"
2019/05/02 18:57:21 [notice] 545#545: start worker processes
2019/05/02 18:57:21 [debug] 545#545: channel 3:7
2019/05/02 18:57:21 [notice] 545#545: start worker process 546
2019/05/02 18:57:21 [debug] 545#545: sigsuspend
2019/05/02 18:57:21 [debug] 546#546: add cleanup: 0000000001B0DAD8
2019/05/02 18:57:21 [debug] 546#546: malloc: 0000000001B10F10:8
2019/05/02 18:57:21 [debug] 546#546: notify eventfd: 9
2019/05/02 18:57:21 [debug] 546#546: eventfd: 10
2019/05/02 18:57:21 [debug] 546#546: testing the EPOLLRDHUP flag: success
2019/05/02 18:57:21 [debug] 546#546: malloc: 0000000001AE48E0:6144
2019/05/02 18:57:21 [debug] 546#546: malloc: 00007F2015031010:253952
2019/05/02 18:57:21 [debug] 546#546: malloc: 0000000001B14070:98304
2019/05/02 18:57:21 [debug] 546#546: malloc: 0000000001B2C080:98304
2019/05/02 18:57:21 [debug] 546#546: epoll add event: fd:6 op:1 ev:00002001
2019/05/02 18:57:21 [debug] 546#546: epoll add event: fd:7 op:1 ev:00002001
2019/05/02 18:57:21 [debug] 546#546: setproctitle: "nginx: worker process"
2019/05/02 18:57:21 [debug] 546#546: worker cycle
2019/05/02 18:57:21 [debug] 546#546: epoll timer: -1
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:6 ev:0001 d:00007F2015031010
2019/05/02 18:57:24 [debug] 546#546: accept on 0.0.0.0:8090, ready: 0
2019/05/02 18:57:24 [debug] 546#546: posix_memalign: 0000000001ADF420:512 @16
2019/05/02 18:57:24 [debug] 546#546: *1 accept: 127.0.0.1:46688 fd:3
2019/05/02 18:57:24 [debug] 546#546: *1 event timer add: 3: 60000:551666690
2019/05/02 18:57:24 [debug] 546#546: *1 reusable connection: 1
2019/05/02 18:57:24 [debug] 546#546: *1 epoll add event: fd:3 op:1 ev:80002001
2019/05/02 18:57:24 [debug] 546#546: timer delta: 2472
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 60000
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:3 ev:0001 d:00007F2015031200
2019/05/02 18:57:24 [debug] 546#546: *1 http wait request handler
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B10890:1024
2019/05/02 18:57:24 [debug] 546#546: *1 recv: eof:0, avail:1
2019/05/02 18:57:24 [debug] 546#546: *1 recv: fd:3 86 of 1024
2019/05/02 18:57:24 [debug] 546#546: *1 reusable connection: 0
2019/05/02 18:57:24 [debug] 546#546: *1 posix_memalign: 0000000001AE60F0:4096 @16
2019/05/02 18:57:24 [debug] 546#546: *1 http process request line
2019/05/02 18:57:24 [debug] 546#546: *1 http request line: "GET /test_url HTTP/1.1"
2019/05/02 18:57:24 [debug] 546#546: *1 http uri: "/test_url"
2019/05/02 18:57:24 [debug] 546#546: *1 http args: ""
2019/05/02 18:57:24 [debug] 546#546: *1 http exten: ""
2019/05/02 18:57:24 [debug] 546#546: *1 posix_memalign: 0000000001AE7100:4096 @16
2019/05/02 18:57:24 [debug] 546#546: *1 http process request header line
2019/05/02 18:57:24 [debug] 546#546: *1 http header: "Host: 127.0.0.1:8090"
2019/05/02 18:57:24 [debug] 546#546: *1 http header: "User-Agent: curl/7.52.1"
2019/05/02 18:57:24 [debug] 546#546: *1 http header: "Accept: */*"
2019/05/02 18:57:24 [debug] 546#546: *1 http header done
2019/05/02 18:57:24 [debug] 546#546: *1 event timer del: 3: 551666690
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 0
2019/05/02 18:57:24 [debug] 546#546: *1 rewrite phase: 1
2019/05/02 18:57:24 [debug] 546#546: *1 test location: "/"
2019/05/02 18:57:24 [debug] 546#546: *1 test location: "subreq"
2019/05/02 18:57:24 [debug] 546#546: *1 test location: "test_url"
2019/05/02 18:57:24 [debug] 546#546: *1 using configuration "/test_url"
2019/05/02 18:57:24 [debug] 546#546: *1 http cl:-1 max:1048576
2019/05/02 18:57:24 [debug] 546#546: *1 rewrite phase: 3
2019/05/02 18:57:24 [debug] 546#546: *1 post rewrite phase: 4
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 5
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 6
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 7
2019/05/02 18:57:24 [debug] 546#546: *1 access phase: 8
2019/05/02 18:57:24 [debug] 546#546: *1 post access phase: 9
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 10
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 11
2019/05/02 18:57:24 [debug] 546#546: *1 http js content handler
2019/05/02 18:57:24 [debug] 546#546: *1 http js content event handler
2019/05/02 18:57:24 [debug] 546#546: *1 add cleanup: 0000000001AE6E40
2019/05/02 18:57:24 [debug] 546#546: *1 http js content call "req_www_google"
2019/05/02 18:57:24 [debug] 546#546: *1 http subrequest "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http finalize request: -4, "/test_url?" a:1, c:3
2019/05/02 18:57:24 [debug] 546#546: *1 http request count:3 blk:0
2019/05/02 18:57:24 [debug] 546#546: *1 http posted request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 rewrite phase: 1
2019/05/02 18:57:24 [debug] 546#546: *1 test location: "/"
2019/05/02 18:57:24 [debug] 546#546: *1 test location: "subreq"
2019/05/02 18:57:24 [debug] 546#546: *1 using configuration "/subreq"
2019/05/02 18:57:24 [debug] 546#546: *1 http cl:-1 max:1048576
2019/05/02 18:57:24 [debug] 546#546: *1 rewrite phase: 3
2019/05/02 18:57:24 [debug] 546#546: *1 post rewrite phase: 4
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 5
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 6
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 7
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 10
2019/05/02 18:57:24 [debug] 546#546: *1 generic phase: 11
2019/05/02 18:57:24 [debug] 546#546: *1 posix_memalign: 0000000001B46110:4096 @16
2019/05/02 18:57:24 [debug] 546#546: *1 http init upstream, client timer: 0
2019/05/02 18:57:24 [debug] 546#546: *1 epoll add event: fd:3 op:3 ev:80002005
2019/05/02 18:57:24 [debug] 546#546: *1 http script copy: "Host"
2019/05/02 18:57:24 [debug] 546#546: *1 http script var: "www.google.com"
2019/05/02 18:57:24 [debug] 546#546: *1 http script copy: "Connection"
2019/05/02 18:57:24 [debug] 546#546: *1 http script copy: "close"
2019/05/02 18:57:24 [debug] 546#546: *1 http script copy: ""
2019/05/02 18:57:24 [debug] 546#546: *1 http script copy: ""
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "User-Agent: curl/7.52.1"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Accept: */*"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header:
"GET / HTTP/1.0^M
Host: www.google.com^M
Connection: close^M
User-Agent: curl/7.52.1^M
Accept: */*^M
^M
"
2019/05/02 18:57:24 [debug] 546#546: *1 http cleanup add: 0000000001AE80E8
2019/05/02 18:57:24 [debug] 546#546: *1 get rr peer, try: 2
2019/05/02 18:57:24 [debug] 546#546: *1 get rr peer, current: 0000000001B0A398 -1
2019/05/02 18:57:24 [debug] 546#546: *1 stream socket 11
2019/05/02 18:57:24 [debug] 546#546: *1 epoll add connection: fd:11 ev:80002005
2019/05/02 18:57:24 [debug] 546#546: *1 connect to 172.217.161.68:443, fd:11 #2
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream connect: -2
2019/05/02 18:57:24 [debug] 546#546: *1 posix_memalign: 0000000001B11920:128 @16
2019/05/02 18:57:24 [debug] 546#546: *1 event timer add: 11: 60000:551666690
2019/05/02 18:57:24 [debug] 546#546: *1 http finalize request: -4, "/subreq?" a:0, c:3
2019/05/02 18:57:24 [debug] 546#546: *1 http request count:3 blk:0
2019/05/02 18:57:24 [debug] 546#546: timer delta: 0
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 60000
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:3 ev:0004 d:00007F2015031200
2019/05/02 18:57:24 [debug] 546#546: *1 http run request: "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 http js content write event handler
2019/05/02 18:57:24 [debug] 546#546: *1 http output filter "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter: l:1 f:0 s:0
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: 0 "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: timer delta: 0
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 60000
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0004 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream send request handler
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B119B0:88
2019/05/02 18:57:24 [debug] 546#546: *1 set session: 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 tcp_nodelay
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_do_handshake: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: timer delta: 92
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59908
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 SSL handshake handler: 0
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_do_handshake: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL handshake handler: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_do_handshake: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: timer delta: 128
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59780
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 SSL handshake handler: 0
2019/05/02 18:57:24 [debug] 546#546: *1 save session: 0000000001B11A10
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_do_handshake: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream ssl handshake: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream send request
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream send request body
2019/05/02 18:57:24 [debug] 546#546: *1 chain writer buf fl:1 s:97
2019/05/02 18:57:24 [debug] 546#546: *1 chain writer in: 0000000001B466D0
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B5F6E0:80
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B47120:16384
2019/05/02 18:57:24 [debug] 546#546: *1 SSL buf copy: 97
2019/05/02 18:57:24 [debug] 546#546: *1 SSL to write: 97
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_write: 97
2019/05/02 18:57:24 [debug] 546#546: *1 chain writer out: 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 event timer del: 11: 551666690
2019/05/02 18:57:24 [debug] 546#546: *1 event timer add: 11: 60000:551667006
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process header
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B4B130:4096
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 96
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 60000
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process header
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy status 200 "200 OK"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Date: Thu, 02 May 2019 09:57:24 GMT"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Expires: -1"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Cache-Control: private, max-age=0"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Content-Type: text/html; charset=ISO-8859-1"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.""
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Server: gws"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "X-XSS-Protection: 0"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "X-Frame-Options: SAMEORIGIN"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Set-Cookie: 1P_JAR=2019-05-02-09; expires=Sat, 01-Jun-2019 09:57:24 GMT; path=/; domain=.google.com"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Set-Cookie: NID=182=dKbtn2qXjSbUKIUdcZqJWwcoUs4U-b7K3voTugq0ei5lPjyGnepY4w-9CuOuHczREpLeeUyd9FitFvXs26P7RHNqOQ-JY-i7OnJrfstaqJYmRljGMnOTN3-ni4-D5UqNH-Ehx_UfzfH_CmZauk_-KjMqAnnyElJsw1YJj_1dUmw; expires=Fri, 01-Nov-2019 09:57:24 GMT; path=/; domain=.google.com; HttpOnly"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Alt-Svc: quic=":443"; ma=2592000; v="46,44,43,39""
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Accept-Ranges: none"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header: "Vary: Accept-Encoding"
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy header done
2019/05/02 18:57:24 [debug] 546#546: *1 http cacheable: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http proxy filter init s:200 h:0 c:0 l:-1
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe preread: 642
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 642 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 642 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667166
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 160
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59840
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 2031 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 2031 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667170
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 4
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59836
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1318
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1318
2019/05/02 18:57:24 [debug] 546#546: *1 input buf #0
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B58830:4096
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 71
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1460
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 1460 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 1460 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667174
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 4
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59832
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 2849 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 2849 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667178
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 4
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59828
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1247
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1247
2019/05/02 18:57:24 [debug] 546#546: *1 input buf #1
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B59840:4096
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 142
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 142
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 142 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 142 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667178
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 0
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59828
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:0005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1389
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: -1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 2
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 2778
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 2920 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 2920 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667186
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream dummy handler
2019/05/02 18:57:24 [debug] 546#546: timer delta: 8
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 59820
2019/05/02 18:57:24 [debug] 546#546: epoll: fd:11 ev:2005 d:00007F20150312F8
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream request: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream process upstream
2019/05/02 18:57:24 [debug] 546#546: *1 pipe read upstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 1176
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 1176
2019/05/02 18:57:24 [debug] 546#546: *1 input buf #2
2019/05/02 18:57:24 [debug] 546#546: *1 posix_memalign: 0000000001B608D0:4096 @16
2019/05/02 18:57:24 [debug] 546#546: *1 malloc: 0000000001B618E0:4096
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 213
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 637
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_read: 0
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_get_error: 5
2019/05/02 18:57:24 [debug] 546#546: *1 peer shutdown SSL cleanly
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 850
2019/05/02 18:57:24 [debug] 546#546: *1 pipe recv chain: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf in   s:1 t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe buf free s:0 t:1 f:0 0000000001B618E0, pos 0000000001B618E0, size: 850 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 pipe length: -1
2019/05/02 18:57:24 [debug] 546#546: *1 input buf #3
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream: 1
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream flush in
2019/05/02 18:57:24 [debug] 546#546: *1 http output filter "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:1 f:0 0000000001B4B130, pos 0000000001B4B41B, size: 3349 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:1 f:0 0000000001B58830, pos 0000000001B58830, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:1 f:0 0000000001B59840, pos 0000000001B59840, size: 4096 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:1 f:0 0000000001B618E0, pos 0000000001B618E0, size: 850 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter: l:0 f:0 s:12391
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter limit 0
2019/05/02 18:57:24 [debug] 546#546: *1 writev: 12391 of 12391
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: 0 "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 pipe write downstream done
2019/05/02 18:57:24 [debug] 546#546: *1 event timer: 11, old: 551667006, new: 551667194
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream exit: 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 finalize http upstream request: 0
2019/05/02 18:57:24 [debug] 546#546: *1 finalize http proxy request
2019/05/02 18:57:24 [debug] 546#546: *1 free rr peer 2 0
2019/05/02 18:57:24 [debug] 546#546: *1 SSL_shutdown: 1
2019/05/02 18:57:24 [debug] 546#546: *1 close http upstream connection: 11
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B47120
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B5F6E0
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B119B0
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B11920, unused: 0
2019/05/02 18:57:24 [debug] 546#546: *1 event timer del: 11: 551667006
2019/05/02 18:57:24 [debug] 546#546: *1 reusable connection: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http upstream temp fd: -1
2019/05/02 18:57:24 [debug] 546#546: *1 http output filter "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter: l:0 f:0 s:0
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: 0 "/subreq?"
2019/05/02 18:57:24 [debug] 546#546: *1 http finalize request: 0, "/subreq?" a:0, c:2
2019/05/02 18:57:24 [debug] 546#546: *1 js subrequest done s: 200 parent ctx: 0000000001AE6DF0
2019/05/02 18:57:24 [info] 546#546: *1 js: return status 200
2019/05/02 18:57:24 [info] 546#546: *1 js: return body
2019/05/02 18:57:24 [debug] 546#546: *1 HTTP/1.1 200 OK^M
Server: nginx/1.16.0^M
Date: Thu, 02 May 2019 09:57:24 GMT^M
Content-Type: application/octet-stream^M
Content-Length: 4^M
Connection: keep-alive^M

2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:1 f:0 0000000001B60BE0, pos 0000000001B60BE0, size: 161 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter: l:0 f:0 s:161
2019/05/02 18:57:24 [debug] 546#546: *1 http output filter "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 write old buf t:1 f:0 0000000001B60BE0, pos 0000000001B60BE0, size: 161 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 write new buf t:0 f:0 0000000000000000, pos 0000000001B44540, size: 4 file: 0, size: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter: l:1 f:0 s:165
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter limit 0
2019/05/02 18:57:24 [debug] 546#546: *1 writev: 165 of 165
2019/05/02 18:57:24 [debug] 546#546: *1 http write filter 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 http copy filter: 0 "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 http request count:2 blk:0
2019/05/02 18:57:24 [debug] 546#546: *1 http posted request: "/test_url?"
2019/05/02 18:57:24 [debug] 546#546: *1 http js content write event handler
2019/05/02 18:57:24 [debug] 546#546: *1 http js content rc: 0
2019/05/02 18:57:24 [debug] 546#546: *1 http finalize request: 0, "/test_url?" a:1, c:1
2019/05/02 18:57:24 [debug] 546#546: *1 set http keepalive handler
2019/05/02 18:57:24 [debug] 546#546: *1 http close request
2019/05/02 18:57:24 [debug] 546#546: *1 http log handler
2019/05/02 18:57:24 [debug] 546#546: *1 run cleanup: 0000000001AE6E40
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B618E0
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B59840
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B58830
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B4B130
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001AE60F0, unused: 0
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001AE7100, unused: 0
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B46110, unused: 8
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B608D0, unused: 2984
2019/05/02 18:57:24 [debug] 546#546: *1 free: 0000000001B10890
2019/05/02 18:57:24 [debug] 546#546: *1 hc free: 0000000000000000
2019/05/02 18:57:24 [debug] 546#546: *1 hc busy: 0000000000000000 0
2019/05/02 18:57:24 [debug] 546#546: *1 tcp_nodelay
2019/05/02 18:57:24 [debug] 546#546: *1 reusable connection: 1
2019/05/02 18:57:24 [debug] 546#546: *1 event timer add: 3: 65000:551672194
2019/05/02 18:57:24 [debug] 546#546: timer delta: 8
2019/05/02 18:57:24 [debug] 546#546: worker cycle
2019/05/02 18:57:24 [debug] 546#546: epoll timer: 65000
2019/05/02 18:58:29 [debug] 546#546: timer delta: 65065
2019/05/02 18:58:29 [debug] 546#546: *1 event timer del: 3: 551672194
2019/05/02 18:58:29 [debug] 546#546: *1 http keepalive handler
2019/05/02 18:58:29 [debug] 546#546: *1 close http connection: 3
2019/05/02 18:58:29 [debug] 546#546: *1 reusable connection: 0
2019/05/02 18:58:29 [debug] 546#546: *1 free: 0000000000000000
2019/05/02 18:58:29 [debug] 546#546: *1 free: 0000000001ADF420, unused: 136
2019/05/02 18:58:29 [debug] 546#546: worker cycle
2019/05/02 18:58:29 [debug] 546#546: epoll timer: -1

after patch with postpone_output directive (set postpone_output 1024000)
- test command

curl http://127.0.0.1:8090/test_url
Done

error log

2019/05/02 19:03:36 [debug] 752#752: bind() 0.0.0.0:8090 #6
2019/05/02 19:03:36 [notice] 752#752: using the "epoll" event method
2019/05/02 19:03:36 [debug] 752#752: counter: 00007F87A7E27080, 1
2019/05/02 19:03:36 [notice] 752#752: nginx/1.16.0
2019/05/02 19:03:36 [notice] 752#752: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11)
2019/05/02 19:03:36 [notice] 752#752: OS: Linux 4.4.0-146-generic
2019/05/02 19:03:36 [notice] 752#752: getrlimit(RLIMIT_NOFILE): 1024:1048576
2019/05/02 19:03:36 [debug] 753#753: write: 7, 00007FFCFC395C50, 4, 0
2019/05/02 19:03:36 [debug] 753#753: setproctitle: "nginx: master process ./nginx"
2019/05/02 19:03:36 [notice] 753#753: start worker processes
2019/05/02 19:03:36 [debug] 753#753: channel 3:7
2019/05/02 19:03:36 [notice] 753#753: start worker process 754
2019/05/02 19:03:36 [debug] 753#753: sigsuspend
2019/05/02 19:03:36 [debug] 754#754: add cleanup: 0000000001A2DAF0
2019/05/02 19:03:36 [debug] 754#754: malloc: 0000000001A30F10:8
2019/05/02 19:03:36 [debug] 754#754: notify eventfd: 9
2019/05/02 19:03:36 [debug] 754#754: eventfd: 10
2019/05/02 19:03:36 [debug] 754#754: testing the EPOLLRDHUP flag: success
2019/05/02 19:03:36 [debug] 754#754: malloc: 0000000001A048E0:6144
2019/05/02 19:03:36 [debug] 754#754: malloc: 00007F87A7DBC010:253952
2019/05/02 19:03:36 [debug] 754#754: malloc: 0000000001A34070:98304
2019/05/02 19:03:36 [debug] 754#754: malloc: 0000000001A4C080:98304
2019/05/02 19:03:36 [debug] 754#754: epoll add event: fd:6 op:1 ev:00002001
2019/05/02 19:03:36 [debug] 754#754: epoll add event: fd:7 op:1 ev:00002001
2019/05/02 19:03:36 [debug] 754#754: setproctitle: "nginx: worker process"
2019/05/02 19:03:36 [debug] 754#754: worker cycle
2019/05/02 19:03:36 [debug] 754#754: epoll timer: -1
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:6 ev:0001 d:00007F87A7DBC010
2019/05/02 19:03:40 [debug] 754#754: accept on 0.0.0.0:8090, ready: 0
2019/05/02 19:03:40 [debug] 754#754: posix_memalign: 00000000019FF420:512 @16
2019/05/02 19:03:40 [debug] 754#754: *1 accept: 127.0.0.1:49878 fd:3
2019/05/02 19:03:40 [debug] 754#754: *1 event timer add: 3: 60000:552042961
2019/05/02 19:03:40 [debug] 754#754: *1 reusable connection: 1
2019/05/02 19:03:40 [debug] 754#754: *1 epoll add event: fd:3 op:1 ev:80002001
2019/05/02 19:03:40 [debug] 754#754: timer delta: 3736
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 60000
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:3 ev:0001 d:00007F87A7DBC200
2019/05/02 19:03:40 [debug] 754#754: *1 http wait request handler
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A30890:1024
2019/05/02 19:03:40 [debug] 754#754: *1 recv: eof:0, avail:1
2019/05/02 19:03:40 [debug] 754#754: *1 recv: fd:3 86 of 1024
2019/05/02 19:03:40 [debug] 754#754: *1 reusable connection: 0
2019/05/02 19:03:40 [debug] 754#754: *1 posix_memalign: 0000000001A060F0:4096 @16
2019/05/02 19:03:40 [debug] 754#754: *1 http process request line
2019/05/02 19:03:40 [debug] 754#754: *1 http request line: "GET /test_url HTTP/1.1"
2019/05/02 19:03:40 [debug] 754#754: *1 http uri: "/test_url"
2019/05/02 19:03:40 [debug] 754#754: *1 http args: ""
2019/05/02 19:03:40 [debug] 754#754: *1 http exten: ""
2019/05/02 19:03:40 [debug] 754#754: *1 posix_memalign: 0000000001A07100:4096 @16
2019/05/02 19:03:40 [debug] 754#754: *1 http process request header line
2019/05/02 19:03:40 [debug] 754#754: *1 http header: "Host: 127.0.0.1:8090"
2019/05/02 19:03:40 [debug] 754#754: *1 http header: "User-Agent: curl/7.52.1"
2019/05/02 19:03:40 [debug] 754#754: *1 http header: "Accept: */*"
2019/05/02 19:03:40 [debug] 754#754: *1 http header done
2019/05/02 19:03:40 [debug] 754#754: *1 event timer del: 3: 552042961
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 0
2019/05/02 19:03:40 [debug] 754#754: *1 rewrite phase: 1
2019/05/02 19:03:40 [debug] 754#754: *1 test location: "/"
2019/05/02 19:03:40 [debug] 754#754: *1 test location: "subreq"
2019/05/02 19:03:40 [debug] 754#754: *1 test location: "test_url"
2019/05/02 19:03:40 [debug] 754#754: *1 using configuration "/test_url"
2019/05/02 19:03:40 [debug] 754#754: *1 http cl:-1 max:1048576
2019/05/02 19:03:40 [debug] 754#754: *1 rewrite phase: 3
2019/05/02 19:03:40 [debug] 754#754: *1 post rewrite phase: 4
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 5
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 6
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 7
2019/05/02 19:03:40 [debug] 754#754: *1 access phase: 8
2019/05/02 19:03:40 [debug] 754#754: *1 post access phase: 9
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 10
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 11
2019/05/02 19:03:40 [debug] 754#754: *1 http js content handler
2019/05/02 19:03:40 [debug] 754#754: *1 http js content event handler
2019/05/02 19:03:40 [debug] 754#754: *1 add cleanup: 0000000001A06E40
2019/05/02 19:03:40 [debug] 754#754: *1 http js content call "req_www_google"
2019/05/02 19:03:40 [debug] 754#754: *1 http subrequest "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http finalize request: -4, "/test_url?" a:1, c:3
2019/05/02 19:03:40 [debug] 754#754: *1 http request count:3 blk:0
2019/05/02 19:03:40 [debug] 754#754: *1 http posted request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 rewrite phase: 1
2019/05/02 19:03:40 [debug] 754#754: *1 test location: "/"
2019/05/02 19:03:40 [debug] 754#754: *1 test location: "subreq"
2019/05/02 19:03:40 [debug] 754#754: *1 using configuration "/subreq"
2019/05/02 19:03:40 [debug] 754#754: *1 http cl:-1 max:1048576
2019/05/02 19:03:40 [debug] 754#754: *1 rewrite phase: 3
2019/05/02 19:03:40 [debug] 754#754: *1 post rewrite phase: 4
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 5
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 6
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 7
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 10
2019/05/02 19:03:40 [debug] 754#754: *1 generic phase: 11
2019/05/02 19:03:40 [debug] 754#754: *1 posix_memalign: 0000000001A66110:4096 @16
2019/05/02 19:03:40 [debug] 754#754: *1 http init upstream, client timer: 0
2019/05/02 19:03:40 [debug] 754#754: *1 epoll add event: fd:3 op:3 ev:80002005
2019/05/02 19:03:40 [debug] 754#754: *1 http script copy: "Host"
2019/05/02 19:03:40 [debug] 754#754: *1 http script var: "www.google.com"
2019/05/02 19:03:40 [debug] 754#754: *1 http script copy: "Connection"
2019/05/02 19:03:40 [debug] 754#754: *1 http script copy: "close"
2019/05/02 19:03:40 [debug] 754#754: *1 http script copy: ""
2019/05/02 19:03:40 [debug] 754#754: *1 http script copy: ""
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "User-Agent: curl/7.52.1"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Accept: */*"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header:
"GET / HTTP/1.0^M
Host: www.google.com^M
Connection: close^M
User-Agent: curl/7.52.1^M
Accept: */*^M
^M
"
2019/05/02 19:03:40 [debug] 754#754: *1 http cleanup add: 0000000001A080E8
2019/05/02 19:03:40 [debug] 754#754: *1 get rr peer, try: 2
2019/05/02 19:03:40 [debug] 754#754: *1 get rr peer, current: 0000000001A2A3B0 -1
2019/05/02 19:03:40 [debug] 754#754: *1 stream socket 11
2019/05/02 19:03:40 [debug] 754#754: *1 epoll add connection: fd:11 ev:80002005
2019/05/02 19:03:40 [debug] 754#754: *1 connect to 172.217.26.36:443, fd:11 #2
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream connect: -2
2019/05/02 19:03:40 [debug] 754#754: *1 posix_memalign: 0000000001A31920:128 @16
2019/05/02 19:03:40 [debug] 754#754: *1 event timer add: 11: 60000:552042961
2019/05/02 19:03:40 [debug] 754#754: *1 http finalize request: -4, "/subreq?" a:0, c:3
2019/05/02 19:03:40 [debug] 754#754: *1 http request count:3 blk:0
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 60000
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:3 ev:0004 d:00007F87A7DBC200
2019/05/02 19:03:40 [debug] 754#754: *1 http run request: "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 http js content write event handler
2019/05/02 19:03:40 [debug] 754#754: *1 http output filter "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter: l:1 f:0 s:0
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: 0 "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 60000
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0004 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream send request handler
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A319B0:88
2019/05/02 19:03:40 [debug] 754#754: *1 set session: 0000000000000000
2019/05/02 19:03:40 [debug] 754#754: *1 tcp_nodelay
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_do_handshake: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: timer delta: 32
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59968
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 SSL handshake handler: 0
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_do_handshake: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL handshake handler: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_do_handshake: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: timer delta: 76
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59892
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 SSL handshake handler: 0
2019/05/02 19:03:40 [debug] 754#754: *1 save session: 0000000001A31A10
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_do_handshake: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream ssl handshake: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream send request
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream send request body
2019/05/02 19:03:40 [debug] 754#754: *1 chain writer buf fl:1 s:97
2019/05/02 19:03:40 [debug] 754#754: *1 chain writer in: 0000000001A666D0
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A7F6E0:80
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A67120:16384
2019/05/02 19:03:40 [debug] 754#754: *1 SSL buf copy: 97
2019/05/02 19:03:40 [debug] 754#754: *1 SSL to write: 97
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_write: 97
2019/05/02 19:03:40 [debug] 754#754: *1 chain writer out: 0000000000000000
2019/05/02 19:03:40 [debug] 754#754: *1 event timer del: 11: 552042961
2019/05/02 19:03:40 [debug] 754#754: *1 event timer add: 11: 60000:552043105
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process header
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A6B130:4096
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 36
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 60000
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process header
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy status 200 "200 OK"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Date: Thu, 02 May 2019 10:03:40 GMT"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Expires: -1"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Cache-Control: private, max-age=0"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Content-Type: text/html; charset=ISO-8859-1"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.""
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Server: gws"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "X-XSS-Protection: 0"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "X-Frame-Options: SAMEORIGIN"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Set-Cookie: 1P_JAR=2019-05-02-10; expires=Sat, 01-Jun-2019 10:03:40 GMT; path=/; domain=.google.com"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Set-Cookie: NID=182=p6CYK3CNMWpmquc21vlavfz8seP8m3pBghSALZgJW-IMa_kFs5AwXsI3UJ0-Na3gHvtCONSKOvZFxG1DK44rjO5zPc12KsPnFSL4iCRjfU_Ybyk6n4SpEz86jfmwnMjxNWlyim0akkPF8oQDLWnoQ2XPbr24oDISdHB2FgttuhE; expires=Fri, 01-Nov-2019 10:03:40 GMT; path=/; domain=.google.com; HttpOnly"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Alt-Svc: quic=":443"; ma=2592000; v="46,44,43,39""
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Accept-Ranges: none"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header: "Vary: Accept-Encoding"
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy header done
2019/05/02 19:03:40 [debug] 754#754: *1 http cacheable: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http proxy filter init s:200 h:0 c:0 l:-1
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe preread: 642
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 642 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 642 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043209
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 104
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59896
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 2031 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 2031 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043209
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59896
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1318
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 1318
2019/05/02 19:03:40 [debug] 754#754: *1 input buf #0
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A78830:4096
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 71
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 71
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 71 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 71 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043213
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 4
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59892
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 1460 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 1460 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043213
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59892
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1247
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 2636
2019/05/02 19:03:40 [debug] 754#754: *1 input buf #1
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A79840:4096
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 142
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 142
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 142 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 142 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043213
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59892
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:0005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1389
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: -1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 2
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 2778
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 2920 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 2920 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043217
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream dummy handler
2019/05/02 19:03:40 [debug] 754#754: timer delta: 4
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 59888
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:11 ev:2005 d:00007F87A7DBC2F8
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream request: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream process upstream
2019/05/02 19:03:40 [debug] 754#754: *1 pipe read upstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 1176
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 1176
2019/05/02 19:03:40 [debug] 754#754: *1 input buf #2
2019/05/02 19:03:40 [debug] 754#754: *1 posix_memalign: 0000000001A808D0:4096 @16
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A818E0:4096
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 213
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 623
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_read: 0
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_get_error: 5
2019/05/02 19:03:40 [debug] 754#754: *1 peer shutdown SSL cleanly
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 836
2019/05/02 19:03:40 [debug] 754#754: *1 pipe recv chain: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf in   s:1 t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe buf free s:0 t:1 f:0 0000000001A818E0, pos 0000000001A818E0, size: 836 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 pipe length: -1
2019/05/02 19:03:40 [debug] 754#754: *1 input buf #3
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream: 1
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream flush in
2019/05/02 19:03:40 [debug] 754#754: *1 http output filter "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:1 f:0 0000000001A818E0, pos 0000000001A818E0, size: 836 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter: l:0 f:0 s:12377
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: 0 "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 pipe write downstream done
2019/05/02 19:03:40 [debug] 754#754: *1 event timer: 11, old: 552043105, new: 552043217
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream exit: 0000000000000000
2019/05/02 19:03:40 [debug] 754#754: *1 finalize http upstream request: 0
2019/05/02 19:03:40 [debug] 754#754: *1 finalize http proxy request
2019/05/02 19:03:40 [debug] 754#754: *1 free rr peer 2 0
2019/05/02 19:03:40 [debug] 754#754: *1 SSL_shutdown: 1
2019/05/02 19:03:40 [debug] 754#754: *1 close http upstream connection: 11
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A67120
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A7F6E0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A319B0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A31920, unused: 0
2019/05/02 19:03:40 [debug] 754#754: *1 event timer del: 11: 552043105
2019/05/02 19:03:40 [debug] 754#754: *1 reusable connection: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http upstream temp fd: -1
2019/05/02 19:03:40 [debug] 754#754: *1 http output filter "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 write old buf t:1 f:0 0000000001A6B130, pos 0000000001A6B41B, size: 3349 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write old buf t:1 f:0 0000000001A78830, pos 0000000001A78830, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write old buf t:1 f:0 0000000001A79840, pos 0000000001A79840, size: 4096 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write old buf t:1 f:0 0000000001A818E0, pos 0000000001A818E0, size: 836 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter: l:0 f:0 s:12377
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: 0 "/subreq?"
2019/05/02 19:03:40 [debug] 754#754: *1 http finalize request: 0, "/subreq?" a:0, c:2
2019/05/02 19:03:40 [debug] 754#754: *1 js subrequest done s: 200 parent ctx: 0000000001A06DF0
2019/05/02 19:03:40 [info] 754#754: *1 js: return status 200
2019/05/02 19:03:40 [info] 754#754: *1 js: return body <!doctype html><html itemscope="" itemtype="http://schema.org/WebPage" lang="ko"><head><meta content="text/html; charset=UTF-8" http-equiv="Content-Type"><meta content="/images/branding/googleg/1x/googleg_standard_color_128dp.png" itemprop="image"><title>Google</title><script nonce="sd8euuEPaAyfjYsplUOq2w==">(function(){window.google={kEI:'fMDKXPnfIYH1wAO2x4dw',kEXPI:'0,201961,1151786,57,1958,1641,781,698,527,730,224,1575,1257,145,680,1070,584,351,554,80,32,176,50,412,2332995,329491,1294,12383,4855,32692,15247,867,12443,16241,369,3314,1263,4242,2436,266,1027,2715,462,903,575,835,284,2,579,727,2432,1361,4323,4968,773,2255,2816,1923,1151,2,4560,3601,669,1050,1808,1397,81,7,492,619,29,1395,978,4612,2157,1162,1288,2,4007,796,101,1119,38,920,746,8,119,1217,1211,153,346,1,1264,1581,1155,49,3012,2,631,732,1830,2,4,2,670,44,3745,757,156,124,2608,632,1139,1089,655,21,318,234,1331,416,142,1247,777,1,3,366,1016,302,606,97,756,98,392,29,400,376,2,614,1107,10,169,7,284,843,235,78,365,367,453,171,564,167,154,82,601,25,10,573,396,692,837,76,132,394,372,9,26,176,37,92,199,1165,87,66,475,154,145,324,31,34,128,513,18,262,16,89,2,172,104,23,161,67,63,32,173,154,276,211,487,428,100,84,143,278,19,33,70,15,10,112,507,340,88,76,914,62,1127,2,7,7,188,317,221,28,393,11,4,29,304,12,500,42,410,834,139,1053,10,48,594,44,491,5938898,1873,1047,5997516,40,2799864,4,1572,549,333,444,1,2,80,1,900,578,14,304,1,8,1,2,2132,1,1,1,1,1,414,1,748,141,59,726,3,7,563,1,1735,1,111,6,4,59,2,2,11,43,1,13,16',authuser:0,kscs:'c9c918f0_fMDKXPnfIYH1wAO2x4dw',kGL:'KR'};google.sn='webhp';google.kHL='ko';})();(function(){google.lc=[];google.li=0;google.getEI=function(a){for(var b;a&&(!a.getAttribute||!(b=a.getAttribute("eid")));)a=a.parentNode;return b||google.kEI};google.getLEI=function(a){for(var b=null;a&&(!a.getAttribute||!(b=a.getAttribute("leid")));)a=a.parentNode;return b};google.https=function(){return"https:"==window.location.protocol};google.ml=function(){return null};google.time=function(){return(
2019/05/02 19:03:40 [debug] 754#754: *1 HTTP/1.1 200 OK^M
Server: nginx/1.16.0^M
Date: Thu, 02 May 2019 10:03:40 GMT^M
Content-Type: application/octet-stream^M
Content-Length: 4^M
Connection: keep-alive^M

2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:1 f:0 0000000001A80C00, pos 0000000001A80C00, size: 161 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter: l:0 f:0 s:161
2019/05/02 19:03:40 [debug] 754#754: *1 http output filter "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 write old buf t:1 f:0 0000000001A80C00, pos 0000000001A80C00, size: 161 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 write new buf t:0 f:0 0000000000000000, pos 0000000001A64530, size: 4 file: 0, size: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter: l:1 f:0 s:165
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter limit 0
2019/05/02 19:03:40 [debug] 754#754: *1 writev: 165 of 165
2019/05/02 19:03:40 [debug] 754#754: *1 http write filter 0000000000000000
2019/05/02 19:03:40 [debug] 754#754: *1 http copy filter: 0 "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 http request count:2 blk:0
2019/05/02 19:03:40 [debug] 754#754: *1 http posted request: "/test_url?"
2019/05/02 19:03:40 [debug] 754#754: *1 http js content write event handler
2019/05/02 19:03:40 [debug] 754#754: *1 http js content rc: 0
2019/05/02 19:03:40 [debug] 754#754: *1 http finalize request: 0, "/test_url?" a:1, c:1
2019/05/02 19:03:40 [debug] 754#754: *1 set http keepalive handler
2019/05/02 19:03:40 [debug] 754#754: *1 http close request
2019/05/02 19:03:40 [debug] 754#754: *1 http log handler
2019/05/02 19:03:40 [debug] 754#754: *1 run cleanup: 0000000001A06E40
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A818E0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A79840
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A78830
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A6B130
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A060F0, unused: 0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A07100, unused: 0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A66110, unused: 8
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A808D0, unused: 2920
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A30890
2019/05/02 19:03:40 [debug] 754#754: *1 hc free: 0000000000000000
2019/05/02 19:03:40 [debug] 754#754: *1 hc busy: 0000000000000000 0
2019/05/02 19:03:40 [debug] 754#754: *1 tcp_nodelay
2019/05/02 19:03:40 [debug] 754#754: *1 reusable connection: 1
2019/05/02 19:03:40 [debug] 754#754: *1 event timer add: 3: 65000:552048217
2019/05/02 19:03:40 [debug] 754#754: timer delta: 0
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: 65000
2019/05/02 19:03:40 [debug] 754#754: epoll: fd:3 ev:2005 d:00007F87A7DBC200
2019/05/02 19:03:40 [debug] 754#754: *1 http keepalive handler
2019/05/02 19:03:40 [debug] 754#754: *1 malloc: 0000000001A30890:1024
2019/05/02 19:03:40 [debug] 754#754: *1 recv: eof:1, avail:1
2019/05/02 19:03:40 [debug] 754#754: *1 recv: fd:3 0 of 1024
2019/05/02 19:03:40 [info] 754#754: *1 client 127.0.0.1 closed keepalive connection
2019/05/02 19:03:40 [debug] 754#754: *1 close http connection: 3
2019/05/02 19:03:40 [debug] 754#754: *1 event timer del: 3: 552048217
2019/05/02 19:03:40 [debug] 754#754: *1 reusable connection: 0
2019/05/02 19:03:40 [debug] 754#754: *1 free: 0000000001A30890
2019/05/02 19:03:40 [debug] 754#754: *1 free: 00000000019FF420, unused: 136
2019/05/02 19:03:40 [debug] 754#754: timer delta: 4
2019/05/02 19:03:40 [debug] 754#754: worker cycle
2019/05/02 19:03:40 [debug] 754#754: epoll timer: -1

Why do I set postpone_directive?
- I figure out that ngx_http_output_filter(...) calls ngx_http_write_filter(ngx_http_request_t *r, ngx_chain_t *in) later, and ngx_http_write_filter has a specific condition to return NGX_OK without returning data from subrequest. Unfortunately, I feel that approaching of setting the directive is not a solution.

    /*
     * avoid the output if there are no last buf, no flush point,
     * there are the incoming bufs and the size of all bufs
     * is smaller than "postpone_output" directive
     */

    if (!last && !flush && in && size < (off_t) clcf->postpone_output) {
        return NGX_OK;
    }

from njs.

xeioex commented on August 20, 2024

@initproc

Thanks you for the detailed report. I am on vacation now, will look into the problem next week.

from njs.

initproc commented on August 20, 2024

@xeioex

Ok. I see. Thank you for letting me know how it's going on.

from njs.

xeioex commented on August 20, 2024

@initproc @janglapuk

The issue is here:

postpone filter is necessary for njs subrequest functionality,
By disabling SSI filter (using --without-http_ssi_module) postpone filter is also disabled.

As a workaround you have to enable one of the following filters: SSI, slice (--with-http_slice_module), addition (--with-http_addition_module).

The correct solution should be done in nginx source code: here.

from njs.

initproc commented on August 20, 2024

@xeioex

I will share the following to clarify this issue.
I've tried the workaround you gave me, but the problem still seems to exist.
I removed an '--with-http_ssi_module' option and added two modules you suggested.

./nginx -V
nginx version: nginx/1.16.0
built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11) 
built with OpenSSL 1.0.2r  26 Feb 2019
TLS SNI support enabled
configure arguments: --prefix=/home/initproc/apps/nginx-1.16.0 --error-log-path=/dev/stderr --http-client-body-temp-path=/tmp/client_body_temp --without-http_fastcgi_module --without-http_uwsgi_module --without-http_scgi_module --without-http_userid_module --without-http_auth_basic_module --with-http_ssl_module --with-http_v2_module --with-http_realip_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_stub_status_module --with-stream --with-stream_ssl_module --with-stream_realip_module --with-pcre=/home/initproc/srcs/pcre-8.39 --with-pcre-opt=-DSUPPORT_UTF --with-openssl=/home/initproc/srcs/openssl-1.0.2r --with-threads --with-debug --with-file-aio --with-http_realip_module --add-module=/home/initproc/srcs/njs/nginx --with-http_slice_module --with-http_addition_module

!curl
curl http://127.0.0.1:8090/test_url
curl: (52) Empty reply from server


cat ../conf/nginx.conf
worker_processes  1;

error_log  logs/error.log debug;

events {
    worker_connections  1024;
}


http {
    include       mime.types;
    default_type  application/octet-stream;

    js_include test.js;

    sendfile        on;

    keepalive_timeout  65;

    gzip  on;

    server {
        listen       8090;
        server_name  localhost;
    
        location / {
            root   html;
            index  index.html index.htm;
        }

        location /subreq {
            #postpone_output 1024000;
            proxy_pass https://www.google.com/;
        }

        location /test_url {
            js_content req_www_google;
        }

        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   html;
        }
    }
}

cat ../conf/test.js


function req_www_google(r) {
    r.subrequest("/subreq", 
        function(res) {
            r.log("return status " + res.status);
            r.log("return body " + res.responseBody);

            r.return(200, "Finally");
        });
}

error log

cat ../logs/error.log 
2019/05/07 10:22:36 [debug] 20144#20144: bind() 0.0.0.0:8090 #6 
2019/05/07 10:22:36 [notice] 20144#20144: using the "epoll" event method
2019/05/07 10:22:36 [debug] 20144#20144: counter: 00007F2E859F6080, 1
2019/05/07 10:22:36 [notice] 20144#20144: nginx/1.16.0
2019/05/07 10:22:36 [notice] 20144#20144: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.11) 
2019/05/07 10:22:36 [notice] 20144#20144: OS: Linux 4.4.0-146-generic
2019/05/07 10:22:36 [notice] 20144#20144: getrlimit(RLIMIT_NOFILE): 1024:1048576
2019/05/07 10:22:36 [debug] 20145#20145: write: 7, 00007FFF0DB24090, 6, 0
2019/05/07 10:22:36 [debug] 20145#20145: setproctitle: "nginx: master process ./nginx"
2019/05/07 10:22:36 [notice] 20145#20145: start worker processes
2019/05/07 10:22:36 [debug] 20145#20145: channel 3:7
2019/05/07 10:22:36 [notice] 20145#20145: start worker process 20146
2019/05/07 10:22:36 [debug] 20145#20145: sigsuspend
2019/05/07 10:22:36 [debug] 20146#20146: add cleanup: 000000000174D4C8
2019/05/07 10:22:36 [debug] 20146#20146: malloc: 000000000174A0D0:8
2019/05/07 10:22:36 [debug] 20146#20146: notify eventfd: 9
2019/05/07 10:22:36 [debug] 20146#20146: eventfd: 10
2019/05/07 10:22:36 [debug] 20146#20146: testing the EPOLLRDHUP flag: success
2019/05/07 10:22:36 [debug] 20146#20146: malloc: 000000000171F880:6144
2019/05/07 10:22:36 [debug] 20146#20146: malloc: 00007F2E8598B010:253952
2019/05/07 10:22:36 [debug] 20146#20146: malloc: 0000000001751300:98304
2019/05/07 10:22:36 [debug] 20146#20146: malloc: 0000000001769310:98304
2019/05/07 10:22:36 [debug] 20146#20146: epoll add event: fd:6 op:1 ev:00002001
2019/05/07 10:22:36 [debug] 20146#20146: epoll add event: fd:7 op:1 ev:00002001
2019/05/07 10:22:36 [debug] 20146#20146: setproctitle: "nginx: worker process"
2019/05/07 10:22:36 [debug] 20146#20146: worker cycle
2019/05/07 10:22:36 [debug] 20146#20146: epoll timer: -1
2019/05/07 10:22:38 [debug] 20146#20146: epoll: fd:6 ev:0001 d:00007F2E8598B010
2019/05/07 10:22:38 [debug] 20146#20146: accept on 0.0.0.0:8090, ready: 0
2019/05/07 10:22:38 [debug] 20146#20146: posix_memalign: 0000000001711420:512 @16
2019/05/07 10:22:38 [debug] 20146#20146: *1 accept: 127.0.0.1:52892 fd:3
2019/05/07 10:22:38 [debug] 20146#20146: *1 event timer add: 3: 60000:952781449
2019/05/07 10:22:38 [debug] 20146#20146: *1 reusable connection: 1
2019/05/07 10:22:38 [debug] 20146#20146: *1 epoll add event: fd:3 op:1 ev:80002001
2019/05/07 10:22:38 [debug] 20146#20146: timer delta: 1880
2019/05/07 10:22:38 [debug] 20146#20146: worker cycle
2019/05/07 10:22:38 [debug] 20146#20146: epoll timer: 60000
2019/05/07 10:22:38 [debug] 20146#20146: epoll: fd:3 ev:0001 d:00007F2E8598B200
2019/05/07 10:22:38 [debug] 20146#20146: *1 http wait request handler
2019/05/07 10:22:38 [debug] 20146#20146: *1 malloc: 0000000001749A50:1024
2019/05/07 10:22:38 [debug] 20146#20146: *1 recv: eof:0, avail:1
2019/05/07 10:22:38 [debug] 20146#20146: *1 recv: fd:3 86 of 1024
2019/05/07 10:22:38 [debug] 20146#20146: *1 reusable connection: 0
2019/05/07 10:22:38 [debug] 20146#20146: *1 posix_memalign: 0000000001721090:4096 @16
2019/05/07 10:22:38 [debug] 20146#20146: *1 http process request line
2019/05/07 10:22:38 [debug] 20146#20146: *1 http request line: "GET /test_url HTTP/1.1"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http uri: "/test_url"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http args: ""
2019/05/07 10:22:38 [debug] 20146#20146: *1 http exten: ""
2019/05/07 10:22:38 [debug] 20146#20146: *1 posix_memalign: 0000000001716850:4096 @16
2019/05/07 10:22:38 [debug] 20146#20146: *1 http process request header line
2019/05/07 10:22:38 [debug] 20146#20146: *1 http header: "Host: 127.0.0.1:8090"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http header: "User-Agent: curl/7.52.1"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http header: "Accept: */*"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http header done
2019/05/07 10:22:38 [debug] 20146#20146: *1 event timer del: 3: 952781449
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 0
2019/05/07 10:22:38 [debug] 20146#20146: *1 rewrite phase: 1
2019/05/07 10:22:38 [debug] 20146#20146: *1 test location: "/"
2019/05/07 10:22:38 [debug] 20146#20146: *1 test location: "subreq"
2019/05/07 10:22:38 [debug] 20146#20146: *1 test location: "test_url"
2019/05/07 10:22:38 [debug] 20146#20146: *1 using configuration "/test_url"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http cl:-1 max:1048576
2019/05/07 10:22:38 [debug] 20146#20146: *1 rewrite phase: 3
2019/05/07 10:22:38 [debug] 20146#20146: *1 post rewrite phase: 4
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 5
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 6
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 7
2019/05/07 10:22:38 [debug] 20146#20146: *1 access phase: 8
2019/05/07 10:22:38 [debug] 20146#20146: *1 access phase: 9
2019/05/07 10:22:38 [debug] 20146#20146: *1 post access phase: 10
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 11
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 12
2019/05/07 10:22:38 [debug] 20146#20146: *1 http js content handler
2019/05/07 10:22:38 [debug] 20146#20146: *1 http js content event handler
2019/05/07 10:22:38 [debug] 20146#20146: *1 add cleanup: 0000000001721E20
2019/05/07 10:22:38 [debug] 20146#20146: *1 http js content call "req_www_google"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http subrequest "/subreq?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http finalize request: -4, "/test_url?" a:1, c:3
2019/05/07 10:22:38 [debug] 20146#20146: *1 http request count:3 blk:0
2019/05/07 10:22:38 [debug] 20146#20146: *1 http posted request: "/subreq?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 rewrite phase: 1
2019/05/07 10:22:38 [debug] 20146#20146: *1 test location: "/"
2019/05/07 10:22:38 [debug] 20146#20146: *1 test location: "subreq"
2019/05/07 10:22:38 [debug] 20146#20146: *1 using configuration "/subreq"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http cl:-1 max:1048576
2019/05/07 10:22:38 [debug] 20146#20146: *1 rewrite phase: 3
2019/05/07 10:22:38 [debug] 20146#20146: *1 post rewrite phase: 4
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 5
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 6
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 7
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 11
2019/05/07 10:22:38 [debug] 20146#20146: *1 generic phase: 12
2019/05/07 10:22:38 [debug] 20146#20146: *1 posix_memalign: 000000000171A490:4096 @16
2019/05/07 10:22:38 [debug] 20146#20146: *1 http init upstream, client timer: 0
2019/05/07 10:22:38 [debug] 20146#20146: *1 epoll add event: fd:3 op:3 ev:80002005
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script copy: "Host"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script var: "www.google.com"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script copy: "Connection"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script copy: "close"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script copy: ""
2019/05/07 10:22:38 [debug] 20146#20146: *1 http script copy: ""
2019/05/07 10:22:38 [debug] 20146#20146: *1 http proxy header: "User-Agent: curl/7.52.1"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http proxy header: "Accept: */*"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http proxy header:
"GET / HTTP/1.0
Host: www.google.com
Connection: close
User-Agent: curl/7.52.1
Accept: */*

"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http cleanup add: 00000000017177D8
2019/05/07 10:22:38 [debug] 20146#20146: *1 get rr peer, try: 2
2019/05/07 10:22:38 [debug] 20146#20146: *1 get rr peer, current: 0000000001745110 -1
2019/05/07 10:22:38 [debug] 20146#20146: *1 stream socket 11
2019/05/07 10:22:38 [debug] 20146#20146: *1 epoll add connection: fd:11 ev:80002005
2019/05/07 10:22:38 [debug] 20146#20146: *1 connect to 172.217.25.68:443, fd:11 #2
2019/05/07 10:22:38 [debug] 20146#20146: *1 http upstream connect: -2
2019/05/07 10:22:38 [debug] 20146#20146: *1 posix_memalign: 000000000174AAE0:128 @16
2019/05/07 10:22:38 [debug] 20146#20146: *1 event timer add: 11: 60000:952781449
2019/05/07 10:22:38 [debug] 20146#20146: *1 http finalize request: -4, "/subreq?" a:0, c:3
2019/05/07 10:22:38 [debug] 20146#20146: *1 http request count:3 blk:0
2019/05/07 10:22:38 [debug] 20146#20146: timer delta: 0
2019/05/07 10:22:38 [debug] 20146#20146: worker cycle
2019/05/07 10:22:38 [debug] 20146#20146: epoll timer: 60000
2019/05/07 10:22:38 [debug] 20146#20146: epoll: fd:3 ev:0004 d:00007F2E8598B200
2019/05/07 10:22:38 [debug] 20146#20146: *1 http run request: "/test_url?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http js content write event handler
2019/05/07 10:22:38 [debug] 20146#20146: *1 http output filter "/test_url?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http copy filter: "/test_url?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http postpone filter "/test_url?" 00007FFF0DB23DD0
2019/05/07 10:22:38 [debug] 20146#20146: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2019/05/07 10:22:38 [debug] 20146#20146: *1 http write filter: l:1 f:0 s:0
2019/05/07 10:22:38 [debug] 20146#20146: *1 http copy filter: 0 "/test_url?"
2019/05/07 10:22:38 [debug] 20146#20146: timer delta: 0
2019/05/07 10:22:38 [debug] 20146#20146: worker cycle
2019/05/07 10:22:38 [debug] 20146#20146: epoll timer: 60000
2019/05/07 10:22:38 [debug] 20146#20146: epoll: fd:11 ev:0004 d:00007F2E8598B2F8
2019/05/07 10:22:38 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:38 [debug] 20146#20146: *1 http upstream send request handler
2019/05/07 10:22:38 [debug] 20146#20146: *1 malloc: 000000000174AB70:88
2019/05/07 10:22:38 [debug] 20146#20146: *1 set session: 0000000000000000
2019/05/07 10:22:38 [debug] 20146#20146: *1 tcp_nodelay
2019/05/07 10:22:38 [debug] 20146#20146: *1 SSL_do_handshake: -1
2019/05/07 10:22:38 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:38 [debug] 20146#20146: timer delta: 100
2019/05/07 10:22:38 [debug] 20146#20146: worker cycle
2019/05/07 10:22:38 [debug] 20146#20146: epoll timer: 59900
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL handshake handler: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_do_handshake: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL handshake handler: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_do_handshake: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 128
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59772
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL handshake handler: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 save session: 000000000174AC70
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_do_handshake: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream ssl handshake: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream send request
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream send request body
2019/05/07 10:22:39 [debug] 20146#20146: *1 chain writer buf fl:1 s:97
2019/05/07 10:22:39 [debug] 20146#20146: *1 chain writer in: 0000000001717818
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 0000000001799740:80
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 0000000001781320:16384
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL buf copy: 97
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL to write: 97
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_write: 97
2019/05/07 10:22:39 [debug] 20146#20146: *1 chain writer out: 0000000000000000
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer del: 11: 952781449
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer add: 11: 60000:952781769
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process header
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 0000000001785330:4096
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 92
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 60000
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process header
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1318
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy status 200 "200 OK"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Date: Tue, 07 May 2019 01:22:39 GMT"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Expires: -1"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Cache-Control: private, max-age=0"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Content-Type: text/html; charset=ISO-8859-1"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.""
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Server: gws"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "X-XSS-Protection: 0"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "X-Frame-Options: SAMEORIGIN"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Set-Cookie: 1P_JAR=2019-05-07-01; expires=Thu, 06-Jun-2019 01:22:39 GMT; path=/; domain=.google.com"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Set-Cookie: NID=182=YvPvhv06RuUHSnzTpZjK_grQlDg2RHVCnlF_0DYr23A1Pzis8IcUICL2eXlcYmYUtkc_jz_3Vig4ppeQ1rJIDdyEEJ11B0WxZojj8og6iV4NYuhCNlib6vXoVCugRr6nQIPf2s0txYFLlnIdU8AfWlFaj1GzhB9SeTA-ivqxnuk; expires=Wed, 06-Nov-2019 01:22:39 GMT; path=/; domain=.google.com; HttpOnly"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Alt-Svc: quic=":443"; ma=2592000; v="46,44,43,39""
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Accept-Ranges: none"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header: "Vary: Accept-Encoding"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy header done
2019/05/07 10:22:39 [debug] 20146#20146: *1 http cacheable: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 http proxy filter init s:200 h:0 c:0 l:-1
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe preread: 3349
2019/05/07 10:22:39 [debug] 20146#20146: *1 input buf #0
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 0000000001792A30:4096
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 71
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 71
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 71 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 71 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781929
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 160
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59840
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 1460 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 1460 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781933
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 4
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59836
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1247
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 2636
2019/05/07 10:22:39 [debug] 20146#20146: *1 input buf #1
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 0000000001793A40:4096
2019/05/07 10:22:39 [debug] 20146#20146: *1 posix_memalign: 000000000179A930:4096 @16
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 142
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 142
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 142 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 142 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781945
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 12
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59824
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 1531 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 1531 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781945
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 0
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59824
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:0005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1389
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 1176
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 2565
2019/05/07 10:22:39 [debug] 20146#20146: *1 input buf #2
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 000000000179B940:4096
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 213
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 213
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 000000000179B940, pos 000000000179B940, size: 213 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 000000000179B940, pos 000000000179B940, size: 213 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781953
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream dummy handler
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 8
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: 59816
2019/05/07 10:22:39 [debug] 20146#20146: epoll: fd:11 ev:2005 d:00007F2E8598B2F8
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream request: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream process upstream
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe read upstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 646
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_read: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_get_error: 5
2019/05/07 10:22:39 [debug] 20146#20146: *1 peer shutdown SSL cleanly
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 646
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe recv chain: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001785330, pos 000000000178561B, size: 3349 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001792A30, pos 0000000001792A30, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf in   s:1 t:1 f:0 0000000001793A40, pos 0000000001793A40, size: 4096 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe buf free s:0 t:1 f:0 000000000179B940, pos 000000000179B940, size: 859 file: 0, size: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe length: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 input buf #3
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 pipe write downstream flush in
2019/05/07 10:22:39 [debug] 20146#20146: *1 http output filter "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http copy filter: "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http postpone filter "/subreq?" 000000000179AB00
2019/05/07 10:22:39 [debug] 20146#20146: *1 http postpone filter in memory
2019/05/07 10:22:39 [debug] 20146#20146: *1 malloc: 000000000179C950:4096
2019/05/07 10:22:39 [debug] 20146#20146: *1 http postpone filter in memory 3349 bytes
2019/05/07 10:22:39 [error] 20146#20146: *1 too big subrequest response while sending to client, client: 127.0.0.1, server: localhost, request: "GET /test_url HTTP/1.1", subrequest: "/subreq", upstream: "https://172.217.25.68:443/", host: "127.0.0.1:8090"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http copy filter: -1 "/subreq?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer: 11, old: 952781769, new: 952781957
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream exit: 0000000000000000
2019/05/07 10:22:39 [debug] 20146#20146: *1 finalize http upstream request: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 finalize http proxy request
2019/05/07 10:22:39 [debug] 20146#20146: *1 free rr peer 2 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 SSL_shutdown: 1
2019/05/07 10:22:39 [debug] 20146#20146: *1 close http upstream connection: 11
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001781320
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001799740
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000174AB70
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000174AAE0, unused: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 event timer del: 11: 952781769
2019/05/07 10:22:39 [debug] 20146#20146: *1 reusable connection: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 http upstream temp fd: -1
2019/05/07 10:22:39 [debug] 20146#20146: *1 http finalize request: 0, "/subreq?" a:0, c:2
2019/05/07 10:22:39 [debug] 20146#20146: *1 http terminate request count:2
2019/05/07 10:22:39 [debug] 20146#20146: *1 http terminate cleanup count:2 blk:0
2019/05/07 10:22:39 [debug] 20146#20146: *1 http posted request: "/test_url?"
2019/05/07 10:22:39 [debug] 20146#20146: *1 http terminate handler count:2
2019/05/07 10:22:39 [debug] 20146#20146: *1 http request count:1 blk:0
2019/05/07 10:22:39 [debug] 20146#20146: *1 http close request
2019/05/07 10:22:39 [debug] 20146#20146: *1 http log handler
2019/05/07 10:22:39 [debug] 20146#20146: *1 run cleanup: 0000000001721E20
2019/05/07 10:22:39 [error] 20146#20146: *1 pending events while closing request, client: 127.0.0.1, server: 0.0.0.0:8090
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000179C950
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000179B940
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001793A40
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001792A30
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001785330
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001721090, unused: 2
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001716850, unused: 6
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000171A490, unused: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 000000000179A930, unused: 3264
2019/05/07 10:22:39 [debug] 20146#20146: *1 close http connection: 3
2019/05/07 10:22:39 [debug] 20146#20146: *1 reusable connection: 0
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001749A50
2019/05/07 10:22:39 [debug] 20146#20146: *1 free: 0000000001711420, unused: 136
2019/05/07 10:22:39 [debug] 20146#20146: timer delta: 4
2019/05/07 10:22:39 [debug] 20146#20146: worker cycle
2019/05/07 10:22:39 [debug] 20146#20146: epoll timer: -1

from njs.

initproc commented on August 20, 2024

@xeioex
I found that your suggest is working and the test above is another problem.
If a response of the subrequest is too big, then nginx emits error.
I checked that it's working, when I change the url from www.google.com to a simple web page.
Thank you for suggesting the workaround.

2019/05/07 10:22:39 [error] 20146#20146: *1 too big subrequest response while sending to client, client: 127.0.0.1, server: localhost, request: "GET /test_url HTTP/1.1", subrequest: "/subreq", upstream: "https://172.217.25.68:443/", host: "127.0.0.1:8090"

from njs.

xeioex commented on August 20, 2024

@initproc

See this:

r.responseBody
holds the subrequest response body, read-only. The size of r.responseBody is limited by the subrequest_output_buffer_size directive.

from njs.

initproc commented on August 20, 2024

@xeioex
Thank you.

from njs.

"the http output chain is empty while connecting to upstream" from subrequest about njs HOT 14 CLOSED

Comments (14)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent