srcache_fetch stucked while processing some requests

[akharc]

Hello, i get very strange trouble with directive "srcache_fetch" and some kind of SOAP requests.

When i send some POST requests from SOAP UI or another app with User-Agent like "HTTP/Apache (java)" to Openresty, some requests processed well: sending GET request to memc_pass, then store cache, go to proxy_pass and send responds to client.
But other requests are stuck after response from memcached server and wait till client closes connection by it's own timeout (that can be much more than memc_read timeout).

BTW, when i send SOAP request with same body by CURL, i can't reproduce this problem - all requests processed well.

openresty version: 1.11.2.5
nginx version: nginx/1.10.2

This is depersonalized part of my nginx.conf^

	location = /memc {
        internal;
        memc_connect_timeout 100ms;
        memc_send_timeout 100ms;
        memc_read_timeout 100ms;
        memc_ignore_client_abort off;

        set $memc_key $query_string;
        set $memc_exptime 3600;


        memc_pass memcached-ip-addr:memcached-port;
    }

   location /memc-stats {
       add_header Content-Type text/plain;
       set $memc_cmd stats;
       memc_pass memcached-ip-addr:memcached-port;
   }


    location /location-name  {

        access_log logs/access.log main;
        set $responsebody "0";
        set $reqbody "0";
        set $key "0";

        lua_need_request_body on;
        client_max_body_size 50M;

        rewrite_by_lua '

        local method = ngx.var.request_method
        if method == "POST" then
            ngx.req.read_body()
            local data = ngx.req.get_body_data()
            ngx.var.reqbody = data
        elseif method == "GET" then
            local data = ngx.var.query_string
            ngx.var.reqbody = data
        end
        ngx.var.key = ngx.md5(ngx.var.reqbody)
        return ngx.var.key
		';

        srcache_request_cache_control off;
        srcache_response_cache_control off;
        srcache_ignore_content_encoding on;
        srcache_store_private on;

        srcache_fetch GET /memc $key;
        srcache_store_statuses 200 201 301 302;


        srcache_store PUT /memc $key;
        srcache_methods GET POST;


        proxy_pass http://proxy-pass-addr;

 
        proxy_buffering         off;
        proxy_connect_timeout 5s;
        proxy_send_timeout 5s;
        proxy_read_timeout 30s;

    }

[kapouer]

Can it be related to the memcached backend ? Sometimes i see memcached takes too long to reply (typically when server memory usage is high).

[akharc]

I dont think so, this problem reproduced on different memcaced backends (including localhost).

[akharc]

Get same behaviour with redis

[agentzh]

@akharc You should use proxy_buffering on. It's known that disabling the proxy buffering can lead to issues in subrequests.

[akharc]

I've turn proxy_buffering on, but still get the same issues.

[akharc]

Can there be other reasons for this problem?

[agentzh]

@akharc You should enable the nginx debug logs to find more detailed info, see

https://github.com/openresty/srcache-nginx-module/#trouble-shooting

[akharc]

@agentzh
Order of playback:

1. start service
2. send request
3. get "Read timed out" exception
4. stop service

nginx debug log here:
error.log

[agentzh]

@akharc You failed to enable the nginx debugging logs. None of your messages have the [debug] tag (or the debug level).

[akharc]

Debug-level log here:
error-2.log

[agentzh]

@akharc The offending line is this:

2017/10/12 20:10:22 [debug] 3186#3186: *1 http request empty handler

To put it into the context:

2017/10/12 20:10:22 [debug] 3186#3186: *1 http finalize request: 404, "/memc?2369cff394f0fd182fde58e04c8c855f" a:1, c:2
2017/10/12 20:10:22 [debug] 3186#3186: *1 http wake parent request: "/XXXXXXX.asmx?"
2017/10/12 20:10:22 [debug] 3186#3186: *1 http posted request: "/XXXXXXX.asmx?"
2017/10/12 20:10:22 [debug] 3186#3186: *1 http request empty handler

I'm not sure who installed that "request empty handler". You need to trace it down with tools like gdb on your side.

BTW, one obvious issue in your nginx.conf snippet is the following line:

proxy_buffering off;

You should really turn it on. Otherwise you would hang on the subrequests.

Another obvious thing is that you should really disable the accept_mutex thing since it would only hurt the performance a lot under load (and would also mess up your debug logs).