Forum: NGINX RE: nginx+lua reverse proxy empty body (weird repeatable behavior)

Hi all

It seems the body_filter_by_lua section is bypassed somehow, it just 
doesn't receive the proxied data. I have this simplified testcase which 
at least for my setup is completely repeatable. See below.

In short, I do a curl call to localhost:9001, which gets the proxied 
server www.spelletjes.nl, and I correctly receive the index file 
including the "Speel" string that I'm trying to replace. But the lua 
section only says: "empty string". Once! So how did the server data get 
through to my curl call? Using openresty 1.2.4.7 (nginx 1.2.4 + 
ngx_lua-0.7.4 and more). The nginx.conf shown below is all there is, I 
am not using anything else.

I could really use some help here.

Thanks

Bart van Deenen


nginx.conf:

worker_processes  1;
error_log logs/error.log debug;
events {
    worker_connections 1024;
}
http {
    server {
        client_body_in_single_buffer on;
        listen 9001;
        location / {
            proxy_pass http://www.spelletjes.nl:80;
            proxy_set_header X-Real-IP $remote_addr;
            body_filter_by_lua '

if ngx.arg[1] ~= "" then
    print ( "The body is " .. ngx.arg[1])
    ngx.arg[1] = string.gsub(ngx.arg[1], "Speel", "NGINX")
else
    print(ngx.var.uri .. " has empty body" .. ngx.arg[1])
end
            ';

        }
    }
}

curl call:

curl -v -o spelletjes.html http://localhost:9001/
* About to connect() to localhost port 9001 (#0)
*   Trying 127.0.0.1...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time 
Current
                                 Dload  Upload   Total   Spent    Left 
Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:-- 
0* connected
* Connected to localhost (127.0.0.1) port 9001 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.27.0
> Host: localhost:9001
> Accept: */*
>
* additional stuff not fine transfer.c:1037: 0 0
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 200 OK
< Server: ngx_openresty/1.2.4.9
< Date: Thu, 29 Nov 2012 09:37:35 GMT
< Content-Type: text/html; charset=UTF-8
< Content-Length: 149577
< Connection: keep-alive
< RTSS: 1-1297-2
< Vary: Accept-Encoding
< Cache-Control: max-age=3600
< P3P: CP="IDC DSP COR CURa ADMa OUR IND PHY ONL COM STA"
< P3P: policyref="http://www.spelletjes.nl/w3c/p3p.xml", CP="DSP IDC CUR 
ADM PSA PSDi OTPi DELi STP NAV COM UNI INT PHY DEM "
< X-Id: 066
< Expires: Thu, 29 Nov 2012 10:29:59 GMT
< Last-Modified: Thu, 29 Nov 2012 09:29:59 GMT
<
{ [data not shown]
100  146k  100  146k    0     0  3163k      0 --:--:-- --:--:-- --:--:-- 
3246k
* Connection #0 to host localhost left intact
* Closing connection #0

error.log:
  1 2012/11/29 10:37:29 [notice] 4013#0: using the "epoll" event method
  2 2012/11/29 10:37:29 [notice] 4013#0: start worker processes
  3 2012/11/29 10:37:29 [notice] 4013#0: start worker process 4218
  4 2012/11/29 10:37:29 [notice] 4013#0: signal 17 (SIGCHLD) received
  5 2012/11/29 10:37:29 [notice] 4013#0: worker process 4215 exited with 
code 0
  6 2012/11/29 10:37:29 [notice] 4013#0: signal 29 (SIGIO) received
  7 2012/11/29 10:37:35 [notice] 4218#0: *65 [lua] variations.lua:67: / 
has empty body while sending to client,         client: 127.0.0.1, 
server: , request: "GET / HTTP/1.1", upstream: 
"http://212.72.60.182:80/", host: "localhost:     9001"
  8 2012/11/29 10:37:35 [info] 4218#0: *65 client 127.0.0.1 closed 
keepalive connection (104: Connection reset by       peer)

And the output of the curl call (the local file spelletjes.html) does 
contain the correct html (from the proxied server, including the string 
'Speel' that I'm trying to match on).

Hello!

On Thu, Nov 29, 2012 at 1:51 AM, Bart van Deenen wrote:
> It seems the body_filter_by_lua section is bypassed somehow, it just doesn't 
receive the proxied data. I have this simplified testcase which at least for my 
setup is completely repeatable. See below.
>

With your (exact) code sample, I cannot see any issues with
ngx_openresty 1.2.4.9 on Linux x86_64.

For a *single* request to location / (note: not multiple!), I'm
getting 26 non-empty data chunks:

    $ grep 'The body is' logs/error.log | wc -l
    26

and also one empty data chunk (which is generated by ngx_proxy to
solely signal the end of the body):

    $ grep 'has empty body' logs/error.log | wc -l
    1

You can try to scan your error.log on your side.

For big enough response bodies, it's common to see multiple data
chunks emitted by ngx_proxy to the output body filter chain. And your
body_filter_by_lua handler will be called multiple times, one time for
one data chunk, for a *single* response.

BTW, please post such questions to the openresty-en mailing list
(https://groups.google.com/group/openresty-en ) instead so that I can
see your mails sooner rather than later :)

Best regards,
-agentzh