Skip to content

Nginx Improved response body filter, issue #56 might be fixed #67

Merged
merged 1 commit into from Apr 9, 2013

2 participants

@chaizhenhua

No description provided.

@brenosilva

Hello chaizhenhua,

NGX_HTTP_SSI_BUFFERED means we will process the response time to time without need complete buffered ?

Thanks

@chaizhenhua

I think this flags tells nginx not to process the write eventimmediately(when fd is ready) . because there is nothing to send to client before all response body was processed, so we should delay the fd event.

@brenosilva brenosilva merged commit 1919c3a into SpiderLabs:remotes/trunk Apr 9, 2013
@brenosilva

Applied Thanks!

@brenosilva

Hello man,

Looks like we still have the CPU issue. I inserted some debug messages and many requests are returning in ngx_http_modsecurity_body_filter() here:

if (in == NULL) {
    /* waiting for more buffer */
    r->buffered |= NGX_HTTP_SSI_BUFFERED;
    return NGX_AGAIN;
}

You can trigger is sending ab -n 1000 -c 10 http://your_ip/index.html (a html page with images).

Could this be the cause of 100% CPU issue ?

Thanks

Breno

Also try set worker_process 1

Looks like if you insert in the beginning of ngx_http_modsecurity_body_filter():

return ngx_http_next_body_filter(r, in);

The problem disappear. So looks like an issue in ngx_http_modsecurity_body_filter

I inserted return NGX_AGAIN;

after if( in == NULL) { } return NGX_AGAIN; and the problem disappeared too. So looks like in == NULL is not the problem

Could be the move_chain_to_brigade() ?

Humm yes.. looks like the issue is calling move_chain_to_brigade()

I changed from:

rc = move_chain_to_brigade(in, ctx->brigade, r->pool, 0);

to

rc = move_chain_to_brigade(in, ctx->brigade, r->pool, 1);

Any idea how we can fix it ?

When the issue is triggered... the modsecurity debug.log stop here:

