search

alibaba / tengine

A distribution of Nginx with some advanced features
https://tengine.taobao.org
BSD 2-Clause "Simplified" License
12.75k stars 2.52k forks source link

http_upstream_dynamic module hangs some reused connections #986

Open alejandropal opened 6 years ago

alejandropal commented 6 years ago

Hello!

We are having an issue when using the http_upstream_dynamic module. We are transparent proxying the outgoing requests from an app with a 150 ms http client.

App's http client (timeout=150ms)---> tengine --> AWS ELB --> another server

If we use this upstream, everything works fine:

upstream static-testing.com {
    server internal-question-read-mw-kvs-xxxx-xxxxxxxxxxx.us-east-1.elb.amazonaws.com;
    keepalive 200;
}

If we don’t use use any upstream, it works fine too.

But, if we use this upstream with the dynamic_upstream module, it hangs some reused connections, and we get 499 status by timeout and finally, the connection to ELB is closed:

upstream dynamic-testing.com {
        dynamic_resolve fallback=stale fail_timeout=5s;
    server internal-question-read-mw-kvs-xx-xxxxx.us-east-1.elb.amazonaws.com max_fails=0;
    keepalive 200;
}

We have taken several samples of the entire flow. In the hanging requests, the other server and the ELB logs http status 200 and 3-5 ms response time, whereas that in tengine’s host, we can see in a tcp dump problems like this:

tcp dump tengine dynamic-upstream

This is an example configuration we are using:

daemon off;

worker_processes auto;
worker_priority 0;

worker_rlimit_nofile 8192;
pid /tmp/nginx.pid;

events {
  worker_connections 8000;
  use epoll;
}

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

  upstream dynamic-testing.com {
    dynamic_resolve fallback=stale fail_timeout=5s;
    server internal-question-read-mw-kvs-xx-xxxxx.us-east-1.elb.amazonaws.com max_fails=0;
    keepalive 200;
  }

  upstream static-testing.com {
    server internal-question-read-mw-kvs-xxxx-xxxxxxxxxxx.us-east-1.elb.amazonaws.com;
    keepalive 200;
  }

  server {
    listen       80;   

    keepalive_requests 100000;
    underscores_in_headers off;
    proxy_buffering off;

    proxy_connect_timeout 5000ms;
    proxy_send_timeout 6;
    lingering_timeout 3s;

    server_tokens off;
    keepalive_timeout 320s;

    sendfile        on;
    tcp_nopush      on;
    tcp_nodelay on;

    location / {
      proxy_pass http://$http_host$request_uri;
      proxy_http_version  1.1;
      proxy_set_header    Connection  "";
    }
  }

}

Thanks in advance!

chobits commented 6 years ago

hi @alejandropal ,thanks for reporting. Could you added a debug log, you can enable debug log from doc: http://nginx.org/en/docs/debugging_log.html.

alejandropal commented 6 years ago

This request (identified by a request-id header ) reproduce this issue.

I hope it'll be usefull:

018/01/05 20:41:50 [debug] 675#0: 1668 post event 00007F72F58B9C80 2018/01/05 20:41:50 [debug] 675#0: 1668 post event 00007F72EF19EC80 2018/01/05 20:41:50 [debug] 675#0: 1668 delete posted event 00007F72F58B9C80 2018/01/05 20:41:50 [debug] 675#0: 1668 http keepalive handler 2018/01/05 20:41:50 [debug] 675#0: 1668 malloc: 00000000018EDFB0:1024 2018/01/05 20:41:50 [debug] 675#0: 1668 recv: fd:88 255 of 1024 2018/01/05 20:41:50 [debug] 675#0: 1668 reusable connection: 0 2018/01/05 20:41:50 [debug] 675#0: 1668 posix_memalign: 00000000018E8380:4096 @16 2018/01/05 20:41:50 [debug] 675#0: 1668 event timer del: 88: 1515185230249 2018/01/05 20:41:50 [debug] 675#0: 1668 http process request line 2018/01/05 20:41:50 [debug] 675#0: 1668 http request line: "GET /sample_service/test/5237122975 HTTP/1.1" 2018/01/05 20:41:50 [debug] 675#0: 1668 http uri: "/sample_service/test/5237122975" 2018/01/05 20:41:50 [debug] 675#0: 1668 http args: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http exten: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 posix_memalign: 000000000184E880:4096 @16 2018/01/05 20:41:50 [debug] 675#0: 1668 http process request header line 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "Host: read.api.sampleservice.com" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "User-Agent: github.com/go-loco/restful" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "Accept: application/json" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "Cache-Control: no-cache" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "Connection: keep-alive" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header: "Accept-Encoding: gzip" 2018/01/05 20:41:50 [debug] 675#0: 1668 http header done 2018/01/05 20:41:50 [debug] 675#0: 1668 rewrite phase: 0 2018/01/05 20:41:50 [debug] 675#0: 1668 test location: "/" 2018/01/05 20:41:50 [debug] 675#0: 1668 using configuration "/" 2018/01/05 20:41:50 [debug] 675#0: 1668 http cl:-1 max:0 2018/01/05 20:41:50 [debug] 675#0: 1668 rewrite phase: 2 2018/01/05 20:41:50 [debug] 675#0: 1668 rewrite phase: 3 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $logs_enabled 2018/01/05 20:41:50 [debug] 675#0: 1668 http script complex value 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "6f823a5c-c5b1-49e5-89d3-9f38fc9586ff" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $fwd_request_id 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $check_time_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $load_so_time_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $call_so_time_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $request_time_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $upstream_response_time_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script value: "0" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $read_config_ms 2018/01/05 20:41:50 [debug] 675#0: 1668 http script complex value 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "/sample_service/test/5237122975" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script set $rew_uri 2018/01/05 20:41:50 [debug] 675#0: 1668 post rewrite phase: 4 2018/01/05 20:41:50 [debug] 675#0: 1668 generic phase: 5 2018/01/05 20:41:50 [debug] 675#0: 1668 generic phase: 6 2018/01/05 20:41:50 [debug] 675#0: 1668 generic phase: 7 2018/01/05 20:41:50 [debug] 675#0: 1668 access phase: 8 2018/01/05 20:41:50 [debug] 675#0: 1668 access phase: 9 2018/01/05 20:41:50 [debug] 675#0: 1668 access phase: 10 2018/01/05 20:41:50 [debug] 675#0: 1668 access phase: 11 2018/01/05 20:41:50 [debug] 675#0: 1668 lua access handler, uri:"/sample_service/test/5237122975" c:1 2018/01/05 20:41:50 [debug] 675#0: 1668 lua creating new thread 2018/01/05 20:41:50 [debug] 675#0: 1668 lua reset ctx 2018/01/05 20:41:50 [debug] 675#0: 1668 http cleanup add: 00000000018E9258 2018/01/05 20:41:50 [debug] 675#0: 1668 lua run thread, top:0 c:1 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Host: read.api.sampleservice.com" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "User-Agent: github.com/go-loco/restful" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Accept: application/json" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Cache-Control: no-cache" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Connection: keep-alive" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Accept-Encoding: gzip" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Host: read.api.sampleservice.com" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "User-Agent: github.com/go-loco/restful" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Accept: application/json" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Cache-Control: no-cache" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Connection: keep-alive" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request header: "Accept-Encoding: gzip" 2018/01/05 20:41:50 [debug] 675#0: 1668 lua exit with code 0 2018/01/05 20:41:50 [debug] 675#0: 1668 lua resume returned 1 2018/01/05 20:41:50 [debug] 675#0: 1668 lua thread yielded 2018/01/05 20:41:50 [debug] 675#0: 1668 lua thread aborting request with status 0 2018/01/05 20:41:50 [debug] 675#0: 1668 lua request cleanup: forcible=0 2018/01/05 20:41:50 [debug] 675#0: 1668 post access phase: 12 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "http://" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "read.api.sampleservice.com" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "/sample_service/test/5237122975" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 posix_memalign: 000000000198B7E0:4096 @16 2018/01/05 20:41:50 [debug] 675#0: 1668 http init upstream, client timer: 0 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "Host: " 2018/01/05 20:41:50 [debug] 675#0: 1668 http script var: "read.api.sampleservice.com" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: " " 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http script copy: "" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "x-request-id: 6f823a5c-c5b1-49e5-89d3-9f38fc9586ff" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "accept: application/json" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "accept-encoding: gzip" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "cache-control: no-cache" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "user-agent: github.com/go-loco/restful" 2018/01/05 20:41:50 [debug] 675#0: 1668 http proxy header: "GET /sample_service/test/5237122975 HTTP/1.1 Host: read.api.sampleservice.com x-request-id: 6f823a5c-c5b1-49e5-89d3-9f38fc9586ff accept: application/json accept-encoding: gzip cache-control: no-cache user-agent: github.com/go-loco/restful

