other module's header_filter called 2 times from subrequest

antony.dovgal · 2015-03-04T22:32:03+00:00

Hi Guys,Can you share any link to a working example of the resolver for ELBs with lua-resty-resolver or lua-upstream-nginx-module? It would be really helpful...

other module's header_filter called 2 times from subrequest

antony.dovgal

Hello all.

We're currently trying to use nginx Lua module in conjunction with our own module and we're seeing a strange behaviour:
our module's header_filter handler is called twice from Lua's subrequest context.
Our module does several operations with the image depending on the parameters passed (resize, crop, converting etc).

I've figured out that Lua module returns data in chunks (looks like there are always two chunks: the actual data and the 'last buffer' chunk)
and our module (seemingly) correctly consumes it, but for some reason Lua module also calls our header_filter two times, so as the result the call sequence looks like this:

ngx_http_lua_subrequest(), ngx_http_jpegresize_header_filter(), ngx_http_jpegresize_body_filter() and then *again* ngx_http_jpegresize_header_filter(), ngx_http_jpegresize_body_filter().


As far as I understand, it's body_filter that should be called several times in such cases, not header_filter.
Am I doing something wrong or is it a Lua module problem?



Here's a sample config:
--------------
location ~ /backend/ {
    root /;
    try_files /local/nginx/html/test.jpg = 404;
}

location ~ /get/ {
    content_by_lua '
        local res = ngx.location.capture("/backend/")
        for k, v in pairs(res.header) do
            ngx.header[k] = v
        end
        ngx.status = res.status
        ngx.print(res.body)
    ';
}
--------------

bt for the first header_filter call:
#0  ngx_http_jpegresize_header_filter (r=0x118a060) at ../ngx_http_jpegresize_module.git/ngx_http_jpegresize_filter_module.c:277
#1  0x00000000005860a2 in ngx_http_lua_capture_header_filter (r=0x118a060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_capturefilter.c:108
#2  0x00000000004fc1a8 in ngx_http_not_modified_header_filter (r=0x118a060) at src/http/modules/ngx_http_not_modified_filter_module.c:108
#3  0x00000000004c50b0 in ngx_http_send_header (r=0x118a060) at src/http/ngx_http_core_module.c:1956
#4  0x000000000057c7d5 in ngx_http_lua_send_header_if_needed (r=0x118a060, ctx=0x11e28c0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:429
#5  0x000000000057c8f9 in ngx_http_lua_send_chain_link (r=0x118a060, ctx=0x11e28c0, in=0x11e4bf0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:469
#6  0x0000000000569602 in ngx_http_lua_ngx_echo (L=0x4000bdd0, newline=0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:224
#7  0x0000000000568ef8 in ngx_http_lua_ngx_print (L=0x4000bdd0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:25
#8  0x0000000000b94917 in lj_BC_FUNCC ()
#9  0x000000000057d962 in ngx_http_lua_run_thread (L=0x40000378, r=0x118a060, ctx=0x11e28c0, nrets=1)
    at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:1000
#10 0x0000000000564041 in ngx_http_lua_subrequest_resume (r=0x118a060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_subrequest.c:1591

bt for the second time:
#0  ngx_http_jpegresize_header_filter (r=0x118a060) at ../ngx_http_jpegresize_module.git/ngx_http_jpegresize_filter_module.c:277
#1  0x00000000005860a2 in ngx_http_lua_capture_header_filter (r=0x118a060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_capturefilter.c:108
#2  0x00000000004fc1a8 in ngx_http_not_modified_header_filter (r=0x118a060) at src/http/modules/ngx_http_not_modified_filter_module.c:108
#3  0x00000000004c50b0 in ngx_http_send_header (r=0x118a060) at src/http/ngx_http_core_module.c:1956
#4  0x000000000057c7d5 in ngx_http_lua_send_header_if_needed (r=0x118a060, ctx=0x11e28c0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:429
#5  0x000000000057c8f9 in ngx_http_lua_send_chain_link (r=0x118a060, ctx=0x11e28c0, in=0x0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:469
#6  0x000000000057e8e5 in ngx_http_lua_run_thread (L=0x40000378, r=0x118a060, ctx=0x11e28c0, nrets=1)
    at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:1468
