Error `async operation inside` in r.subrequest with callback

[levonet]

nginx throw errors after update version of njs to 0.3.8:
2020/02/10 16:18:29 [error] 144#144: *6947506 async operation inside "js_log" variable handler, client: nda, server: nda, request: "POST /nda HTTP/1.1", host: "nda"

r.subrequest continues to work. In documentation:

Since 0.3.8, if a callback is not provided, the Promise object that resolves to the subrequest response object is returned.

There should be no error if a function has a callback argument. I think so.

Here is a minimal case:

function js_log(r) {
    var log = {
        // ...
    };
    var args = {
        method: 'POST',
        body: JSON.stringify(log)
    };
    r.subrequest('/_log', args, (res) => {});
    return '1';
}

in conf:

js_set $x_js_log js_log;
server {
    location / {
        proxy_set_header X-Log $x_js_log;
        proxy_pass http://backend;
    }
    location = /_log {
        internal;
        return 200;
    }
}

[xeioex]

Hi @levonet ,

nginx does not support asynchronous operations (it is not related to async keyword in JavaScript) in its variable handlers. When nginx want the value of some variable (say $x_js_log) it finds it and calls its handler (js_log). Nginx cannot block here, and wants the result right away. r.subrequest() is asynchronous operation by it nature.

To avoid confusion, nginx-http-js module checks whether pending operations was created in variable handler and returns error in such situation.

Yes, that check can be removed, in the sense that r.subrequest() can be scheduled from js_set handler, but there is no way to return r.subrequest() result as js_set result.

Can you give a good example where such behavior is desired?

[levonet]

I agree with you. But in my case proxy_pass and r.subrequest() work in parallel.
r.subrequest() called to send part of requestBody to storage. And js_log not wait for a response.
js_log always return '1'.

Can you remove that check for cases like mine?

[xeioex]

@levonet

BTW, take a look at http://nginx.org/en/docs/http/ngx_http_mirror_module.html Maybe this is what you actually need? Mirror subrequest works in parallel with the original one. The only caveat to remember: client request would not be considered finished until both proxy_pass and mirror subrequests are done (may affect log metrics if mirror is slow).

[levonet]

@xeioex Thanks!
This works fine with js_content.

[levonet]

I didn't remember, but maybe I refused mirror after the first overload tests. Now I use queue before storage.
In other cases, maybe, need custom switch off of check of promise in js_set.

[xeioex]

@levonet
In 0.3.8 background subrequests were removed, which is almost the same as mirror directive, because this behavior was never documented. Before 0.3.8 absense of a callback meant background subrequest, after 0.3.8 promise object which installs its own callback.

We can consider adding background flag, to options argument to enforce background subrequests.

[xeioex]

@levonet

You may try the patch.

[xeioex]

@levonet
Was committed in 889c17e

The flag was changed to "detached". Will be released within 0.3.9 (tomorrow, 03.03.2020).