" 2018/01/05 20:41:50 [debug] 675#0: 1668 http cleanup add: 000000000198BC08 2018/01/05 20:41:50 [debug] 675#0: 1668 init keepalive peer 2018/01/05 20:41:50 [debug] 675#0: 1668 init dynamic peer 2018/01/05 20:41:50 [debug] 675#0: 1668 get keepalive peer 2018/01/05 20:41:50 [debug] 675#0: 1668 get dynamic peer 2018/01/05 20:41:50 [debug] 675#0: 1668 get rr peer, try: 4 2018/01/05 20:41:50 [debug] 675#0: 1668 get rr peer, current: 3 -1 2018/01/05 20:41:50 [debug] 675#0: 1668 name was resolved to 10.73.3.250:80 2018/01/05 20:41:50 [debug] 675#0: 1668 get keepalive peer 2018/01/05 20:41:50 [debug] 675#0: 1668 get dynamic peer 2018/01/05 20:41:50 [debug] 675#0: 1668 get keepalive peer: using connection 00007F72EEEB94B0 2018/01/05 20:41:50 [debug] 675#0: 1668 http upstream connect: -4 2018/01/05 20:41:50 [debug] 675#0: 1668 http upstream send request 2018/01/05 20:41:50 [debug] 675#0: 1668 http upstream send request body 2018/01/05 20:41:50 [debug] 675#0: 1668 chain writer buf fl:1 s:589 2018/01/05 20:41:50 [debug] 675#0: 1668 chain writer in: 000000000198BD80 2018/01/05 20:41:50 [debug] 675#0: 1668 writev: 589 of 589 2018/01/05 20:41:50 [debug] 675#0: 1668 chain writer out: 0000000000000000 2018/01/05 20:41:50 [debug] 675#0: 1668 event timer add: 133: 60000:1515184970257 2018/01/05 20:41:50 [debug] 675#0: 1668 http finalize request: -4, "/sample_service/test/5237122975?" a:1, c:2 2018/01/05 20:41:50 [debug] 675#0: 1668 http request count:2 blk:0 2018/01/05 20:41:50 [debug] 675#0: 1668 delete posted event 00007F72EF19EC80 2018/01/05 20:41:50 [debug] 675#0: 1668 http run request: "/sample_service/test/5237122975?" 2018/01/05 20:41:50 [debug] 675#0: 1668 http upstream check client, write event:1, "/sample_service/test/5237122975" 2018/01/05 20:41:50 [debug] 675#0: 1668 http upstream recv(): -1 (11: Resource temporarily unavailable) 2018/01/05 20:41:50 [debug] 678#0: 1758 http keepalive handler 2018/01/05 20:41:50 [debug] 678#0: 1758 malloc: 00000000018DC6B0:1024 2018/01/05 20:41:50 [debug] 678#0: 1758 recv: fd:14 255 of 1024 2018/01/05 20:41:50 [debug] 678#0: *1758 reusable connection: 0

alejandropal commented 6 years ago

Hello! Do you have any comments? Please let me know if you need more info about this issue or how you could reproduce this.

Thanks in advance.

hongxiaolong commented 6 years ago

Hi, @alejandropal I tried to reproduce this problem and found debug info as follows.

