Njs: r.subrequest() to a static file hangs silently when aio is enabled.

[shankerwangmiao]

Here is a minimal case:

.
├── 1.js
├── html
│   └── bar
├── info.log
├── modules -> /usr/lib/nginx/modules
└── nginx.conf

where 1.js is

var fooHandler = function(r){
  r.subrequest('/bar', {
    args: '',
    body: '',
    method: 'GET'
  }, function(subR){
    r.status = subR.status;
    r.headersOut['Content-Type'] = 'text/html';
    r.sendHeader();
    if(subR.status != 200){
      r.send("Sub Req Err: " + subR.status);
    }
    r.send(subR.responseBody);
    r.finish();
  });
};

and nginx.conf is

user www-data;
worker_processes 1;
pid /run/nginx.pid;
load_module modules/ngx_http_js_module-debug.so;

error_log info.log debug;

events {
}

http {

  js_include '1.js';
  aio threads;

  server {
    listen 80;
    location / {
      root html/;
    }
    location = /foo {
      js_content fooHandler;
    }
  }
}

The debug log is:

2019/08/23 12:15:18 [info] 1268#1268: epoll_wait() failed (4: Interrupted system call)
2019/08/23 12:15:18 [debug] 1268#1268: timer delta: 3840
2019/08/23 12:15:18 [debug] 1268#1268: worker cycle
2019/08/23 12:15:18 [debug] 1268#1268: epoll timer: -1
2019/08/23 12:15:19 [debug] 1268#1268: epoll: fd:22 ev:2001 d:000055CB88F7D280
2019/08/23 12:15:19 [debug] 1268#1268: *7 http run request: "/foo?"
2019/08/23 12:15:19 [debug] 1268#1268: *7 http reading blocked
2019/08/23 12:15:19 [debug] 1268#1268: timer delta: 1136
2019/08/23 12:15:19 [debug] 1268#1268: worker cycle
2019/08/23 12:15:19 [debug] 1268#1268: epoll timer: -1
2019/08/23 12:15:22 [debug] 1268#1268: epoll: fd:6 ev:0001 d:000055CB88F7CAC0
2019/08/23 12:15:22 [debug] 1268#1268: accept on 0.0.0.0:80, ready: 0
2019/08/23 12:15:22 [debug] 1268#1268: posix_memalign: 000055CB88FDC930:512 @16
2019/08/23 12:15:22 [debug] 1268#1268: *8 accept: 127.0.0.1:59264 fd:24
2019/08/23 12:15:22 [debug] 1268#1268: *8 event timer add: 24: 60000:2542737
2019/08/23 12:15:22 [debug] 1268#1268: *8 reusable connection: 1
2019/08/23 12:15:22 [debug] 1268#1268: *8 epoll add event: fd:24 op:1 ev:80002001
2019/08/23 12:15:22 [debug] 1268#1268: timer delta: 2876
2019/08/23 12:15:22 [debug] 1268#1268: worker cycle
2019/08/23 12:15:22 [debug] 1268#1268: epoll timer: 60000
2019/08/23 12:15:22 [debug] 1268#1268: epoll: fd:24 ev:0001 d:000055CB88F7D378
2019/08/23 12:15:22 [debug] 1268#1268: *8 http wait request handler
2019/08/23 12:15:22 [debug] 1268#1268: *8 malloc: 000055CB88FDCB40:1024
2019/08/23 12:15:22 [debug] 1268#1268: *8 recv: eof:0, avail:1
2019/08/23 12:15:22 [debug] 1268#1268: *8 recv: fd:24 76 of 1024
2019/08/23 12:15:22 [debug] 1268#1268: *8 reusable connection: 0
2019/08/23 12:15:22 [debug] 1268#1268: *8 posix_memalign: 000055CB88FDCF50:4096 @16
2019/08/23 12:15:22 [debug] 1268#1268: *8 http process request line
2019/08/23 12:15:22 [debug] 1268#1268: *8 http request line: "GET /foo HTTP/1.1"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http uri: "/foo"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http args: ""
2019/08/23 12:15:22 [debug] 1268#1268: *8 http exten: ""
2019/08/23 12:15:22 [debug] 1268#1268: *8 posix_memalign: 000055CB88FDDF60:4096 @16
2019/08/23 12:15:22 [debug] 1268#1268: *8 http process request header line
2019/08/23 12:15:22 [debug] 1268#1268: *8 http header: "Host: 127.0.0.1"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http header: "User-Agent: curl/7.52.1"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http header: "Accept: */*"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http header done
2019/08/23 12:15:22 [debug] 1268#1268: *8 event timer del: 24: 2542737
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 0
2019/08/23 12:15:22 [debug] 1268#1268: *8 rewrite phase: 1
2019/08/23 12:15:22 [debug] 1268#1268: *8 test location: "/"
2019/08/23 12:15:22 [debug] 1268#1268: *8 test location: "foo"
2019/08/23 12:15:22 [debug] 1268#1268: *8 using configuration "=/foo"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http cl:-1 max:1048576
2019/08/23 12:15:22 [debug] 1268#1268: *8 rewrite phase: 3
2019/08/23 12:15:22 [debug] 1268#1268: *8 post rewrite phase: 4
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 5
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 6
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 7
2019/08/23 12:15:22 [debug] 1268#1268: *8 access phase: 8
2019/08/23 12:15:22 [debug] 1268#1268: *8 access phase: 9
2019/08/23 12:15:22 [debug] 1268#1268: *8 access phase: 10
2019/08/23 12:15:22 [debug] 1268#1268: *8 post access phase: 11
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 12
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 13
2019/08/23 12:15:22 [debug] 1268#1268: *8 http js content handler
2019/08/23 12:15:22 [debug] 1268#1268: *8 http js content event handler
2019/08/23 12:15:22 [debug] 1268#1268: *8 add cleanup: 000055CB88FDDD50
2019/08/23 12:15:22 [debug] 1268#1268: *8 http js content call "fooHandler"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http subrequest "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http finalize request: -4, "/foo?" a:1, c:3
2019/08/23 12:15:22 [debug] 1268#1268: *8 http request count:3 blk:0
2019/08/23 12:15:22 [debug] 1268#1268: *8 http posted request: "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 rewrite phase: 1
2019/08/23 12:15:22 [debug] 1268#1268: *8 test location: "/"
2019/08/23 12:15:22 [debug] 1268#1268: *8 test location: "foo"
2019/08/23 12:15:22 [debug] 1268#1268: *8 using configuration "/"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http cl:0 max:1048576
2019/08/23 12:15:22 [debug] 1268#1268: *8 rewrite phase: 3
2019/08/23 12:15:22 [debug] 1268#1268: *8 post rewrite phase: 4
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 5
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 6
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 7
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 12
2019/08/23 12:15:22 [debug] 1268#1268: *8 generic phase: 13
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 14
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 15
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 16
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 17
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 18
2019/08/23 12:15:22 [debug] 1268#1268: *8 content phase: 19
2019/08/23 12:15:22 [debug] 1268#1268: *8 http filename: "/path/to/nginx_debug/html/bar"
2019/08/23 12:15:22 [debug] 1268#1268: *8 add cleanup: 000055CB88FDDEB8
2019/08/23 12:15:22 [debug] 1268#1268: *8 http static fd: 25
2019/08/23 12:15:22 [debug] 1268#1268: *8 posix_memalign: 000055CB88FE2220:4096 @16
2019/08/23 12:15:22 [debug] 1268#1268: *8 http output filter "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http copy filter: "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 thread read: 25, 000055CB88FDDF28, 12, 0
2019/08/23 12:15:22 [debug] 1268#1268: task #7 added to thread pool "default"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http copy filter: -2 "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http finalize request: -2, "/bar?" a:0, c:2
2019/08/23 12:15:22 [debug] 1268#1268: *8 http request count:2 blk:1
2019/08/23 12:15:22 [debug] 1268#1268: timer delta: 0
2019/08/23 12:15:22 [debug] 1268#1268: worker cycle
2019/08/23 12:15:22 [debug] 1268#1268: epoll timer: -1
2019/08/23 12:15:22 [debug] 1268#1269: run task #7 in thread pool "default"
2019/08/23 12:15:22 [debug] 1268#1269: thread read handler
2019/08/23 12:15:22 [debug] 1268#1269: pread: 12 (err: 0) of 12 @0
2019/08/23 12:15:22 [debug] 1268#1269: complete task #7 in thread pool "default"
2019/08/23 12:15:22 [debug] 1268#1268: epoll: fd:9 ev:0001 d:000055CB87BD1160
2019/08/23 12:15:22 [debug] 1268#1268: thread pool handler
2019/08/23 12:15:22 [debug] 1268#1268: run completion handler for task #7
2019/08/23 12:15:22 [debug] 1268#1268: *8 http thread: "/bar?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http run request: "/foo?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http js content write event handler
2019/08/23 12:15:22 [debug] 1268#1268: *8 http output filter "/foo?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http copy filter: "/foo?"
2019/08/23 12:15:22 [debug] 1268#1268: *8 http postpone filter "/foo?" 0000000000000000
2019/08/23 12:15:22 [debug] 1268#1268: *8 http copy filter: 0 "/foo?"
2019/08/23 12:15:22 [debug] 1268#1268: timer delta: 0
2019/08/23 12:15:22 [debug] 1268#1268: worker cycle
2019/08/23 12:15:22 [debug] 1268#1268: epoll timer: -1
2019/08/23 12:15:23 [debug] 1268#1268: epoll: fd:24 ev:2001 d:000055CB88F7D378
2019/08/23 12:15:23 [debug] 1268#1268: *8 http run request: "/foo?"
2019/08/23 12:15:23 [debug] 1268#1268: *8 http reading blocked
2019/08/23 12:15:23 [debug] 1268#1268: timer delta: 820
2019/08/23 12:15:23 [debug] 1268#1268: worker cycle
2019/08/23 12:15:23 [debug] 1268#1268: epoll timer: -1

