upgrade to 1-9.15 caused block requests

Ortal nginx-forum at forum.nginx.org
Thu Nov 22 12:15:41 UTC 2018


This is a small example of my code, I changed the code and in the current
version on post/put request trying to read the buffer and print it, on any
other requests just send response (I tried to minimal it as much as I
could)
On the current flow when  running a post request with 1MB data the
ngx_http_read_client_request_body return NGX_AGAIN and not call the
post_handler
I am not getting the ngx_http_block_reading for the request but I still do
not get the request buffer, and the post_handler is not called

static char *ngx_v3io_test_pass(ngx_conf_t *cf, ngx_command_t *cmd, void
*conf)
{
    if (unlikely(cf == NULL || cmd == NULL || conf == NULL))
        return NGX_CONF_ERROR;

    ngx_http_core_loc_conf_t *core_loc_cf;

    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, cf->log, 0, "ngx_v3io_test: pass cmd
args:%d", cf->args->nelts);

    core_loc_cf = ngx_http_conf_get_module_loc_conf(cf,
ngx_http_core_module);
    if (unlikely(!core_loc_cf))
        return NGX_CONF_ERROR;

    core_loc_cf->handler = ngx_v3io_test_req_handler;

    return NGX_CONF_OK;
}

static void ngx_v3io_test_send_response(ngx_http_request_t *req, ngx_int_t
rc)
{

    req->headers_out.status = rc;
    req->headers_out.content_length_n = 0;
    req->header_only = 1;

    ngx_http_send_header(req);

    req->connection->log->action = "sending to client";
    ngx_http_finalize_request(req, NGX_DONE);
}