#7  0x0000000000564041 in ngx_http_lua_subrequest_resume (r=0x118a060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_subrequest.c:1591

--
Wbr,
Antony Dovgal

agentzh

Hello!

On Wed, Mar 4, 2015 at 6:31 AM, Antony Dovgal wrote:
> but for some reason Lua
> module also calls our header_filter two times, so as the result the call
> sequence looks like this:
>
> ngx_http_lua_subrequest(), ngx_http_jpegresize_header_filter(),
> ngx_http_jpegresize_body_filter() and then *again*
> ngx_http_jpegresize_header_filter(), ngx_http_jpegresize_body_filter().
>

Please note that a subrequest and its parent request are separate
"requests" so both of them will have their own response header and
body sending processes.

Your output filter module should take subrequests into account. Maybe
in your case you should only enable your module's header filter in
just one of the two locations served by your main request and your
subrequest, respectively?

Regards,
-agentzh

antony.dovgal

On 03/04/2015 11:15 PM, Yichun Zhang (agentzh) wrote:
> Hello!
>
> On Wed, Mar 4, 2015 at 6:31 AM, Antony Dovgal wrote:
>> but for some reason Lua module also calls our header_filter two
>> times, so as the result the call sequence looks like this:
>>
>> ngx_http_lua_subrequest(), ngx_http_jpegresize_header_filter(),
>> ngx_http_jpegresize_body_filter() and then *again*
>> ngx_http_jpegresize_header_filter(),
>> ngx_http_jpegresize_body_filter().
>>
>
> Please note that a subrequest and its parent request are separate
> "requests" so both of them will have their own response header and
> body sending processes.

Is it intended that they are separate, but still represented by the same request pointer?

> Maybe in your case you should only enable your module's header filter
> in just one of the two locations served by your main request and your
> subrequest, respectively? Regards, -agentzh

Maybe.
Unfortunately, I don't see any way to do it - it's the same request, so the location config is the same, too.