[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Transformation completed in 1 usec.
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Executing operator "rx" with param "index" against REQUEST_URI.
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][9] Target value: "/catalog/index.html"
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Operator completed in 10 usec.
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][2] Warning. Pattern match "index" at REQUEST_URI. [file "/usr/local/nginx/conf/modsecurity.conf"] [line "236"] [id "10"]
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Rule returned 1.
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][9] Match -> mode NEXT_RULE.
[11/May/2013:10:36:54 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Hook insert_filter: Adding output filter (r a1239c0).

So ... it does not follow the execution like a normal transaction:

[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Transformation completed in 1 usec.
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Executing operator "rx" with param "index" against REQUEST_URI.
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][9] Target value: "/catalog/index.html"
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Operator completed in 7 usec.
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][2] Warning. Pattern match "index" at REQUEST_URI. [file "/usr/local/nginx/conf/modsecurity.conf"] [line "236"] [id "10"]
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Rule returned 1.
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][9] Match -> mode NEXT_RULE.
[11/May/2013:10:35:07 --0700] [/sid#a04f618][rid#a1239c0][/catalog/index.html][4] Hook insert_filter: Adding output filter (r a1239c0).
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Receiving output (f a0a8430, r a0a77c0).
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][4] Starting phase RESPONSE_HEADERS.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] This phase consists of 0 rule(s).
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Content Injection: Not enabled.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 3773 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 4096 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 3594 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type NGINX contains 0 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][9] Output filter: Bucket type EOS contains 0 bytes.
[11/May/2013:10:35:08 --0700] [/sid#a04f618][rid#a0a77c0][/catalog/index.html][4] Output filter: Completed receiving response body (buffered full - 31943 bytes).

It is entering in this condition:

if (rc != NGX_OK) {
r->buffered |= NGX_HTTP_SSI_BUFFERED;
return rc;
}

Then in modsecurity debug.log it stay here:

Hook insert_filter: Adding output filter (r 95aea10).

And cpu 100%

Any idea ?

This ( Resource temporarily unavailable) is strange ..

2013/05/11 11:30:09 [debug] 5976#0: epoll: fd:24 ev:0005 d:094F1D00
2013/05/11 11:30:09 [debug] 5976#0: *14 http upstream request: "/catalog/index2.html?"
2013/05/11 11:30:09 [debug] 5976#0: *14 http upstream process upstream
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe read upstream: 1
2013/05/11 11:30:09 [debug] 5976#0: *14 readv: 1:952
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe recv chain: 952
2013/05/11 11:30:09 [debug] 5976#0: *14 input buf #1
2013/05/11 11:30:09 [debug] 5976#0: *14 malloc: 095F7D20:4096
2013/05/11 11:30:09 [debug] 5976#0: *14 readv: 1:4096
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe recv chain: 1944
2013/05/11 11:30:09 [debug] 5976#0: *14 readv: 1:2152
2013/05/11 11:30:09 [debug] 5976#0: *14 readv() not ready (11: Resource temporarily unavailable)
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe recv chain: -2
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe buf busy s:1 t:1 f:0 095F4D08, pos 095F4D08, size: 4096 file: 0, size: 0
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe buf in s:1 t:1 f:0 095F4D08, pos 095F4D08, size: 4096 file: 0, size: 0
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe buf free s:0 t:1 f:0 095F7D20, pos 095F7D20, size: 1944 file: 0, size: 0
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe length: 48870
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe write downstream: 1
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe write busy: 4096
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe write buf ls:1 095F4D08 4096
2013/05/11 11:30:09 [debug] 5976#0: *14 pipe write: out:0957BD70, f:0
2013/05/11 11:30:09 [debug] 5976#0: *14 http output filter "/catalog/index2.html?"
2013/05/11 11:30:09 [debug] 5976#0: *14 http copy filter: "/catalog/index2.html?"
2013/05/11 11:30:09 [debug] 5976#0: *14 modSecurity: body filter 1
2013/05/11 11:30:09 [debug] 5976#0: *14 modSecurity: body filter 3
2013/05/11 11:30:09 [debug] 5976#0: *14 modSecurity: body filter 5
2013/05/11 11:30:09 [debug] 5976#0: *14 http copy filter: -2 "/catalog/index2.html?"

gdb -p 8645

ngx_event_pipe_write_to_downstream (p=0x9bbc720, do_write=0) at src/event/ngx_event_pipe.c:551
551 if (cl->buf->recycled) {
(gdb)

@brenosilva i think i know the reasion:

  • some nginx filters or modules will reuse the ngx_buf_t (see ngx_chain_update_chains), and some module has a buffer limit.
  • in modsecurity_body_filter, we store all ngx_buf_t in ctx->brigade. the bufs will not flush out until last buf. if there is not enough buffer for the other module, the module will always to call modsecurity_body_filter with NULL chain.

maybe this is the key problem. i will add a patch to fix it.

Looks like remove the

    ngx_free_chain(pool, cl);

call from the move_chain_to_brigade() function fix it.
Looks OK for me until now. What do you think

Hello man,

The CPU issue goes away removing the ngx_free_chain() . However sometimes the output filter does not load the entire buffer, sometimes the "adding output filter" task is slow.

Maybe your fix could fix it ?

Thanks

Maybe we need to change ??

    rc = move_chain_to_brigade(in, ctx->brigade, r->pool, 0);

    if (rc != NGX_OK)  {
            r->buffered |= NGX_HTTP_SSI_BUFFERED;
            return ngx_http_next_body_filter(r, in);   ---> instead of return rc;

    }

Looks like return ngx_http_next_body_filter(r, in); is making modsecurity read all buckets. However i'm seeing memory leaks in RESPONSE_BODY variable.

What do you think ?

@brenosilva

Looks like return ngx_http_next_body_filter(r, in); is making modsecurity read all buckets. However i'm seeing memory leaks in RESPONSE_BODY variable.

What do you think ?

Hello
Return ngx_http next body filter will send the buffer out. What's the memory leak problem?

Looks like remove the

   ngx_free_chain(pool, cl);

call from the move_chain_to_brigade() function fix it.
Looks OK for me until now. What do you think

I think we have to copy buffer from nginx to modsecurity and then clear the buffer so that nginx can recycle the buffer

Right. Can you send a patch ?

The memory leak i'm seeing:

Response 1:

[12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Transformation completed in 1 usec.
[12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Executing operator "rx" with param "footer_eof" against RESPONSE_BODY.
[12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][9] Target value: "e Banho

  • \n class="infoBoxHeading">\n \n \n\n\n \n \n \n
    \n\n \n <td height="14" cl
    [12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Operator completed in 73 usec.
    [12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][2] Warning. Pattern match "footer_eof" at RESPONSE_BODY. [file "/usr/local/nginx/conf/modsecurity.conf"] [line "229"] [id "115"]
    [12/May/2013:21:06:50 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Rule returned 1.

    Response 2:

    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][5] Rule 94de590: SecRule "RESPONSE_BODY" "@rx footer_eof" "phase:4,log,auditlog,pass,id:115"
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Transformation completed in 1 usec.
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Executing operator "rx" with param "footer_eof" against RESPONSE_BODY.
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][9] Target value: "\x00\x00\x00\x00\x19\x02\x00\x00\xe8\x05\x7f\x00\xe8\x05\x7f\x00X6L\tX6L\t\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Operator completed in 46 usec.
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][2] Warning. Pattern match "footer_eof" at RESPONSE_BODY. [file "/usr/local/nginx/conf/modsecurity.conf"] [line "229"] [id "115"]
    [12/May/2013:21:06:51 --0700] [/sid#94ce618][rid#94d6638][/catalog/index2.html][4] Rule returned 1.
    

    Any idea to fix it ?

  • Copying it to github was not very good.. but it think you can see.
    Sending the same request i'm getting very different data into response body. Target starts with wrong data too.

    For example in Response 1 ... Target value: "e Banho
    it is not the start of index2.html. So there is something wrong copying data to brigade ?

    Thanks

    @brenosilva I will send the patch as soon as possiable. i haven't finish the patch yet.

    Sounds good man.

    I still didn't detect the reason of memory leaks.. do you have any idea ?

    I'm trying to create a new ngx_buf_t to send to brigade instead of chain->buf in move_chain_to_brigade.. to see if memory leaks disappears:

                buf = ngx_palloc(pool, sizeof(ngx_buf_t));
                if (buf == NULL) {
                        return NGX_ERROR;
                }
    
                len = chain->buf->end - chain->buf->start;
                buf->start = ngx_palloc(pool, len);
                ngx_memcpy(buf->start, chain->buf->start, len);
    
                buf->pos = buf->last = buf->start;
                buf->end = buf->start + len;
                buf->last_buf = chain->buf->last_buf;
                buf->last_in_chain = chain->buf->last_in_chain;
    
                e = ngx_buf_to_apr_bucket(buf, bb->p, bb->bucket_alloc);
                if (e == NULL) {
                        return NGX_ERROR;
                }
    

    However i'm seeing in the modsecurity log:

    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type NGINX contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][9] Output filter: Bucket type EOS contains 0 bytes.
    [12/May/2013:23:26:17 --0700] [/sid#9af2618][rid#9b3b780][/catalog/index2.html][4] Output filter: Completed receiving response body (buffered full - 0 bytes).

    I think i 'm missing some detail
    Any idea ?

    buf->pos = buf->last = buf->start; this line should be buf->last = buf->end;

    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Something went wrong with that request. Please try again.