2018/01/31 11:31:48 [debug] 67172#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67172#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:00000000031B6000
2018/01/31 11:31:48 [debug] 67168#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:0000000000700000
2018/01/31 11:31:48 [debug] 67171#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67167#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67167#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:00000000031B6000
2018/01/31 11:31:48 [debug] 67167#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67171#0: posix_memalign: 0000000002B00000:256 @16
2018/01/31 11:31:48 [debug] 67167#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67170#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67165#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67167#0: timer delta: 52173311
2018/01/31 11:31:48 [debug] 67165#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:0000000000700000
2018/01/31 11:31:48 [debug] 67171#0: *13 accept: 127.0.0.1:50640 fd:12
2018/01/31 11:31:48 [debug] 67167#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: posix_memalign: 0000000000319980:256 @16
2018/01/31 11:31:48 [debug] 67165#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67169#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67168#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:00000000031B6000
2018/01/31 11:31:48 [debug] 67170#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:0000000000700000
2018/01/31 11:31:48 [debug] 67172#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67168#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67166#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67167#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67166#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:00000000031B6000
2018/01/31 11:31:48 [debug] 67165#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67168#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67170#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67166#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67169#0: kevent: 7: ft:-1 fl:0005 ff:00000000 d:1 ud:00000000031B6000
2018/01/31 11:31:48 [debug] 67172#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67165#0: timer delta: 52238402
2018/01/31 11:31:48 [debug] 67168#0: timer delta: 52238402
2018/01/31 11:31:48 [debug] 67166#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67169#0: accept on 0.0.0.0:8000, ready: 1
2018/01/31 11:31:48 [debug] 67170#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67170#0: timer delta: 52238403
2018/01/31 11:31:48 [debug] 67166#0: timer delta: 52238404
2018/01/31 11:31:48 [debug] 67172#0: timer delta: 52238400
2018/01/31 11:31:48 [debug] 67168#0: worker cycle
2018/01/31 11:31:48 [debug] 67169#0: accept() not ready (35: Resource temporarily unavailable)
2018/01/31 11:31:48 [debug] 67165#0: worker cycle
2018/01/31 11:31:48 [debug] 67169#0: timer delta: 52238404
2018/01/31 11:31:48 [debug] 67170#0: worker cycle
2018/01/31 11:31:48 [debug] 67169#0: worker cycle
2018/01/31 11:31:48 [debug] 67166#0: worker cycle
2018/01/31 11:31:48 [debug] 67168#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67169#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67170#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67166#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67165#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67172#0: worker cycle
2018/01/31 11:31:48 [debug] 67172#0: kevent timer: -1, changes: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer add: 12: 60000:1517369568764
2018/01/31 11:31:48 [debug] 67171#0: *13 reusable connection: 1
2018/01/31 11:31:48 [debug] 67171#0: *13 kevent set event: 12: ft:-1 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 52238402
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 60000, changes: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 12: ft:-1 fl:0025 ff:00000000 d:86 ud:00000000007000E0
2018/01/31 11:31:48 [debug] 67171#0: *13 http wait request handler
2018/01/31 11:31:48 [debug] 67171#0: *13 malloc: 0000000000801800:1024
2018/01/31 11:31:48 [debug] 67171#0: *13 recv: eof:0, avail:86, err:0
2018/01/31 11:31:48 [debug] 67171#0: *13 recv: fd:12 86 of 1024
2018/01/31 11:31:48 [debug] 67171#0: *13 reusable connection: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 posix_memalign: 0000000001010800:4096 @16
2018/01/31 11:31:48 [debug] 67171#0: *13 http process request line
2018/01/31 11:31:48 [debug] 67171#0: *13 http request line: "GET /aaa HTTP/1.1"
2018/01/31 11:31:48 [debug] 67171#0: *13 http uri: "/aaa"
2018/01/31 11:31:48 [debug] 67171#0: *13 http args: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http exten: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http process request header line
2018/01/31 11:31:48 [debug] 67171#0: *13 http header: "Host: dynamic-testing.com"
2018/01/31 11:31:48 [debug] 67171#0: *13 http header: "User-Agent: curl/7.54.0"
2018/01/31 11:31:48 [debug] 67171#0: *13 http header: "Accept: */*"
2018/01/31 11:31:48 [debug] 67171#0: *13 http header done
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer del: 12: 1517369568764
2018/01/31 11:31:48 [debug] 67171#0: *13 rewrite phase: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 test location: "/"
2018/01/31 11:31:48 [debug] 67171#0: *13 using configuration "/"
2018/01/31 11:31:48 [debug] 67171#0: *13 http cl:-1 max:0
2018/01/31 11:31:48 [debug] 67171#0: *13 rewrite phase: 2
2018/01/31 11:31:48 [debug] 67171#0: *13 rewrite phase: 3
2018/01/31 11:31:48 [debug] 67171#0: *13 post rewrite phase: 4
2018/01/31 11:31:48 [debug] 67171#0: *13 generic phase: 5
2018/01/31 11:31:48 [debug] 67171#0: *13 generic phase: 6
2018/01/31 11:31:48 [debug] 67171#0: *13 generic phase: 7
2018/01/31 11:31:48 [debug] 67171#0: *13 access phase: 8
2018/01/31 11:31:48 [debug] 67171#0: *13 access phase: 9
2018/01/31 11:31:48 [debug] 67171#0: *13 access phase: 10
2018/01/31 11:31:48 [debug] 67171#0: *13 post access phase: 11
2018/01/31 11:31:48 [debug] 67171#0: *13 posix_memalign: 0000000001011800:4096 @16
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: "http://"
2018/01/31 11:31:48 [debug] 67171#0: *13 http script var: "dynamic-testing.com"
2018/01/31 11:31:48 [debug] 67171#0: *13 http script var: "/aaa"
2018/01/31 11:31:48 [debug] 67171#0: *13 http init upstream, client timer: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 kevent set event: 12: ft:-2 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: "Host: "
2018/01/31 11:31:48 [debug] 67171#0: *13 http script var: "dynamic-testing.com"
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: "
"
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http script copy: ""
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "User-Agent: curl/7.54.0"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Accept: */*"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header:
"GET /aaa HTTP/1.1
Host: dynamic-testing.com
User-Agent: curl/7.54.0
Accept: */*