The callback function in the njs script is never called.

[ivorbosloper]

The exact same problem seems to occur if you enable http2 on any of your server definitions.

In another site/server-definition (not using njs) within the same nginx instance, I changed

listen 443 ssl;

to

listen 443 ssl http2;

This caused the callback failure for the site using njs.

[xeioex]

@ivorbosloper

This is the way nginx works. If you have several listen directives on the same port (as in your example) in the same nginx instance all extra options (ssl, http2) are actually merged.
So when you have several listen 443 ssl, and you add listen 443 ssl http2 in another server, in effect you have listen 443 ssl http2 for every server. The reason for that is simple, nginx need to know what protocol to use (tls, http2) BEFORE extracting server name from the request (and deciding which server block to use).

[shankerwangmiao]

Just FYI, on my server, http2 is enabled and I can see subrequest in njs working properly.

[xeioex]

@shankerwangmiao
The following patch for nginx solves the issue.

# HG changeset patch
# User Dmitry Volyntsev <[email protected]>
# Date 1582896462 -10800
#      Fri Feb 28 16:27:42 2020 +0300
# Node ID 8462b3e20a8042bbcbf33167fef5f3d53f8d30d2
# Parent  2e3bfd696ecb822c82605681554381e9eabd032d
Fixed background subrequest finalization.

