Comments (14)
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.
Fixed in nginx here.
Fixed since nginx-1.17.0.
from njs.
@janglapuk
I get same problem. Did you solve this or have any progress?
from njs.
@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.
@janglapuk
Thank you for your reply.
from njs.
Can please you share your debug.log?
from njs.
-
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:굴림,돋움,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>검색</b> <a class=gb1 href="https://www.google.co.kr/imghp?hl=ko&tab=wi">이미지</a> <a class=gb1 href="https://maps.google.co.kr/maps?hl=ko&tab=wl">지도</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">뉴스</a> <a class=gb1 href="https://mail.google.com/mail/?tab=wm">Gmail</a> <a class=gb1 href="https://drive.google.com/?tab=wo">드라이브</a> <a class=gb1 style="text-decoration:none" href="https://www.google.co.kr/intl/ko/about/products?tab=wh"><u>더보기</u> »</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>웹 기록</a> | <a href="/preferences?hl=ko" class=gb4>설정</a> | <a target=_top id=gb_70 href="https://accounts.google.com/ServiceLogin?hl=ko&passive=true&continue=https://www.google.com/" class=gb4>로그인</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%"> </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 검색" 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 검색" name="btnG" type="submit"></span></span><span class="ds"><span class="lsbb"><input class="lsb" value="I’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&authuser=0">고급검색</a><a href="/language_tools?hl=ko&authuser=0">언어도구</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/">광고 프로그램</a><a href="http://www.google.co.kr/intl/ko/services/">비즈니스 솔루션</a><a href="/intl/ko/about.html">Google 정보</a><a href="https://www.google.com/setprefdomain?prefdom=KR&prev=https://www.google.co.kr/&sig=K_bMHi1zNHtKv_X7UFl2T_pVSvJXQ%3D">Google.co.kr</a></div></div><p style="color:#767676;font-size:8pt">© 2019 - <a href="/intl/ko/policies/privacy/">개인정보처리방침</a> - <a href="/intl/ko/policies/terms/">약관</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검색어 지우기\x22,\x22dym\x22:\x22이것을 찾으셨나요?\x22,\x22lcky\x22:\x22I’m Feeling Lucky\x22,\x22lml\x22:\x22자세히 알아보기\x22,\x22oskt\x22:\x22입력 도구\x22,\x22psrc\x22:\x22검색어가 \\u003Ca href\x3d\\\x22/history\\\x22\\u003E웹 기록\\u003C/a\\u003E에서 삭제되었습니다.\x22,\x22psrl\x22:\x22삭제\x22,\x22sbit\x22:\x22이미지로 검색\x22,\x22srch\x22:\x22Google 검색\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.
Thanks you for the detailed report. I am on vacation now, will look into the problem next week.
from njs.
Ok. I see. Thank you for letting me know how it's going on.
from njs.
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.
- 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.
@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.
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.
@xeioex
Thank you.
from njs.
Related Issues (20)
- context for js_var variables HOT 2
- First chunk detection in js_body_filter HOT 1
- how to hide response header : server HOT 3
- How to log to a separate log file instead of error log file? HOT 2
- Detached r.subrequest not running HOT 4
- ngx.shared.SharedDict.clear() fails! HOT 2
- Shared library and installation
- js_periodic / Reading status connections growing HOT 3
- ngx.fetch Content-Length header is not sent HOT 8
- How to implement an external rate limitter? HOT 2
- njs_string_atob cannot handle cypertext unless the padding is intact HOT 1
- Add Support for js_balancer like balancer_by_lua_block HOT 2
- How to remove or override value of 'Server' header for all locations. HOT 10
- Introducing QuickJS engine as alternative JS engine. HOT 7
- ngx.shared.SharedDict.clear() hangs when called on an empty dict HOT 1
- NJS call wrong function. HOT 7
- Sending a Buffer with r.send() does not work HOT 1
- Repo looks empty
- Test failure with zlib-ng HOT 6
- False Positive Duplicate Checker Warning HOT 3
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from njs.