"
2018/01/31 11:31:48 [debug] 67171#0: *13 http cleanup add: 0000000001011FD0
2018/01/31 11:31:48 [debug] 67171#0: *13 init keepalive peer
2018/01/31 11:31:48 [debug] 67171#0: *13 init dynamic peer
2018/01/31 11:31:48 [debug] 67171#0: *13 get keepalive peer
2018/01/31 11:31:48 [debug] 67171#0: *13 get dynamic peer
2018/01/31 11:31:48 [debug] 67171#0: *13 get rr peer, try: 1
2018/01/31 11:31:48 [debug] 67171#0: malloc: 0000000000401380:176
2018/01/31 11:31:48 [debug] 67171#0: resolve: "op.hongxiaolong.com"
2018/01/31 11:31:48 [debug] 67171#0: malloc: 0000000000401430:128
2018/01/31 11:31:48 [debug] 67171#0: malloc: 00000000004014B0:19
2018/01/31 11:31:48 [debug] 67171#0: malloc: 00000000004014D0:37
2018/01/31 11:31:48 [debug] 67171#0: resolve: "op.hongxiaolong.com" A 63679
2018/01/31 11:31:48 [debug] 67171#0: UDP socket 14
2018/01/31 11:31:48 [debug] 67171#0: connect to 10.65.1.3:53, fd:14 #14
2018/01/31 11:31:48 [debug] 67171#0: kevent set event: 14: ft:-1 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: send: fd:14 37 of 37
2018/01/31 11:31:48 [debug] 67171#0: malloc: 00000000004000B0:112
2018/01/31 11:31:48 [debug] 67171#0: event timer add: -1: 30000:1517369538778
2018/01/31 11:31:48 [debug] 67171#0: event timer add: -1: 5000:1517369513778
2018/01/31 11:31:48 [debug] 67171#0: *13 http finalize request: -4, "/aaa?" a:1, c:2
2018/01/31 11:31:48 [debug] 67171#0: *13 http request count:2 blk:0
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 14
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 5000, changes: 2
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 12: ft:-2 fl:0025 ff:00000000 d:146988 ud:00000000029B60E0
2018/01/31 11:31:48 [debug] 67171#0: *13 http run request: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream check client, write event:1, "/aaa"
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 1
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4999, changes: 0
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 14: ft:-1 fl:0025 ff:00000000 d:53 ud:0000000000700150
2018/01/31 11:31:48 [debug] 67171#0: recv: fd:14 53 of 4096
2018/01/31 11:31:48 [debug] 67171#0: resolver DNS response 63679 fl:8180 1/1/0/0
2018/01/31 11:31:48 [debug] 67171#0: resolver DNS response qt:1 cl:1
2018/01/31 11:31:48 [debug] 67171#0: malloc: 0000000000502070:19
2018/01/31 11:31:48 [debug] 67171#0: resolver qs:op.hongxiaolong.com
2018/01/31 11:31:48 [debug] 67171#0: resolver naddrs:1 cname:0000000000000000 ttl:600
2018/01/31 11:31:48 [debug] 67171#0: resolve name done: 0
2018/01/31 11:31:48 [debug] 67171#0: event timer del: -1: 1517369538778
2018/01/31 11:31:48 [debug] 67171#0: resolver expire
2018/01/31 11:31:48 [debug] 67171#0: *13 get keepalive peer
2018/01/31 11:31:48 [debug] 67171#0: *13 get dynamic peer
2018/01/31 11:31:48 [debug] 67171#0: *13 socket 16
2018/01/31 11:31:48 [debug] 67171#0: *13 connect to 101.198.190.237:80, fd:16 #15
2018/01/31 11:31:48 [debug] 67171#0: *13 kevent set event: 16: ft:-1 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: *13 kevent set event: 16: ft:-2 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream connect: -2
2018/01/31 11:31:48 [debug] 67171#0: *13 posix_memalign: 00000000005022A0:128 @16
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer add: 16: 5000:1517369513807
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 28
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4971, changes: 2
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 16: ft:-2 fl:0025 ff:00000000 d:131768 ud:00000000029B61C0
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream request: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream send request handler
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream send request
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream send request body
2018/01/31 11:31:48 [debug] 67171#0: *13 chain writer buf fl:1 s:86
2018/01/31 11:31:48 [debug] 67171#0: *13 chain writer in: 0000000001012120
2018/01/31 11:31:48 [debug] 67171#0: *13 writev: 86 of 86
2018/01/31 11:31:48 [debug] 67171#0: *13 chain writer out: 0000000000000000
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer del: 16: 1517369513807
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer add: 16: 60000:1517369568818
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 11
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4960, changes: 0
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 16: ft:-2 fl:0025 ff:00000000 d:131768 ud:00000000029B61C0
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream request: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream dummy handler
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 13
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4947, changes: 0
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 1
2018/01/31 11:31:48 [debug] 67171#0: kevent: 16: ft:-1 fl:0025 ff:00000000 d:171 ud:00000000007001C0
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream request: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream process header
2018/01/31 11:31:48 [debug] 67171#0: *13 malloc: 000000000200DC00:4096
2018/01/31 11:31:48 [debug] 67171#0: *13 recv: eof:0, avail:171, err:0
2018/01/31 11:31:48 [debug] 67171#0: *13 recv: fd:16 171 of 4096
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy status 200 "200 OK"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Server: openresty/1.13.6.1"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Date: Wed, 31 Jan 2018 03:31:41 GMT"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Content-Type: application/octet-stream"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Content-Length: 4"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header: "Connection: keep-alive"
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy header done
2018/01/31 11:31:48 [debug] 67171#0: *13 HTTP/1.1 200 OK
Server: Tengine
Date: Wed, 31 Jan 2018 03:31:48 GMT
Content-Type: application/octet-stream
Content-Length: 4
Connection: keep-alive

2018/01/31 11:31:48 [debug] 67171#0: *13 write new buf t:1 f:0 00000000010123D0, pos 00000000010123D0, size: 156 file: 0, size: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 http write filter: l:0 f:0 s:156
2018/01/31 11:31:48 [debug] 67171#0: *13 http proxy filter init s:200 h:0 c:0 l:4
2018/01/31 11:31:48 [debug] 67171#0: *13 tcp_nodelay
2018/01/31 11:31:48 [debug] 67171#0: *13 http upstream process non buffered downstream
2018/01/31 11:31:48 [debug] 67171#0: *13 http output filter "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http copy filter: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http trim filter
2018/01/31 11:31:48 [debug] 67171#0: *13 http footer body filter
2018/01/31 11:31:48 [debug] 67171#0: *13 http postpone filter "/aaa?" 0000000001012480
2018/01/31 11:31:48 [debug] 67171#0: *13 write old buf t:1 f:0 00000000010123D0, pos 00000000010123D0, size: 156 file: 0, size: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 write new buf t:0 f:0 0000000000000000, pos 000000000200DCA7, size: 4 file: 0, size: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 http write filter: l:0 f:1 s:160
2018/01/31 11:31:48 [debug] 67171#0: *13 http write filter limit 0
2018/01/31 11:31:48 [debug] 67171#0: *13 writev: 160 of 160
2018/01/31 11:31:48 [debug] 67171#0: *13 http write filter 0000000000000000
2018/01/31 11:31:48 [debug] 67171#0: *13 http copy filter: 0 "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 finalize http upstream request: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 finalize http proxy request
2018/01/31 11:31:48 [debug] 67171#0: *13 free keepalive peer
2018/01/31 11:31:48 [debug] 67171#0: *13 free keepalive peer: saving connection 0000000002800380
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer del: 16: 1517369568818
2018/01/31 11:31:48 [debug] 67171#0: *13 free dynamic peer
2018/01/31 11:31:48 [debug] 67171#0: *13 free rr peer 1 0
2018/01/31 11:31:48 [debug] 67171#0: *13 http output filter "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http copy filter: "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http trim filter
2018/01/31 11:31:48 [debug] 67171#0: *13 http footer body filter
2018/01/31 11:31:48 [debug] 67171#0: *13 http postpone filter "/aaa?" 00007FFEEFBFED70
2018/01/31 11:31:48 [debug] 67171#0: *13 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 http write filter: l:1 f:0 s:0
2018/01/31 11:31:48 [debug] 67171#0: *13 http copy filter: 0 "/aaa?"
2018/01/31 11:31:48 [debug] 67171#0: *13 http finalize request: 0, "/aaa?" a:1, c:1
2018/01/31 11:31:48 [debug] 67171#0: *13 set http keepalive handler
2018/01/31 11:31:48 [debug] 67171#0: *13 http close request
2018/01/31 11:31:48 [debug] 67171#0: *13 http log handler
2018/01/31 11:31:48 [debug] 67171#0: *13 http status: request_time 53
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 000000000200DC00
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000001010800, unused: 1
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000001011800, unused: 477
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000000801800
2018/01/31 11:31:48 [debug] 67171#0: *13 hc free: 0000000000000000 0
2018/01/31 11:31:48 [debug] 67171#0: *13 hc busy: 0000000000000000 0
2018/01/31 11:31:48 [debug] 67171#0: *13 reusable connection: 1
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer add: 12: 320000:1517369828831
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 0
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4947, changes: 0
2018/01/31 11:31:48 [debug] 67171#0: kevent events: 2
2018/01/31 11:31:48 [debug] 67171#0: kevent: 12: ft:-2 fl:0025 ff:00000000 d:146988 ud:00000000029B60E0
2018/01/31 11:31:48 [debug] 67171#0: *13 http empty handler
2018/01/31 11:31:48 [debug] 67171#0: kevent: 12: ft:-1 fl:8025 ff:00000000 d:0 ud:00000000007000E0
2018/01/31 11:31:48 [debug] 67171#0: *13 http keepalive handler
2018/01/31 11:31:48 [info] 67171#0: *13 kevent() reported that client 127.0.0.1 closed keepalive connection
2018/01/31 11:31:48 [debug] 67171#0: *13 close http connection: 12
2018/01/31 11:31:48 [debug] 67171#0: *13 event timer del: 12: 1517369828831
2018/01/31 11:31:48 [debug] 67171#0: *13 reusable connection: 0
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000000000000
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000002B00000, unused: 24
2018/01/31 11:31:48 [debug] 67171#0: *13 free: 0000000000319980, unused: 72
2018/01/31 11:31:48 [debug] 67171#0: timer delta: 3
2018/01/31 11:31:48 [debug] 67171#0: worker cycle
2018/01/31 11:31:48 [debug] 67171#0: kevent timer: 4944, changes: 0
2018/01/31 11:31:53 [debug] 67171#0: kevent events: 0
2018/01/31 11:31:53 [debug] 67171#0: timer delta: 4944
2018/01/31 11:31:53 [debug] 67171#0: event timer del: -1: 1517369513778
2018/01/31 11:31:53 [debug] 67171#0: resolver resend handler
2018/01/31 11:31:53 [debug] 67171#0: worker cycle
2018/01/31 11:31:53 [debug] 67171#0: kevent timer: -1, changes: 0