ngx_int_t ngx_v3io_http_test_read_client_request_body(ngx_http_request_t
*req,
                                                     
ngx_http_client_body_handler_pt post_handler)
{
    if (unlikely(req->main->count == 0)){
        ngx_log_error(NGX_LOG_ERR, req->connection->log, 0, "ngx_v3io_test:
r->main->count == 0, req: %p", req);
        return NGX_HTTP_INTERNAL_SERVER_ERROR;
    }

    req->main->count--;
    return ngx_http_read_client_request_body(req, post_handler);
}

static void ngx_v3io_obj_test_post_handle_request_body(ngx_http_request_t
*req)
{
    ngx_log_t *log = req->connection->log;

    ngx_log_error(NGX_LOG_INFO, log, 0, "ngx_v3io_test req: %p, ngx_ret: %d,
req_len: %l \n", req, req->headers_in.content_length_n);

    if (req->request_body->bufs != NULL) {
        ngx_log_error(NGX_LOG_INFO, log, 0, "ngx_v3io_test req: %p, req_buf:
%s \n", req, req->request_body->bufs->buf->pos);
    } else {
        ngx_log_error(NGX_LOG_INFO, log, 0, "ngx_v3io_test req: %p, %d,
req_buf is NULL \n", req);
    }

    ngx_v3io_test_send_response(req, NGX_OK);
}

ngx_int_t ngx_v3io_http_test_handle_post_req(ngx_http_request_t *req)
{
    ngx_log_t *log = req->connection->log;
    ngx_int_t rc;

    rc = ngx_handle_read_event(req->connection->read, 0);
    if (unlikely(rc != NGX_OK)) {
        ngx_log_error(NGX_LOG_INFO,
                      log,
                      0,
                      "ngx_v3io_test: req: %p, failed to handle_read_event,
ngx_ret: %d",
                      req,
                      rc);
        return NGX_HTTP_INTERNAL_SERVER_ERROR;
    }

    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, log, 0, "ngx_v3io_test: req: %p",
req);
    rc = ngx_v3io_http_test_read_client_request_body(req,
ngx_v3io_obj_test_post_handle_request_body);
    if (likely(rc == NGX_OK || rc == NGX_AGAIN)) {
        ngx_log_error(NGX_LOG_INFO, log, 0, "ngx_v3io_test req: %p,
read_client_request_body, ngx_ret: %d \n", req, rc);
        return NGX_AGAIN;
    } else {
        ngx_log_error(NGX_LOG_INFO, log, 0, "ngx_v3io_test req: %p,
read_client_request_body, ngx_ret: %d \n", req, rc);
        return rc;
    }


}

#define ONE_MB_LEN (1024 * 1024)

ngx_int_t ngx_v3io_http_test_post_req(ngx_http_request_t *req) {
    ngx_int_t rc = NGX_OK;
    rc = ngx_v3io_http_test_handle_post_req(req);
    if (unlikely(rc != NGX_AGAIN)) {
        rc = NGX_HTTP_INTERNAL_SERVER_ERROR;
        ngx_v3io_test_send_response(req, rc);
    }

    return rc;

}

ngx_int_t ngx_v3io_test_req_handler(ngx_http_request_t *req)
{
    if (unlikely(!req))
        return NGX_HTTP_INTERNAL_SERVER_ERROR;

    ngx_log_t *log = req->connection->log;
    if (unlikely(!log))
        return NGX_HTTP_INTERNAL_SERVER_ERROR;

    ngx_uint_t method = req->method;
    ngx_int_t rc = NGX_OK;

    if (method & (NGX_HTTP_PUT | NGX_HTTP_POST))
        rc = ngx_v3io_http_test_post_req(req);
    else
        ngx_v3io_test_send_response(req, rc);

    return rc;
}


nginx logs:
When I am sending a post request with size = 4 bytes

=======
2018/11/22 14:00:21 [debug] 16673#0: epoll: fd:13 ev:0001
d:00007F4A7DB21010
2018/11/22 14:00:21 [debug] 16673#0: accept on 0.0.0.0:8081, ready: 1
2018/11/22 14:00:21 [debug] 16673#0: posix_memalign: 00000000011C9F10:512
@16
2018/11/22 14:00:21 [debug] 16673#0: *7 accept: 127.0.0.1:35432 fd:17
2018/11/22 14:00:21 [debug] 16673#0: *7 event timer add: 17: 60000:56037164
2018/11/22 14:00:21 [debug] 16673#0: *7 reusable connection: 1
2018/11/22 14:00:21 [debug] 16673#0: *7 epoll add event: fd:17 op:1
ev:80002001
2018/11/22 14:00:21 [debug] 16673#0: accept() not ready (11: Resource
temporarily unavailable)
2018/11/22 14:00:21 [debug] 16673#0: timer delta: 4760
2018/11/22 14:00:21 [debug] 16673#0: worker cycle
2018/11/22 14:00:21 [debug] 16673#0: epoll timer: 20077
2018/11/22 14:00:21 [debug] 16673#0: epoll: fd:17 ev:0001
d:00007F4A7DB212E0
2018/11/22 14:00:21 [debug] 16673#0: *7 http wait request handler
2018/11/22 14:00:21 [debug] 16673#0: *7 malloc: 00000000011CA120:1024
2018/11/22 14:00:21 [debug] 16673#0: *7 recv: eof:0, avail:1
2018/11/22 14:00:21 [debug] 16673#0: *7 recv: fd:17 160 of 1024
2018/11/22 14:00:21 [debug] 16673#0: *7 reusable connection: 0
2018/11/22 14:00:21 [debug] 16673#0: *7 posix_memalign:
00000000011D2AE0:4096 @16
2018/11/22 14:00:21 [debug] 16673#0: *7 http process request line
2018/11/22 14:00:21 [debug] 16673#0: *7 http request line: "PUT /1/file.txt
HTTP/1.1"
2018/11/22 14:00:21 [debug] 16673#0: *7 http uri: "/1/file.txt"
2018/11/22 14:00:21 [debug] 16673#0: *7 http args: ""
2018/11/22 14:00:21 [debug] 16673#0: *7 http exten: "txt"
2018/11/22 14:00:21 [debug] 16673#0: *7 posix_memalign:
00000000011AF4A0:4096 @16
2018/11/22 14:00:21 [debug] 16673#0: *7 http process request header line
2018/11/22 14:00:21 [debug] 16673#0: *7 http header: "Host: 127.0.0.1:8081"
2018/11/22 14:00:21 [debug] 16673#0: *7 http header: "User-Agent:
curl/7.47.0"
2018/11/22 14:00:21 [debug] 16673#0: *7 http header: "Accept: */*"
2018/11/22 14:00:21 [debug] 16673#0: *7 http header: "Content-Length: 4"
2018/11/22 14:00:21 [debug] 16673#0: *7 http header: "Content-Type:
application/x-www-form-urlencoded"
2018/11/22 14:00:21 [debug] 16673#0: *7 http header done
2018/11/22 14:00:21 [debug] 16673#0: *7 event timer del: 17: 56037164
2018/11/22 14:00:21 [debug] 16673#0: *7 rewrite phase: 0
2018/11/22 14:00:21 [debug] 16673#0: *7 test location: "/"
2018/11/22 14:00:21 [debug] 16673#0: *7 using configuration "/"
2018/11/22 14:00:21 [debug] 16673#0: *7 http cl:4 max:5368709120
2018/11/22 14:00:21 [debug] 16673#0: *7 rewrite phase: 2
2018/11/22 14:00:21 [debug] 16673#0: *7 http script value: "1"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script set $cors
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var: "PUT"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script value: "OPTIONS"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script equal
2018/11/22 14:00:21 [debug] 16673#0: *7 http script equal: no
2018/11/22 14:00:21 [debug] 16673#0: *7 http script if
2018/11/22 14:00:21 [debug] 16673#0: *7 http script if: false
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var: "1"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script value: "1"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script equal
2018/11/22 14:00:21 [debug] 16673#0: *7 http script if
2018/11/22 14:00:21 [debug] 16673#0: *7 http script complex value
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var: "/1/file.txt"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script copy: "?"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script set $v3io_key
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var
2018/11/22 14:00:21 [debug] 16673#0: *7 http script var: "1"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script value: "1o"
2018/11/22 14:00:21 [debug] 16673#0: *7 http script equal
2018/11/22 14:00:21 [debug] 16673#0: *7 http script equal: no
2018/11/22 14:00:21 [debug] 16673#0: *7 http script if
2018/11/22 14:00:21 [debug] 16673#0: *7 http script if: false
2018/11/22 14:00:21 [debug] 16673#0: *7 post rewrite phase: 3
2018/11/22 14:00:21 [debug] 16673#0: *7 generic phase: 4
2018/11/22 14:00:21 [debug] 16673#0: *7 generic phase: 5
2018/11/22 14:00:21 [debug] 16673#0: *7 access phase: 6
2018/11/22 14:00:21 [debug] 16673#0: *7 access phase: 7
2018/11/22 14:00:21 [debug] 16673#0: *7 post access phase: 8
2018/11/22 14:00:21 [debug] 16673#0: *7 generic phase: 9
2018/11/22 14:00:21 [debug] 16673#0: *7 generic phase: 10
2018/11/22 14:00:21 [debug] 16673#0: *7 ngx_v3io_test: req:
00000000011D2B30
2018/11/22 14:00:21 [debug] 16673#0: *7 http client request body preread 4
2018/11/22 14:00:21 [debug] 16673#0: *7 http request body content length
filter
2018/11/22 14:00:21 [debug] 16673#0: *7 http body new buf t:1 f:0
00000000011CA1BC, pos 00000000011CA1BC, size: 4 file: 0, size: 0
2018/11/22 14:00:21 [info] 16673#0: *7 ngx_v3io_test req: 00000000011D2B30,
ngx_ret: 4, req_len: 4 
, client: 127.0.0.1, server: localhost, request: "PUT /1/file.txt HTTP/1.1",
host: "127.0.0.1:8081"
2018/11/22 14:00:21 [info] 16673#0: *7 ngx_v3io_test req: 00000000011D2B30,
req_buf: txt1
, client: 127.0.0.1, server: localhost, request: "PUT /1/file.txt HTTP/1.1",
host: "127.0.0.1:8081"
2018/11/22 14:00:21 [debug] 16673#0: *7 HTTP/1.1 000 
Server: nginx/1.15.6
Date: Thu, 22 Nov 2018 12:00:21 GMT
Content-Length: 0
Connection: keep-alive

2018/11/22 14:00:21 [debug] 16673#0: *7 write new buf t:1 f:0
00000000011D3A10, pos 00000000011D3A10, size: 119 file: 0, size: 0
2018/11/22 14:00:21 [debug] 16673#0: *7 http write filter: l:1 f:0 s:119
2018/11/22 14:00:21 [debug] 16673#0: *7 http write filter limit 0
2018/11/22 14:00:21 [debug] 16673#0: *7 writev: 119 of 119
2018/11/22 14:00:21 [debug] 16673#0: *7 http write filter 0000000000000000
2018/11/22 14:00:21 [debug] 16673#0: *7 http finalize request: -4,
"/1/file.txt?" a:1, c:1
2018/11/22 14:00:21 [debug] 16673#0: *7 set http keepalive handler
2018/11/22 14:00:21 [debug] 16673#0: *7 http close request
2018/11/22 14:00:21 [debug] 16673#0: *7 http log handler
2018/11/22 14:00:21 [debug] 16673#0: *7 free: 00000000011D2AE0, unused: 32
2018/11/22 14:00:21 [debug] 16673#0: *7 free: 00000000011AF4A0, unused:
2974
2018/11/22 14:00:21 [debug] 16673#0: *7 free: 00000000011CA120
2018/11/22 14:00:21 [debug] 16673#0: *7 hc free: 0000000000000000
2018/11/22 14:00:21 [debug] 16673#0: *7 hc busy: 0000000000000000 0
2018/11/22 14:00:21 [debug] 16673#0: *7 tcp_nodelay
2018/11/22 14:00:21 [debug] 16673#0: *7 reusable connection: 1
2018/11/22 14:00:21 [debug] 16673#0: *7 event timer add: 17: 65000:56042164
2018/11/22 14:00:21 [info] 16673#0: *7 ngx_v3io_test req: 00000000011D2B30,
read_client_request_body, ngx_ret: 0 
 while keepalive, client: 127.0.0.1, server: 0.0.0.0:8081
2018/11/22 14:00:21 [debug] 16673#0: *7 http finalize request: -2, "x
                                                                     }|J?"
a:0, c:1
2018/11/22 14:00:21 [alert] 16673#0: *7 http finalize non-active request:
"x
                                                                           
}|J?" while keepalive, client: 127.0.0.1, server: 0.0.0.0:8081
2018/11/22 14:00:21 [debug] 16673#0: timer delta: 0
2018/11/22 14:00:21 [debug] 16673#0: worker cycle
2018/11/22 14:00:21 [debug] 16673#0: epoll timer: 20077
2018/11/22 14:00:21 [debug] 16673#0: epoll: fd:17 ev:2001
d:00007F4A7DB212E0
2018/11/22 14:00:21 [debug] 16673#0: *7 http keepalive handler
2018/11/22 14:00:21 [debug] 16673#0: *7 malloc: 00000000011CA120:1024
2018/11/22 14:00:21 [debug] 16673#0: *7 recv: eof:1, avail:1
2018/11/22 14:00:21 [debug] 16673#0: *7 recv: fd:17 0 of 1024
2018/11/22 14:00:21 [info] 16673#0: *7 client 127.0.0.1 closed keepalive
connection
2018/11/22 14:00:21 [debug] 16673#0: *7 close http connection: 17
2018/11/22 14:00:21 [debug] 16673#0: *7 event timer del: 17: 56042164
2018/11/22 14:00:21 [debug] 16673#0: *7 reusable connection: 0
2018/11/22 14:00:21 [debug] 16673#0: *7 free: 00000000011CA120
2018/11/22 14:00:21 [debug] 16673#0: *7 free: 00000000011C9F10, unused: 128
2018/11/22 14:00:21 [debug] 16673#0: timer delta: 0
2018/11/22 14:00:21 [debug] 16673#0: worker cycle
2018/11/22 14:00:21 [debug] 16673#0: epoll timer: 20077

=======

When I am sending 1MB file:

=======
2018/11/22 14:01:56 [debug] 16673#0: epoll: fd:13 ev:0001
d:00007F4A7DB21010
2018/11/22 14:01:56 [debug] 16673#0: accept on 0.0.0.0:8081, ready: 1
2018/11/22 14:01:56 [debug] 16673#0: posix_memalign: 00000000011A0150:512
@16
2018/11/22 14:01:56 [debug] 16673#0: *8 accept: 127.0.0.1:35438 fd:3
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer add: 3: 60000:56131622
2018/11/22 14:01:56 [debug] 16673#0: *8 reusable connection: 1
2018/11/22 14:01:56 [debug] 16673#0: *8 epoll add event: fd:3 op:1
ev:80002001
2018/11/22 14:01:56 [debug] 16673#0: accept() not ready (11: Resource
temporarily unavailable)
2018/11/22 14:01:56 [debug] 16673#0: timer delta: 74359
2018/11/22 14:01:56 [debug] 16673#0: worker cycle
2018/11/22 14:01:56 [debug] 16673#0: epoll timer: 60000
2018/11/22 14:01:56 [debug] 16673#0: epoll: fd:3 ev:0001 d:00007F4A7DB211F0
2018/11/22 14:01:56 [debug] 16673#0: *8 http wait request handler
2018/11/22 14:01:56 [debug] 16673#0: *8 malloc: 00000000011C9F10:1024
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: eof:0, avail:1
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: fd:3 224 of 1024
2018/11/22 14:01:56 [debug] 16673#0: *8 reusable connection: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 posix_memalign:
00000000011D2AE0:4096 @16
2018/11/22 14:01:56 [debug] 16673#0: *8 http process request line
2018/11/22 14:01:56 [debug] 16673#0: *8 http request line: "PUT
/1/file_2G.txt HTTP/1.1"
2018/11/22 14:01:56 [debug] 16673#0: *8 http uri: "/1/file_2G.txt"
2018/11/22 14:01:56 [debug] 16673#0: *8 http args: ""
2018/11/22 14:01:56 [debug] 16673#0: *8 http exten: "txt"
2018/11/22 14:01:56 [debug] 16673#0: *8 posix_memalign:
00000000011AF4A0:4096 @16
2018/11/22 14:01:56 [debug] 16673#0: *8 http process request header line
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "Host: 127.0.0.1:8081"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "User-Agent:
curl/7.47.0"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "Accept: */*"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "Content-Length:
1048804"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "Expect: 100-continue"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header: "Content-Type:
multipart/form-data; boundary=------------------------2034d95ad2250138"
2018/11/22 14:01:56 [debug] 16673#0: *8 http header done
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer del: 3: 56131622
2018/11/22 14:01:56 [debug] 16673#0: *8 rewrite phase: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 test location: "/"
2018/11/22 14:01:56 [debug] 16673#0: *8 using configuration "/"
2018/11/22 14:01:56 [debug] 16673#0: *8 http cl:1048804 max:5368709120
2018/11/22 14:01:56 [debug] 16673#0: *8 rewrite phase: 2
2018/11/22 14:01:56 [debug] 16673#0: *8 http script value: "1"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script set $cors
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var: "PUT"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script value: "OPTIONS"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script equal
2018/11/22 14:01:56 [debug] 16673#0: *8 http script equal: no
2018/11/22 14:01:56 [debug] 16673#0: *8 http script if
2018/11/22 14:01:56 [debug] 16673#0: *8 http script if: false
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var: "1"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script value: "1"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script equal
2018/11/22 14:01:56 [debug] 16673#0: *8 http script if
2018/11/22 14:01:56 [debug] 16673#0: *8 http script complex value
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var: "/1/file_2G.txt"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script copy: "?"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script set $v3io_key
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var
2018/11/22 14:01:56 [debug] 16673#0: *8 http script var: "1"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script value: "1o"
2018/11/22 14:01:56 [debug] 16673#0: *8 http script equal
2018/11/22 14:01:56 [debug] 16673#0: *8 http script equal: no
2018/11/22 14:01:56 [debug] 16673#0: *8 http script if
2018/11/22 14:01:56 [debug] 16673#0: *8 http script if: false
2018/11/22 14:01:56 [debug] 16673#0: *8 post rewrite phase: 3
2018/11/22 14:01:56 [debug] 16673#0: *8 generic phase: 4
2018/11/22 14:01:56 [debug] 16673#0: *8 generic phase: 5
2018/11/22 14:01:56 [debug] 16673#0: *8 access phase: 6
2018/11/22 14:01:56 [debug] 16673#0: *8 access phase: 7
2018/11/22 14:01:56 [debug] 16673#0: *8 post access phase: 8
2018/11/22 14:01:56 [debug] 16673#0: *8 generic phase: 9
2018/11/22 14:01:56 [debug] 16673#0: *8 generic phase: 10
2018/11/22 14:01:56 [debug] 16673#0: *8 ngx_v3io_test: req:
00000000011D2B30
2018/11/22 14:01:56 [debug] 16673#0: *8 send 100 Continue
2018/11/22 14:01:56 [debug] 16673#0: *8 send: fd:3 25 of 25
2018/11/22 14:01:56 [debug] 16673#0: *8 http request body content length
filter
2018/11/22 14:01:56 [debug] 16673#0: *8 malloc: 000000000121C990:1048804
2018/11/22 14:01:56 [debug] 16673#0: *8 http read client request body
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: eof:0, avail:0
2018/11/22 14:01:56 [debug] 16673#0: *8 http client request body recv -2
2018/11/22 14:01:56 [debug] 16673#0: *8 http client request body rest
1048804
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer add: 3: 60000:56131622
2018/11/22 14:01:56 [info] 16673#0: *8 ngx_v3io_test req: 00000000011D2B30,
read_client_request_body, ngx_ret: -2 
, client: 127.0.0.1, server: localhost, request: "PUT /1/file_2G.txt
HTTP/1.1", host: "127.0.0.1:8081"
2018/11/22 14:01:56 [debug] 16673#0: *8 http finalize request: -2,
"/1/file_2G.txt?" a:1, c:1
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer del: 3: 56131622
2018/11/22 14:01:56 [debug] 16673#0: *8 set http keepalive handler
2018/11/22 14:01:56 [debug] 16673#0: *8 http close request
2018/11/22 14:01:56 [debug] 16673#0: *8 http log handler
2018/11/22 14:01:56 [debug] 16673#0: *8 free: 000000000121C990
2018/11/22 14:01:56 [debug] 16673#0: *8 free: 00000000011D2AE0, unused: 155
2018/11/22 14:01:56 [debug] 16673#0: *8 free: 00000000011AF4A0, unused:
3104
2018/11/22 14:01:56 [debug] 16673#0: *8 free: 00000000011C9F10
2018/11/22 14:01:56 [debug] 16673#0: *8 hc free: 0000000000000000
2018/11/22 14:01:56 [debug] 16673#0: *8 hc busy: 0000000000000000 0
2018/11/22 14:01:56 [debug] 16673#0: *8 tcp_nodelay
2018/11/22 14:01:56 [debug] 16673#0: *8 reusable connection: 1
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer add: 3: 65000:56136622
2018/11/22 14:01:56 [debug] 16673#0: timer delta: 0
2018/11/22 14:01:56 [debug] 16673#0: worker cycle
2018/11/22 14:01:56 [debug] 16673#0: epoll timer: 65000
2018/11/22 14:01:56 [debug] 16673#0: epoll: fd:3 ev:0001 d:00007F4A7DB211F0
2018/11/22 14:01:56 [debug] 16673#0: *8 http keepalive handler
2018/11/22 14:01:56 [debug] 16673#0: *8 malloc: 00000000011C9F10:1024
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: eof:0, avail:1
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: fd:3 1024 of 1024
2018/11/22 14:01:56 [debug] 16673#0: *8 reusable connection: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 posix_memalign:
00000000011D2AE0:4096 @16
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer del: 3: 56136622
2018/11/22 14:01:56 [debug] 16673#0: *8 http process request line
2018/11/22 14:01:56 [info] 16673#0: *8 client sent invalid method while
reading client request line, client: 127.0.0.1, server: localhost, request:
"--------------------------2034d95ad2250138"
2018/11/22 14:01:56 [debug] 16673#0: *8 http finalize request: 400, "?" a:1,
c:1
2018/11/22 14:01:56 [debug] 16673#0: *8 http special response: 400, "?"
2018/11/22 14:01:56 [debug] 16673#0: *8 http set discard body
2018/11/22 14:01:56 [debug] 16673#0: *8 HTTP/1.1 400 Bad Request
Server: nginx/1.15.6
Date: Thu, 22 Nov 2018 12:01:56 GMT
Content-Type: text/html
Content-Length: 157
Connection: close

2018/11/22 14:01:56 [debug] 16673#0: *8 write new buf t:1 f:0
00000000011D3810, pos 00000000011D3810, size: 152 file: 0, size: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 http write filter: l:0 f:0 s:152
2018/11/22 14:01:56 [debug] 16673#0: *8 http output filter "?"
2018/11/22 14:01:56 [debug] 16673#0: *8 http copy filter: "?"
2018/11/22 14:01:56 [debug] 16673#0: *8 http postpone filter "?"
00000000011D39E0
2018/11/22 14:01:56 [debug] 16673#0: *8 write old buf t:1 f:0
00000000011D3810, pos 00000000011D3810, size: 152 file: 0, size: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 write new buf t:0 f:0
0000000000000000, pos 000000000072DBC0, size: 104 file: 0, size: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 write new buf t:0 f:0
0000000000000000, pos 000000000072D6A0, size: 53 file: 0, size: 0
2018/11/22 14:01:56 [debug] 16673#0: *8 http write filter: l:1 f:0 s:309
2018/11/22 14:01:56 [debug] 16673#0: *8 http write filter limit 0
2018/11/22 14:01:56 [debug] 16673#0: *8 writev: 309 of 309
2018/11/22 14:01:56 [debug] 16673#0: *8 http write filter 0000000000000000
2018/11/22 14:01:56 [debug] 16673#0: *8 http copy filter: 0 "?"
2018/11/22 14:01:56 [debug] 16673#0: *8 http finalize request: 0, "?" a:1,
c:1
2018/11/22 14:01:56 [debug] 16673#0: *8 event timer add: 3: 600000:56671622
2018/11/22 14:01:56 [debug] 16673#0: *8 http lingering close handler
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: eof:0, avail:1
2018/11/22 14:01:56 [debug] 16673#0: *8 recv: fd:3 4096 of 4096

=======

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,282068,282075#msg-282075



More information about the nginx mailing list