Hang after NGX_AGAIN

[tguyard.wordpress.com]

I've been trying to develop a filter module.

In some rare cases, ngx_http_write_filter return NGX_AGAIN (Mostly when using the limit_rate feature). My filter then just return NGX_AGAIN and wait to be called again later.
This works well most of the time.

The error occurs when my filter has finished to send all the data (buf->last_buf = 1;), and gets a NGX_AGAIN from the next filter. I then return NGX_AGAIN, but NEVER GET CALLED again.

Maybe I did something wrong, but when trying to fix the problem, I found something that seems weird in the source code:
ngx_http_finalize_request does not always reset the c->write->delayed value.

After adding c->write->delayed = 0; in ngx_http_finalize_request on line 2428, the error was fixed. (And everything seems to work ok)

The nginx I use come from the Ubuntu14/04 repository.

[tguyard.wordpress.com]

The module I'm currently developping

[Maxim Dounin]

The ngx_http_finalize_request() is not expected to reset c->write->delayed unless it's removing the timer. This flag indicates that processing of a request was delayed, and an appropriate timer was set. Processing of a request will be continued once the timer expires.

What you describe sounds like a problem in your filter. If you think the problem is in nginx - please try reducing your code to a bare minimum which demonstrates the problem, and provide corresponding debug logs. The code you've posted unfortunately is too complicated to easily analyse.

[tguyard.wordpress.com]

Thank you for your reply.
I will dig a little deeper and try to find exactly what is going on.

[tguyard.wordpress.com]

I've been able to reproduce the bug without my custom filter.

I'm using

• x-accel-redirect from an fcgi (php) upstream.
• x-accel-limit-rate = 2560000
• a post_action (that can take some time)
• keepalive is activated

(I will try to reproduce the bug without php)

What happens
When doing 2 requests on the same connection (keepalive), the first one is done correctly, the second one hangs, with no response.

There is no issue without keepalive (keepalive_timeout 0;).
There is no issue without the post_action.
There is no issue without the x-accel-limit-rate.
There is no issue with a very small value of x-accel-limit-rate.

What I gather so far

• At the end of the first request, due to the x-accel-limit-rate, c->write->delayed = 1 and a timer is launched (I observed a very short timer ~7ms).
• When doing ngx_http_finalize_request(), the timer is not canceled, because there is a post_action to do first.
• During the post_action request, the timer expire, c->write->timer_set is set to 0 but c->write->delayed STAYS AT 1.
• Then the post_action finishes and ngx_http_finalize_request() is called again. timer_set being = 0, the delayed value is not reset to 0.
• The second request get processed with a delayed value of 1, then wait for a timer event that will never be fired.

[tguyard.wordpress.com]

I was able to reproduce the bug with these parameters:

nginx.conf:
(you need the echo module)

worker_processes 4;
pid /run/nginx.pid;
daemon off;

events {
    worker_connections 1024;
}

http {
    sendfile on;
    keepalive_timeout 65;
    root /tmp/;
    
    server {
        listen 8888;

        location / {
            try_files /testfile =404;
            limit_rate 2560000;
            post_action @postaction;
        }

        location @postaction {
            internal;
            echo_sleep 1;
            try_files /testfile =404;
        }
    }
}

the /tmp/testfile I used was a random file of at least 2321 Bytes (no bug with smaller files)

> ll /tmp/testfile 
-rw-rw-r-- 1 thomas thomas 2321 Jul 30 15:55 /tmp/testfile

curl command:

curl 'http://localhost:8888' -o /dev/null 'http://localhost:8888' -o /dev/null --dump-header -

[Maxim Dounin]

Thanks for the details. What you describe sounds like a bug in post_action. Not really a surprise, as post_action was always considered to be a dirty hack and it is not documented on purpose. Do you see any problems when not using post_action?

[tguyard.wordpress.com]

There is no problem without post_action.

[tguyard.wordpress.com]

This patch fix the bug for me :
patch -p 1 src/http/ngx_http_request.c < ngx_http_request.c.patch

with ngx_http_request.c.patch :

2416,2419d2415
<     if (ngx_http_post_action(r) == NGX_OK) {
<         return;
<     }
< 
2426a2423,2426
>     }
> 
>     if (ngx_http_post_action(r) == NGX_OK) {
>         return;

[Maxim Dounin]

See also #1228.

[Maxim Dounin <mdounin@…>]

In 6961:903fb1ddc07f/nginx:

Moved handling of wev->delayed to the connection event handler.

With post_action or subrequests, it is possible that the timer set for
wev->delayed will expire while the active subrequest write event handler
is not ready to handle this. This results in request hangs as observed
with limit_rate / sendfile_max_chunk and post_action (ticket #776) or
subrequests (ticket #1228).

Moving the handling to the connection event handler fixes the hangs observed,
and also slightly simplifies the code.

[Maxim Dounin]

Fix committed.