diff --git a/src/http/ngx_http_request.c b/src/http/ngx_http_request.c
--- a/src/http/ngx_http_request.c
+++ b/src/http/ngx_http_request.c
@@ -2490,6 +2490,15 @@ ngx_http_finalize_request(ngx_http_reque
     if (r != r->main) {
         clcf = ngx_http_get_module_loc_conf(r, ngx_http_core_module);

+        if (r->buffered || r->postponed) {
+
+            if (ngx_http_set_write_handler(r) != NGX_OK) {
+                ngx_http_terminate_request(r, 0);
+            }
+
+            return;
+        }
+
         if (r->background) {
             if (!r->logged) {
                 if (clcf->log_subrequest) {
@@ -2509,15 +2518,6 @@ ngx_http_finalize_request(ngx_http_reque
             return;
         }

-        if (r->buffered || r->postponed) {
-
-            if (ngx_http_set_write_handler(r) != NGX_OK) {
-                ngx_http_terminate_request(r, 0);
-            }
-
-            return;
-        }
-
         pr = r->parent;

         if (r == c->data) {

[xeioex]

Fixed in https://github.com/nginx/nginx/commit/3733c6fd70a9e9ce64901982621629a8cfcc66a8, will be released tomorrow within 1.17.9-release.

[xeioex]

@ivorbosloper You may also retry the issue with nginx-1.17.9.