Pay attention to section:

2018/01/31 11:31:48 [debug] 67171#0: resolve: "op.hongxiaolong.com" A 63679
2018/01/31 11:31:48 [debug] 67171#0: UDP socket 14
2018/01/31 11:31:48 [debug] 67171#0: connect to 10.65.1.3:53, fd:14 #14
2018/01/31 11:31:48 [debug] 67171#0: kevent set event: 14: ft:-1 fl:0025
2018/01/31 11:31:48 [debug] 67171#0: send: fd:14 37 of 37

2018/01/31 11:31:48 [debug] 67171#0: resolver DNS response 63679 fl:8180 1/1/0/0
2018/01/31 11:31:48 [debug] 67171#0: resolver DNS response qt:1 cl:1
2018/01/31 11:31:48 [debug] 67171#0: malloc: 0000000000502070:19
2018/01/31 11:31:48 [debug] 67171#0: resolver qs:op.hongxiaolong.com
2018/01/31 11:31:48 [debug] 67171#0: resolver naddrs:1 cname:0000000000000000 ttl:600
2018/01/31 11:31:48 [debug] 67171#0: resolve name done: 0

I found your debug info missing this important info in http_upstream_dynamic module, can u reproduce again to make sure the problem, thks.

alejandropal commented 6 years ago

Hi there!

I have been trying to get the debug info you asked me for.

The DNS resolution is not exactly as your debug info shows. There are no log entries saying "resolver DNS response".

Keep in mind we are using dynamic_resolve with an upstream to an Amazon ELB (Elastic Load Balancer) which resolves into multiple ips. In this test case resolves in 2 ips:

2018/02/10 01:02:03 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:02:03 [debug] 57#0: *100 get rr peer, current: 0 0
2018/02/10 01:02:03 [debug] 57#0: *100 name was resolved to 10.73.xxx.yyy:80
2018/02/10 01:02:03 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:02:03 [debug] 57#0: *100 get dynamic peer
--
--
2018/02/10 01:02:44 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:02:44 [debug] 57#0: *100 get rr peer, current: 1 -1
2018/02/10 01:02:44 [debug] 57#0: *100 name was resolved to 10.73.xxx.zzz:80
2018/02/10 01:02:44 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:02:44 [debug] 57#0: *100 get dynamic peer

These tests were done in Tengine 2.2.1. We are repeating these tests in the 2.2.2 soon to discard any resolved bug.

The following log shows a hanging connection:

ELB response time ( 200 at <1ms), tengine hangs (499 at 150ms)

tengine access log entry:


nginx: 172.17.0.3 - - [10/Feb/2018:01:04:21 +0000] [type:interceptor] "read.service.web.io GET /sample_service/test/5237122975 HTTP/1.1" 499 0 "-" "github.com/go-loco/restful" [status:499] [request_time:0.150] [request_time_ms:150] [upstream_response_time:-, -] [request_id:f01f071e-eb68-42aa-9156-00d5557b41f3]

ELB access log:

2018-02-10T01:04:21.028437Z sampleservice 10.90.zzz.ttt:54412 10.73.xxx.yyy:8080 **0.00002** 0.002458 0.000022 200 200 0 47 "GET http://read.service.web.io:80/sample_service/test/5237122975?**request.id=f01f071e-eb68-42aa-9156-00d5557b41f3** HTTP/1.1" "github.com/go-loco/restful" - -
2018/02/10 01:04:21 [debug] 57#0: *100 http uri: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http args: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http exten: ""
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021C8AB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http process request header line
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "X-Request-Id: 08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http header done
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 0
2018/02/10 01:04:21 [debug] 57#0: *100 test location: "/"
2018/02/10 01:04:21 [debug] 57#0: *100 using configuration "/"
2018/02/10 01:04:21 [debug] 57#0: *100 http cl:-1 max:0
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 2
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 3
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $logs_enabled
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "b2b3f2d5-2fb9-4af8-aff1-251ea8551e1e"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $fwd_request_id
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $check_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $load_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $call_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $request_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $upstream_response_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $read_config_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $rew_uri
2018/02/10 01:04:21 [debug] 57#0: *100 post rewrite phase: 4
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 5
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 6
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 7
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 8
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 9
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 10
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 11
2018/02/10 01:04:21 [debug] 57#0: *100 lua access handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua creating new thread
2018/02/10 01:04:21 [debug] 57#0: *100 lua reset ctx
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021F2CF0
2018/02/10 01:04:21 [debug] 57#0: *100 lua run thread, top:0 c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua exit with code 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua resume returned 1
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread yielded
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread aborting request with status 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua request cleanup: forcible=0
2018/02/10 01:04:21 [debug] 57#0: *100 post access phase: 12
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F4F90:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "http://"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "?"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http init upstream, client timer: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "Host: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "user-agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept-encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "x-request-id: 08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "cache-control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header:
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021C9A98
2018/02/10 01:04:21 [debug] 57#0: *100 init keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 init dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, current: 0 0
2018/02/10 01:04:21 [debug] 57#0: *100 name was resolved to 10.73.xxx.yyy:80
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer: using connection 00007FF5C543D710
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream connect: -4
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request body
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer buf fl:1 s:711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer in: 00000000021F5718
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 711 of 711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer out: 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 28: 60000:1518224721006
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: -4, "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf" a:1, c:2
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:2 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:1, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream request: "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process header
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021F5FA0:4096
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:28 426 of 4096
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy status 200 "200 "
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Credentials: true"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Headers: X-Requested-With,Content-Type"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Type: application/json;charset=utf-8"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Date: Sat, 10 Feb 2018 01:04:21 GMT"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Server: Tengine"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Vary: Accept-Encoding"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Timestamp: 1518223104185000"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Ttls: -1"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Versions: 0"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Length: 47"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header done
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture header filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 HTTP/1.1 200 
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:1 f:0 00000000021F5CA0, pos 00000000021F5CA0, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:0 s:379
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy filter init s:200 h:0 c:0 l:47
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process non buffered downstream
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf" 00000000021F5E30
2018/02/10 01:04:21 [debug] 57#0: *100 write old buf t:1 f:0 00000000021F5CA0, pos 00000000021F5CA0, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 00000000021F611B, size: 47 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:1 s:426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter limit 0
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 426 of 426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http upstream request: 0
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http proxy request
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer: saving connection 00007FF5C543D710
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 28: 1518224721006
2018/02/10 01:04:21 [debug] 57#0: *100 free dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 free rr peer 2 0
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf" 00007FFD16643EA0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:1 f:0 s:0
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf"
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: 0, "/sample_service/test/5237122975?request.id=08dfde22-af49-4a30-9a18-f4bb307267bf" a:1, c:1
2018/02/10 01:04:21 [debug] 57#0: *100 set http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 http close request
2018/02/10 01:04:21 [debug] 57#0: *100 lua log handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F6FB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http log handler
2018/02/10 01:04:21 [debug] 57#0: *100 http status: request_time 5
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F5FA0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F1DB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021C8AB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F4F90, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F6FB0, unused: 3292
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021E5880
2018/02/10 01:04:21 [debug] 57#0: *100 hc free: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 hc busy: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 1
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 24: 320000:1518224981011
2018/02/10 01:04:21 [debug] 57#0: *100 post event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 delete posted event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021E5880:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 -1 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv() not ready (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021E5880
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021E5880:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 343 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 0
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021C8AB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 24: 1518224981011
2018/02/10 01:04:21 [debug] 57#0: *100 http process request line
2018/02/10 01:04:21 [debug] 57#0: *100 http request line: "GET /sample_service/test/5237122975 HTTP/1.1"
2018/02/10 01:04:21 [debug] 57#0: *100 http uri: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http args: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http exten: ""
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F1DB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http process request header line
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "X-Request-Id: 0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http header done
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 0
2018/02/10 01:04:21 [debug] 57#0: *100 test location: "/"
2018/02/10 01:04:21 [debug] 57#0: *100 using configuration "/"
2018/02/10 01:04:21 [debug] 57#0: *100 http cl:-1 max:0
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 2
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 3
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $logs_enabled
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "b0db64c3-1810-42be-ae10-e0b5d50e557f"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $fwd_request_id
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $check_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $load_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $call_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $request_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $upstream_response_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $read_config_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $rew_uri
2018/02/10 01:04:21 [debug] 57#0: *100 post rewrite phase: 4
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 5
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 6
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 7
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 8
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 9
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 10
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 11
2018/02/10 01:04:21 [debug] 57#0: *100 lua access handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua creating new thread
2018/02/10 01:04:21 [debug] 57#0: *100 lua reset ctx
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021C99F0
2018/02/10 01:04:21 [debug] 57#0: *100 lua run thread, top:0 c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua exit with code 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua resume returned 1
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread yielded
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread aborting request with status 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua request cleanup: forcible=0
2018/02/10 01:04:21 [debug] 57#0: *100 post access phase: 12
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F4F90:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "http://"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "?"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http init upstream, client timer: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "Host: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "user-agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept-encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "x-request-id: 0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "cache-control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header:
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021F2D98
2018/02/10 01:04:21 [debug] 57#0: *100 init keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 init dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, current: 1 -1
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer: using connection 00007FF5C543D710
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream connect: -4
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request body
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer buf fl:1 s:711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer in: 00000000021F56F0
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 711 of 711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer out: 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 28: 60000:1518224721011
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: -4, "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c" a:1, c:2
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:2 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:1, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream request: "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process header
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021F5FA0:4096
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:28 426 of 4096
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy status 200 "200 "
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Credentials: true"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Headers: X-Requested-With,Content-Type"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Type: application/json;charset=utf-8"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Date: Sat, 10 Feb 2018 01:04:21 GMT"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Server: Tengine"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Vary: Accept-Encoding"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Timestamp: 1518223104185000"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Ttls: -1"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Versions: 0"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Length: 47"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header done
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture header filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 HTTP/1.1 200 
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:1 f:0 00000000021F5C78, pos 00000000021F5C78, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:0 s:379
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy filter init s:200 h:0 c:0 l:47
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process non buffered downstream
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c" 00000000021F5E08
2018/02/10 01:04:21 [debug] 57#0: *100 write old buf t:1 f:0 00000000021F5C78, pos 00000000021F5C78, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 00000000021F611B, size: 47 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:1 s:426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter limit 0
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 426 of 426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http upstream request: 0
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http proxy request
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer: saving connection 00007FF5C543D710
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 28: 1518224721011
2018/02/10 01:04:21 [debug] 57#0: *100 free dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 free rr peer 2 0
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c" 00007FFD16643EA0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:1 f:0 s:0
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c"
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: 0, "/sample_service/test/5237122975?request.id=0e2010a3-6724-4bdf-a011-226ad462c46c" a:1, c:1
2018/02/10 01:04:21 [debug] 57#0: *100 set http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 http close request
2018/02/10 01:04:21 [debug] 57#0: *100 lua log handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F6FB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http log handler
2018/02/10 01:04:21 [debug] 57#0: *100 http status: request_time 4
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F5FA0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021C8AB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F1DB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F4F90, unused: 7
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F6FB0, unused: 3322
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021E5880
2018/02/10 01:04:21 [debug] 57#0: *100 hc free: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 hc busy: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 1
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 24: 320000:1518224981015
2018/02/10 01:04:21 [debug] 57#0: *100 post event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 delete posted event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021F3680:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 -1 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv() not ready (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F3680
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021F3680:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 343 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 0
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F1AF0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 24: 1518224981015
2018/02/10 01:04:21 [debug] 57#0: *100 http process request line
2018/02/10 01:04:21 [debug] 57#0: *100 http request line: "GET /sample_service/test/5237122975 HTTP/1.1"
2018/02/10 01:04:21 [debug] 57#0: *100 http uri: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http args: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http exten: ""
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021C8AB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http process request header line
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "X-Request-Id: 077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http header done
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 0
2018/02/10 01:04:21 [debug] 57#0: *100 test location: "/"
2018/02/10 01:04:21 [debug] 57#0: *100 using configuration "/"
2018/02/10 01:04:21 [debug] 57#0: *100 http cl:-1 max:0
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 2
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 3
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $logs_enabled
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "f993ca67-a448-4da7-8759-2a775801073f"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $fwd_request_id
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $check_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $load_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $call_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $request_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $upstream_response_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $read_config_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $rew_uri
2018/02/10 01:04:21 [debug] 57#0: *100 post rewrite phase: 4
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 5
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 6
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 7
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 8
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 9
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 10
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 11
2018/02/10 01:04:21 [debug] 57#0: *100 lua access handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua creating new thread
2018/02/10 01:04:21 [debug] 57#0: *100 lua reset ctx
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021F2A30
2018/02/10 01:04:21 [debug] 57#0: *100 lua run thread, top:0 c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: 077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua exit with code 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua resume returned 1
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread yielded
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread aborting request with status 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua request cleanup: forcible=0
2018/02/10 01:04:21 [debug] 57#0: *100 post access phase: 12
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F4DD0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "http://"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "?"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http init upstream, client timer: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "Host: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept-encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "x-request-id: 077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "cache-control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "user-agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header:
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021F53F8
2018/02/10 01:04:21 [debug] 57#0: *100 init keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 init dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, current: 0 0
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer: using connection 00007FF5C543D630
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream connect: -4
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request body
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer buf fl:1 s:711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer in: 00000000021F5538
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 711 of 711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer out: 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 26: 60000:1518224721015
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: -4, "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d" a:1, c:2
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:2 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:1, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream request: "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process header
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021F5DE0:4096
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:26 426 of 4096
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy status 200 "200 "
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Credentials: true"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Access-Control-Allow-Headers: X-Requested-With,Content-Type"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Type: application/json;charset=utf-8"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Date: Sat, 10 Feb 2018 01:04:21 GMT"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Server: Tengine"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Vary: Accept-Encoding"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Timestamp: 1518223104185000"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Ttls: -1"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "X-Service-Versions: 0"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Content-Length: 47"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header done
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture header filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 HTTP/1.1 200 
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:1 f:0 00000000021F5AC0, pos 00000000021F5AC0, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:0 s:379
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy filter init s:200 h:0 c:0 l:47
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream process non buffered downstream
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d" 00000000021F5C50
2018/02/10 01:04:21 [debug] 57#0: *100 write old buf t:1 f:0 00000000021F5AC0, pos 00000000021F5AC0, size: 379 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 00000000021F5F5B, size: 47 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:0 f:1 s:426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter limit 0
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 426 of 426
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http upstream request: 0
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http proxy request
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer: saving connection 00007FF5C543D630
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 26: 1518224721015
2018/02/10 01:04:21 [debug] 57#0: *100 free dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 free rr peer 2 0
2018/02/10 01:04:21 [debug] 57#0: *100 http output filter "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 lua capture body filter, uri "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http trim filter
2018/02/10 01:04:21 [debug] 57#0: *100 http footer body filter
2018/02/10 01:04:21 [debug] 57#0: *100 http postpone filter "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d" 00007FFD16643EA0
2018/02/10 01:04:21 [debug] 57#0: *100 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http write filter: l:1 f:0 s:0
2018/02/10 01:04:21 [debug] 57#0: *100 http copy filter: 0 "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d"
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: 0, "/sample_service/test/5237122975?request.id=077e6880-480e-4a8c-bb9a-37e28bb4644d" a:1, c:1
2018/02/10 01:04:21 [debug] 57#0: *100 set http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 http close request
2018/02/10 01:04:21 [debug] 57#0: *100 lua log handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F6DF0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http log handler
2018/02/10 01:04:21 [debug] 57#0: *100 http status: request_time 5
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F5DE0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F1AF0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021C8AB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F4DD0, unused: 7
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F6DF0, unused: 3316
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F3680
2018/02/10 01:04:21 [debug] 57#0: *100 hc free: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 hc busy: 0000000000000000 0
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 1
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 24: 320000:1518224981020
2018/02/10 01:04:21 [debug] 57#0: *100 post event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 delete posted event 00007FF5CBD43218
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021E5880:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 -1 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv() not ready (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021E5880
2018/02/10 01:04:21 [debug] 57#0: *100 http keepalive handler
2018/02/10 01:04:21 [debug] 57#0: *100 malloc: 00000000021E5880:1024
2018/02/10 01:04:21 [debug] 57#0: *100 recv: fd:24 343 of 1024
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 0
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021C8AB0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 24: 1518224981020
2018/02/10 01:04:21 [debug] 57#0: *100 http process request line
2018/02/10 01:04:21 [debug] 57#0: *100 http request line: "GET /sample_service/test/5237122975 HTTP/1.1"
2018/02/10 01:04:21 [debug] 57#0: *100 http uri: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http args: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http exten: ""
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F1AF0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http process request header line
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "X-Request-Id: f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http header done
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 0
2018/02/10 01:04:21 [debug] 57#0: *100 test location: "/"
2018/02/10 01:04:21 [debug] 57#0: *100 using configuration "/"
2018/02/10 01:04:21 [debug] 57#0: *100 http cl:-1 max:0
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 2
2018/02/10 01:04:21 [debug] 57#0: *100 rewrite phase: 3
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $logs_enabled
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "dff6a621-d25b-42c7-8d80-8f5bd0b882be"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $fwd_request_id
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $check_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $load_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $call_so_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $request_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $upstream_response_time_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script value: "0"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $read_config_ms
2018/02/10 01:04:21 [debug] 57#0: *100 http script complex value
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script set $rew_uri
2018/02/10 01:04:21 [debug] 57#0: *100 post rewrite phase: 4
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 5
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 6
2018/02/10 01:04:21 [debug] 57#0: *100 generic phase: 7
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 8
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 9
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 10
2018/02/10 01:04:21 [debug] 57#0: *100 access phase: 11
2018/02/10 01:04:21 [debug] 57#0: *100 lua access handler, uri:"/sample_service/test/5237122975" c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua creating new thread
2018/02/10 01:04:21 [debug] 57#0: *100 lua reset ctx
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021C99F0
2018/02/10 01:04:21 [debug] 57#0: *100 lua run thread, top:0 c:1
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Host: read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "User-Agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Cache-Control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Connection: keep-alive"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "X-Request-Id: f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 lua request header: "Accept-Encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 lua exit with code 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua resume returned 1
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread yielded
2018/02/10 01:04:21 [debug] 57#0: *100 lua thread aborting request with status 0
2018/02/10 01:04:21 [debug] 57#0: *100 lua request cleanup: forcible=0
2018/02/10 01:04:21 [debug] 57#0: *100 post access phase: 12
2018/02/10 01:04:21 [debug] 57#0: *100 posix_memalign: 00000000021F4DD0:4096 @16
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "http://"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "?"
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http init upstream, client timer: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "Host: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script var: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: "
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http script copy: ""
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept-encoding: gzip"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "accept: application/json"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "x-request-id: f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "cache-control: no-cache"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header: "user-agent: github.com/go-loco/restful"
2018/02/10 01:04:21 [debug] 57#0: *100 http proxy header:
2018/02/10 01:04:21 [debug] 57#0: *100 http cleanup add: 00000000021F53F8
2018/02/10 01:04:21 [debug] 57#0: *100 init keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 init dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, try: 2
2018/02/10 01:04:21 [debug] 57#0: *100 get rr peer, current: 1 -1
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 get dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 get keepalive peer: using connection 00007FF5C543D710
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream connect: -4
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream send request body
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer buf fl:1 s:711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer in: 00000000021F5538
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 711 of 711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer out: 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 28: 60000:1518224721021
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: -4, "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3" a:1, c:2
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:2 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:1, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:0, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [info] 57#0: *100 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 172.17.0.3, server: interceptor, request: "GET /sample_service/test/5237122975 HTTP/1.1", upstream: "http://10.73.xxx.yyy:80/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3", host: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http upstream request: 499
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http proxy request
2018/02/10 01:04:21 [debug] 57#0: *100 free keepalive peer
2018/02/10 01:04:21 [debug] 57#0: *100 free dynamic peer
2018/02/10 01:04:21 [debug] 57#0: *100 free rr peer 2 0
2018/02/10 01:04:21 [debug] 57#0: *100 close http upstream connection: 28
2018/02/10 01:04:21 [debug] 57#0: *100 free: 0000000002144480, unused: 48
2018/02/10 01:04:21 [debug] 57#0: *100 event timer del: 28: 1518224721021
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 0
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: 499, "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3" a:1, c:1
2018/02/10 01:04:21 [debug] 57#0: *100 http terminate request count:1
2018/02/10 01:04:21 [debug] 57#0: *100 http terminate cleanup count:1 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http posted request: "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http terminate handler count:1
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:1 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http close request
2018/02/10 01:04:21 [debug] 57#0: *100 lua log handler, uri:"/sample_service/test/5237122975" c:0
2018/02/10 01:04:21 [debug] 57#0: *100 http log handler
2018/02/10 01:04:21 [debug] 57#0: *100 http status: request_time 150
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021C8AB0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F1AF0, unused: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021F4DD0, unused: 1358
2018/02/10 01:04:21 [debug] 57#0: *100 close http connection: 24
2018/02/10 01:04:21 [debug] 57#0: *100 reusable connection: 0
2018/02/10 01:04:21 [debug] 57#0: *100 free: 00000000021E5880
2018/02/10 01:04:21 [debug] 57#0: *100 free: 0000000002142B60, unused: 24
2018/02/10 01:04:21 [debug] 57#0: *100 free: 0000000002144370, unused: 72

Please let me know if you need any further information.

Thanks in advance, Alejandro

hongxiaolong commented 6 years ago 
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer in: 00000000021F5538
2018/02/10 01:04:21 [debug] 57#0: *100 writev: 711 of 711
2018/02/10 01:04:21 [debug] 57#0: *100 chain writer out: 0000000000000000
2018/02/10 01:04:21 [debug] 57#0: *100 event timer add: 28: 60000:1518224721021
2018/02/10 01:04:21 [debug] 57#0: *100 http finalize request: -4, "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3" a:1, c:2
2018/02/10 01:04:21 [debug] 57#0: *100 http request count:2 blk:0
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:1, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/02/10 01:04:21 [debug] 57#0: *100 http run request: "/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3"
2018/02/10 01:04:21 [debug] 57#0: *100 http upstream check client, write event:0, "/sample_service/test/5237122975"
2018/02/10 01:04:21 [info] 57#0: *100 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 172.17.0.3, server: interceptor, request: "GET /sample_service/test/5237122975 HTTP/1.1", upstream: "http://10.73.xxx.yyy:80/sample_service/test/5237122975?request.id=f01f071e-eb68-42aa-9156-00d5557b41f3", host: "read.service.web.io"
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http upstream request: 499
2018/02/10 01:04:21 [debug] 57#0: *100 finalize http proxy request

Hello, @alejandropal I saw your debug information, even though u might delete some sensitive information, I could not favoringly analyse how ur requests worked. But as I listed above, I could saw that ur ngx_http_upstream_send_request_body had worked and successfully wrote 711 bytes, and finally u reached ngx_http_upstream_check_broken_connection, in this function, TENGINE checked "that client prematurely closed connection, so upstream connection is closed too while sending request to upstream", so u got a 499 error. Maybe u can try to find the client log with 499 or record the network errorflag between client.

Wish to be helpful, thks

alejandropal commented 6 years ago

Yes, I deleted the write section in order to keep the log as minimum as possible.

...
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'73:s'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'2F:/'
2018/02/10 04:15:16 [debug] 58#0: *57 s:1 in:'73:s'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'74:t'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'72:r'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'65:e'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'73:s'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'73:s'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'5F:_'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'74:t'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'65:e'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'73:s'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'74:t'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'5F:_'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'66:f'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'69:i'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'6C:l'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'74:t'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'65:e'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'72:r'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'65:e'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'64:d'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'5F:_'
2018/02/10 04:15:16 [debug] 58#0: *57 s:0 in:'5F:_'
....

that client prematurely closed connection, so upstream connection is closed too while sending request to upstream.

This shows the behavior I mentioned at first. The request is correctly sent to the service through ELB (which response with 200 and took about 1-2 ms), but It has never arrived at Tengine. About 150 ms later, the client closes the connection by timeout, and immediately starts with this strange FIN/ACK and RESET.

This doesn't happen if we use a nginx regular upstream instead of using dynamic_resolve.

Thanks!

Alejandro.

hongxiaolong commented 6 years ago

The request is correctly sent to the service through ELB (which response with 200 and took about 1-2 ms), but It has never arrived at Tengine.

According to ur tcpdump and debug log, can I comprehend that:

Clinet -> TENGINE -> ELB

ELB received the request from TENGINE and already responsed with 200 (according to ngx_http_upstream_send_request_body with "writev: 711 of 711"). What do you mean about

but It has never arrived at Tengine

Yes, tcpdump showed TENGINE received PSH from Client, following with the strang FIN/ACK after 0.15ms, could u please try to dump the whole TCP flow from Client <-> TENGINE <-> ELB.

I alse suggest u can add some debug points/logs to detail ur case, because there not exists timer or hang behavior in this module except DNS resolver(in ur case, ELB had already be resovled).

Wish to be helpful, thks