Here's an excerpt from GDB trace:
ngx_http_lua_subrequest (r=0x118a060 <--- NB
ngx_http_jpegresize_header_filter (r=0x118a060
ngx_http_jpegresize_body_filter (r=0x118a060
ngx_http_jpegresize_header_filter (r=0x118a060
ngx_http_jpegresize_body_filter (r=0x118a060

--
Wbr,
Antony Dovgal

agentzh

Hello!

On Thu, Mar 5, 2015 at 1:26 AM, Antony Dovgal wrote:
> Is it intended that they are separate, but still represented by the same
> request pointer?
>

They're separate and different ngx_http_request_t structs and pointers.

> Unfortunately, I don't see any way to do it - it's the same request, so the
> location config is the same, too.
>
> Here's an excerpt from GDB trace:
> ngx_http_lua_subrequest (r=0x118a060               <--- NB
> ngx_http_jpegresize_header_filter (r=0x118a060
> ngx_http_jpegresize_body_filter (r=0x118a060
> ngx_http_jpegresize_header_filter (r=0x118a060
> ngx_http_jpegresize_body_filter (r=0x118a060

antony.dovgal

Hello Yichin,

On 03/05/2015 11:15 PM, Yichun Zhang (agentzh) wrote:

Hello!

> They're separate and different ngx_http_request_t structs and pointers.

Surely you can demonstrate it to me, right?

> Unfortunately, I don't see any way to do it - it's the same request, so the
> location config is the same, too.
>
> Here's an excerpt from GDB trace:
> ngx_http_lua_subrequest (r=0x118a060 <--- NB
> ngx_http_jpegresize_header_filter (r=0x118a060
> ngx_http_jpegresize_body_filter (r=0x118a060
> ngx_http_jpegresize_header_filter (r=0x118a060
> ngx_http_jpegresize_body_filter (r=0x118a060
>
> From this backtrace, I wonder how *your* header filter calls into *your* body filter in the first place

I'm sorry for not being clear enough, but I said this is only an excerpt.
No, header_filter doesn't call body_filter, it's the breakpoints that are triggered in exactly this sequence.
See my first email for a bit more detailed traces.

> and also how your body filter can in turn call into your header filter. This looks more like an issue in your own filter module to me.
> Maybe you should arm yourself with more basic nginx programming knowledge first :)

Ok, I've removed our custom module completely and added standard image_filter module instead.
And I can still reproduce the bug, see sample config and gdb traces below.

Note that there is no second image_body_filter call because image_filter resets its location context
on the second header_filter call (because it doesn't expect it to be called twice in the same request).

Apparently, its author also should go read a book and learn some basic nginx programming practices.


Sample config for image_filter:
-----------
location ~ /backend/ {
    root /;
    try_files /local/nginx/html/image.jpg = 404;
}

location ~ /get/ {
    image_filter resize 150 100; # yes, I want to get original image in Lua and then resize it
    image_filter rotate 90;          # so the filter has to be here, not in the section above
    content_by_lua '
        local res = ngx.location.capture("/backend/")
        for k, v in pairs(res.header) do
            ngx.header[k] = v
        end
        ngx.status = res.status
        ngx.print(res.body)
    ';
}
-----------

gdb traces (all during the same request to /get/):
1)
#0  ngx_http_image_header_filter (r=0xa69060) at src/http/modules/ngx_http_image_filter_module.c:214
#1  0x00000000004e26ef in ngx_http_userid_filter (r=0xa69060) at src/http/modules/ngx_http_userid_filter_module.c:209
#2  0x000000000051b7ae in ngx_http_cc_header_filter (r=0xa69060) at ../ngx_http_cc_module.git/ngx_http_cc_module.c:909
#3  0x00000000004ccfe9 in ngx_http_headers_filter (r=0xa69060) at src/http/modules/ngx_http_headers_filter_module.c:167
#4  0x00000000005558a5 in ngx_http_lua_capture_header_filter (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_capturefilter.c:108
#5  0x00000000004ce098 in ngx_http_not_modified_header_filter (r=0xa69060) at src/http/modules/ngx_http_not_modified_filter_module.c:108
#6  0x0000000000496fa0 in ngx_http_send_header (r=0xa69060) at src/http/ngx_http_core_module.c:1956
#7  0x000000000054bfd8 in ngx_http_lua_send_header_if_needed (r=0xa69060, ctx=0xac28d0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:429
#8  0x000000000054c0fc in ngx_http_lua_send_chain_link (r=0xa69060, ctx=0xac28d0, in=0xac4490) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:469
#9  0x0000000000538e05 in ngx_http_lua_ngx_echo (L=0xa6a5f0, newline=0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:224
#10 0x00000000005386fb in ngx_http_lua_ngx_print (L=0xa6a5f0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:25
#11 0x0000000000574718 in luaD_precall ()
#12 0x000000000057d407 in luaV_execute ()
#13 0x0000000000573ec8 in luaD_rawrunprotected ()
#14 0x0000000000574b8b in lua_resume ()
#15 0x000000000054d165 in ngx_http_lua_run_thread (L=0xae5a90, r=0xa69060, ctx=0xac28d0, nrets=1) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:1000
#16 0x0000000000533844 in ngx_http_lua_subrequest_resume (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_subrequest.c:1591
#17 0x000000000055344a in ngx_http_lua_content_wev_handler (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_contentby.c:131

2)
#0  ngx_http_image_body_filter (r=0xa69060, in=0xac4490) at src/http/modules/ngx_http_image_filter_module.c:287
#1  0x0000000000555974 in ngx_http_lua_capture_body_filter (r=0xa69060, in=0xac4490) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_capturefilter.c:132
#2  0x0000000000457d24 in ngx_output_chain (ctx=0xac4628, in=0xac4490) at src/core/ngx_output_chain.c:66
#3  0x00000000004aca8f in ngx_http_copy_filter (r=0xa69060, in=0xac4490) at src/http/ngx_http_copy_filter_module.c:143
#4  0x00000000004cc233 in ngx_http_range_body_filter (r=0xa69060, in=0xac4490) at src/http/modules/ngx_http_range_filter_module.c:594
#5  0x000000000049702a in ngx_http_output_filter (r=0xa69060, in=0xac4490) at src/http/ngx_http_core_module.c:1971
#6  0x000000000054c453 in ngx_http_lua_output_filter (r=0xa69060, in=0xac4490) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:588
#7  0x000000000054c361 in ngx_http_lua_send_chain_link (r=0xa69060, ctx=0xac28d0, in=0xac4490) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:543
#8  0x0000000000538e05 in ngx_http_lua_ngx_echo (L=0xa6a5f0, newline=0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:224
#9  0x00000000005386fb in ngx_http_lua_ngx_print (L=0xa6a5f0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_output.c:25
#10 0x0000000000574718 in luaD_precall ()
#11 0x000000000057d407 in luaV_execute ()
#12 0x0000000000573ec8 in luaD_rawrunprotected ()
#13 0x0000000000574b8b in lua_resume ()
#14 0x000000000054d165 in ngx_http_lua_run_thread (L=0xae5a90, r=0xa69060, ctx=0xac28d0, nrets=1) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:1000
#15 0x0000000000533844 in ngx_http_lua_subrequest_resume (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_subrequest.c:1591
#16 0x000000000055344a in ngx_http_lua_content_wev_handler (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_contentby.c:131

3)
#0  ngx_http_image_header_filter (r=0xa69060) at src/http/modules/ngx_http_image_filter_module.c:214
#1  0x00000000004e26ef in ngx_http_userid_filter (r=0xa69060) at src/http/modules/ngx_http_userid_filter_module.c:209
#2  0x000000000051b7ae in ngx_http_cc_header_filter (r=0xa69060) at ../ngx_http_cc_module.git/ngx_http_cc_module.c:909
#3  0x00000000004ccfe9 in ngx_http_headers_filter (r=0xa69060) at src/http/modules/ngx_http_headers_filter_module.c:167
#4  0x00000000005558a5 in ngx_http_lua_capture_header_filter (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_capturefilter.c:108
#5  0x00000000004ce098 in ngx_http_not_modified_header_filter (r=0xa69060) at src/http/modules/ngx_http_not_modified_filter_module.c:108
#6  0x0000000000496fa0 in ngx_http_send_header (r=0xa69060) at src/http/ngx_http_core_module.c:1956
#7  0x000000000054bfd8 in ngx_http_lua_send_header_if_needed (r=0xa69060, ctx=0xac28d0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:429
#8  0x000000000054c0fc in ngx_http_lua_send_chain_link (r=0xa69060, ctx=0xac28d0, in=0x0) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:469
#9  0x000000000054e0e8 in ngx_http_lua_run_thread (L=0xae5a90, r=0xa69060, ctx=0xac28d0, nrets=1) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_util.c:1468
#10 0x0000000000533844 in ngx_http_lua_subrequest_resume (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_subrequest.c:1591
#11 0x000000000055344a in ngx_http_lua_content_wev_handler (r=0xa69060) at ../lua-nginx-module-0.9.14/src/ngx_http_lua_contentby.c:131

--

Wbr,
Antony Dovgal
---
http://pinba.org - realtime profiling for PHP

agentzh

Hello!

On Fri, Mar 6, 2015 at 2:23 AM, Antony Dovgal wrote:
> Sample config for image_filter:
> -----------
> location ~ /backend/ {
>     root /;
>     try_files /local/nginx/html/image.jpg = 404;
> }
>
> location ~ /get/ {
>     image_filter resize 150 100; # yes, I want to get original image in Lua
> and then resize it
>     image_filter rotate 90;          # so the filter has to be here, not in
> the section above
>     content_by_lua '
[...]

OK, this minimal standalone example that I can run locally is what I
need. The ngx_http_image_filter_module is special in that its header
filter intercepts the header filter chain leaving the r->header_sent
flag unset, which confuses ngx_lua's output subsystem. I've just
committed a fix to ngx_lua's git repos:

    https://github.com/openresty/lua-nginx-module/commit/7c37b4bbd

Please try it out on your side.

Thanks for the test case!

Best regards,
-agentzh

antony.dovgal

On 03/07/2015 02:51 AM, Yichun Zhang (agentzh) wrote:

OK, this minimal standalone example that I can run locally is what I
need. The ngx_http_image_filter_module is special in that its header
filter intercepts the header filter chain leaving the r->header_sent
flag unset, which confuses ngx_lua's output subsystem. I've just
committed a fix to ngx_lua's git repos:

     https://github.com/openresty/lua-nginx-module/commit/7c37b4bbd

Please try it out on your side.

I can confirm that the patch does fix the problem.
Thanks a lot!

--
Wbr,
Antony Dovgal