Hopefully this isn't too awful a place to post this issue I'm having -- I figure if anyone has loads of experience with nginx+lua, it'd be the openresty group! Thanks!
My goal is to use access_by_lua to send an auth check via lua subrequest to an upstream server and allow a request to a separate upstream server once the check is successful. requests to /navbar/rstudio cause a subrequest to /app/user/whoami (which returns a confirmation of authentication, simplified below by matching "success" in the body, which had a separate gzip issue i've been able to resolve, so i'm certain gzip content is not the issue here) and then proxy_pass serves the rstudio server content. This is working flawlessly for static content etc but some of the requests (rpc calls) don't complete successfully, the client just hangs (and the remote rstudio server never receives the rpc request). Any ideas?
nginx location directive:
location /navbar/rstudio/ {
access_by_lua '
local res = ngx.location.capture("/app/user/whoami")
if string.match(res.body, "success") then
return;
else
--redirects user to log in
ngx.redirect("/web/#login");
end
';
rewrite ^/rstudio/(.*)$ /$1 break;
proxy_pass https://{rstudio_server};
proxy_redirect https://{rstudio_server}/ $scheme://$host/navbar/rstudio/;
}
And the debug log from the rpc request (for this log, I've commented out the actual access limiting, simply making the ngx.location.capture subrequest causes the "client_init" request to never be called):
2014/10/31 08:34:58 [debug] 12506#0: *1 lua access handler, uri "/rpc/client_init"
2014/10/31 08:34:58 [debug] 12506#0: *1 lua creating new thread
2014/10/31 08:34:58 [debug] 12506#0: *1 lua reset ctx
2014/10/31 08:34:58 [debug] 12506#0: *1 http cleanup add: 00000000016F6170
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run thread
2014/10/31 08:34:58 [debug] 12506#0: *1 posix_memalign: 00000000016F6670:4096 @16
2014/10/31 08:34:58 [debug] 12506#0: *1 http subrequest "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 lua resume returned 1
2014/10/31 08:34:58 [debug] 12506#0: *1 lua thread yielded
2014/10/31 08:34:58 [debug] 12506#0: *1 http posted request: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 rewrite phase: 1
2014/10/31 08:34:58 [debug] 12506#0: *1 test location: "/"
2014/10/31 08:34:58 [debug] 12506#0: *1 using configuration "/app"
2014/10/31 08:34:58 [debug] 12506#0: *1 http cl:50 max:104857600
2014/10/31 08:34:58 [debug] 12506#0: *1 rewrite phase: 3
2014/10/31 08:34:58 [debug] 12506#0: *1 rewrite phase: 4
2014/10/31 08:34:58 [debug] 12506#0: *1 post rewrite phase: 5
2014/10/31 08:34:58 [debug] 12506#0: *1 generic phase: 6
2014/10/31 08:34:58 [debug] 12506#0: *1 generic phase: 7
2014/10/31 08:34:58 [debug] 12506#0: *1 generic phase: 8
2014/10/31 08:34:58 [debug] 12506#0: *1 http client request body preread 50
2014/10/31 08:34:58 [debug] 12506#0: *1 http init upstream, client timer: 0
2014/10/31 08:34:58 [debug] 12506#0: *1 posix_memalign: 00000000016F7680:4096 @16
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "X-Real-IP: "
2014/10/31 08:34:58 [debug] 12506#0: *1 http script var: "{CLIENT_IP}"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "^M
"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "X-Forwarded-For: "
2014/10/31 08:34:58 [debug] 12506#0: *1 http script var: "{CLIENT_IP}"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "^M
"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "Host: "
2014/10/31 08:34:58 [debug] 12506#0: *1 http script var: "{HOST_DNS}"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "^M
"
2014/10/31 08:34:58 [debug] 12506#0: *1 http script copy: "Connection: close^M
"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Content-Length: 50"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Pragma: no-cache"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Cache-Control: no-cache"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Accept: application/json"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Origin: https://{HOST_DNS}"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Content-Type: application/json"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.104 Safari/537.36"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "X-RS-RID: -1243952224"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "DNT: 1"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Referer: https://{HOST_DNS}/navbar/rstudio/"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Accept-Encoding: gzip,deflate"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Accept-Language: en-US,en;q=0.8"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Cookie: user-id=localadmin|Wed%2C%2030%20Oct%202024%2015%3A30%3A07%20GMT|jghDL11l8sVuVvZ8Ht%2BHulCiLPc%3D; _pk_id.6.1e76=433ab61043e4bd3b.1413832511.1.1413832511.1413832511."
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header:
"GET /app/user/whoami?client=nginx HTTP/1.0^M
X-Real-IP: {CLIENT_IP}^M
X-Forwarded-For: {CLIENT_IP}^M
Host: {HOST_DNS}^M
Connection: close^M
Content-Length: 50^M
Pragma: no-cache^M
Cache-Control: no-cache^M
Accept: application/json^M
Origin: https://{HOST_DNS}^M
Content-Type: application/json^M
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.104 Safari/537.36^M
X-RS-RID: -1243952224^M
DNT: 1^M
Referer: https://{HOST_DNS}/navbar/rstudio/^M
Accept-Encoding: gzip,deflate^M
Accept-Language: en-US,en;q=0.8^M
Cookie: user-id=localadmin|Wed%2C%2030%20Oct%202024%2015%3A30%3A07%20GMT|jghDL11l8sVuVvZ8Ht%2BHulCiLPc%3D; _pk_id.6.1e76=433ab61043e4bd3b.1413832511.1.1413832511.1413832511.^M
^M
"
2014/10/31 08:34:58 [debug] 12506#0: *1 http cleanup add: 00000000016F7A68
2014/10/31 08:34:58 [debug] 12506#0: *1 get rr peer, try: 1
2014/10/31 08:34:58 [debug] 12506#0: *1 socket 22
2014/10/31 08:34:58 [debug] 12506#0: *1 epoll add connection: fd:22 ev:80000005
2014/10/31 08:34:58 [debug] 12506#0: *1 connect to 127.0.0.1:8080, fd:22 #16
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream connect: -2
2014/10/31 08:34:58 [debug] 12506#0: *1 posix_memalign: 00000000015BAF70:128 @16
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer add: 22: 60000:1414769758472
2014/10/31 08:34:58 [debug] 12506#0: *1 http finalize request: -4, "/app/user/whoami?client=nginx" a:1, c:3
2014/10/31 08:34:58 [debug] 12506#0: *1 http request count:3 blk:0
2014/10/31 08:34:58 [debug] 12506#0: *1 post event 00000000016E1E58
2014/10/31 08:34:58 [debug] 12506#0: *1 delete posted event 00000000016E1E58
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream request: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream send request handler
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream send request
2014/10/31 08:34:58 [debug] 12506#0: *1 chain writer buf fl:0 s:775
2014/10/31 08:34:58 [debug] 12506#0: *1 chain writer buf fl:1 s:50
2014/10/31 08:34:58 [debug] 12506#0: *1 chain writer in: 00000000016F7AC0
2014/10/31 08:34:58 [debug] 12506#0: *1 writev: 825
2014/10/31 08:34:58 [debug] 12506#0: *1 chain writer out: 0000000000000000
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer del: 22: 1414769758472
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer add: 22: 60000:1414769758474
2014/10/31 08:34:58 [debug] 12506#0: *1 post event 00000000016CE648
2014/10/31 08:34:58 [debug] 12506#0: *1 post event 00000000016E1E58
2014/10/31 08:34:58 [debug] 12506#0: *1 delete posted event 00000000016E1E58
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream request: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream dummy handler
2014/10/31 08:34:58 [debug] 12506#0: *1 delete posted event 00000000016CE648
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream request: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream process header
2014/10/31 08:34:58 [debug] 12506#0: *1 malloc: 0000000001727300:4096
2014/10/31 08:34:58 [debug] 12506#0: *1 recv: fd:22 519 of 4096
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy status 200 "200 OK"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Server: Apache-Coyote/1.1"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Access-Control-Allow-Origin: https://{HOST_DNS}"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Access-Control-Allow-Credentials: true"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Content-Encoding: gzip"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Vary: Accept-Encoding"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Expires: Fri, 5 May 1995 12:00:00 GMT"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Cache-Control: no-store, no-cache, must-revalidate"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Pragma: no-cache"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Content-Type: application/json"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Content-Length: 108"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Date: Fri, 31 Oct 2014 15:34:57 GMT"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header: "Connection: close"
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy header done
2014/10/31 08:34:58 [debug] 12506#0: *1 lua capturing response body
2014/10/31 08:34:58 [debug] 12506#0: *1 http cacheable: 0
2014/10/31 08:34:58 [debug] 12506#0: *1 http proxy filter init s:200 h:0 c:0 l:108
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream process upstream
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe read upstream: 1
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe preread: 108
2014/10/31 08:34:58 [debug] 12506#0: *1 readv: 1:3577
2014/10/31 08:34:58 [debug] 12506#0: *1 readv() not ready (11: Resource temporarily unavailable)
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe recv chain: -2
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe buf free s:0 t:1 f:0 0000000001727300, pos 000000000172749B, size: 108 file: 0, size: 0
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe length: 108
2014/10/31 08:34:58 [debug] 12506#0: *1 input buf #0
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe write downstream: 1
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe write downstream flush in
2014/10/31 08:34:58 [debug] 12506#0: *1 http output filter "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http copy filter: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 lua capture body filter capturing response body, uri "/app/user/whoami"
2014/10/31 08:34:58 [debug] 12506#0: *1 http copy filter: 0 "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 pipe write downstream done
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer: 22, old: 1414769758474, new: 1414769758531
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream exit: 0000000000000000
2014/10/31 08:34:58 [debug] 12506#0: *1 finalize http upstream request: 0
2014/10/31 08:34:58 [debug] 12506#0: *1 finalize http proxy request
2014/10/31 08:34:58 [debug] 12506#0: *1 free rr peer 1 0
2014/10/31 08:34:58 [debug] 12506#0: *1 close http upstream connection: 22
2014/10/31 08:34:58 [debug] 12506#0: *1 free: 00000000015BAF70, unused: 48
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer del: 22: 1414769758474
2014/10/31 08:34:58 [debug] 12506#0: *1 reusable connection: 0
2014/10/31 08:34:58 [debug] 12506#0: *1 http upstream temp fd: -1
2014/10/31 08:34:58 [debug] 12506#0: *1 http output filter "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http copy filter: "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 lua capture body filter capturing response body, uri "/app/user/whoami"
2014/10/31 08:34:58 [debug] 12506#0: *1 http copy filter: 0 "/app/user/whoami?client=nginx"
2014/10/31 08:34:58 [debug] 12506#0: *1 http finalize request: 0, "/app/user/whoami?client=nginx" a:1, c:2
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run post subrequest handler: rc:0, waiting:0, done:0
2014/10/31 08:34:58 [debug] 12506#0: *1 http wake parent request: "/rpc/client_init?"
2014/10/31 08:34:58 [debug] 12506#0: *1 http posted request: "/rpc/client_init?"
2014/10/31 08:34:58 [debug] 12506#0: *1 access phase: 14
2014/10/31 08:34:58 [debug] 12506#0: *1 lua access handler, uri "/rpc/client_init"
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run write event handler
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run subrequests done, resuming lua thread
2014/10/31 08:34:58 [debug] 12506#0: *1 lua handle subrequest responses
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run thread
2014/10/31 08:34:58 [debug] 12506#0: *1 lua resume returned 0
2014/10/31 08:34:58 [debug] 12506#0: *1 lua thread ended normally
2014/10/31 08:34:58 [debug] 12506#0: *1 lua deleting thread
2014/10/31 08:34:58 [debug] 12506#0: *1 lua run thread returned 0
2014/10/31 08:34:58 [debug] 12506#0: *1 posix_memalign: 0000000001728310:4096 @16
2014/10/31 08:34:58 [debug] 12506#0: *1 http read client request body
2014/10/31 08:34:58 [debug] 12506#0: *1 SSL_read: -1
2014/10/31 08:34:58 [debug] 12506#0: *1 SSL_get_error: 2
2014/10/31 08:34:58 [debug] 12506#0: *1 http client request body recv -2
2014/10/31 08:34:58 [debug] 12506#0: *1 http client request body rest 50
2014/10/31 08:34:58 [debug] 12506#0: *1 event timer add: 21: 60000:1414769758531
2014/10/31 08:34:58 [debug] 12506#0: *1 http finalize request: -4, "/rpc/client_init?" a:1, c:2
2014/10/31 08:34:58 [debug] 12506#0: *1 http request count:2 blk:0
2014/10/31 08:34:58 [debug] 12506#0: *17 http cl:-1 max:104857600
Thanks a million!
