Detached r.subrequest not running

[Coronon]

Hi there,

first of all thank you for all the awesome work! I just stumbled across this module and it really opens up so many possibilities!

When receiving a request to a specific endpoint, I want to send another request in the background that handles some logging (if the first one hits the content-cache I can't record the event). While investigating possible solutions I found #287 which I quickly tried to implement. While I don't get any error, the subrequest doesn't seem to be sent either (tried debug logging).

My nginx.conf:

# ... http {
log_format  customformat '$remote_addr - $remote_user [$time_local] "$request" '
                         '$status $body_bytes_sent "$http_referer" '
                         '"$http_user_agent" "$http_x_forwarded_for" recorded:"$recorded"'; // <-- notice the $recorded variable
# ... }

My server.conf:

# ...
js_path "/etc/nginx/njs/";
js_import logger.js;

location /api/route {
    js_set $recorded logger.log;
    access_log /var/log/nginx/access.log customformat;

    proxy_pass http://my-api;

    proxy_http_version 1.1;
    proxy_set_header Upgrade $http_upgrade;
    proxy_set_header Connection "upgrade";

    proxy_redirect off;
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header X-Forwarded-Host $server_name;
}

location /myloggingenpoint {
    # This is sadly never invoked :(
}
# ...

The logger.js file:

function log(r) {
  let args = {
    detached: true,
  }
  r.subrequest("/myloggingenpoint", args)

  return true
}

export default { log }

I know that logger.log is called as setting detached->false will cause an error to be printed and the returned value true shows up in the logs:

[DATE_TIME] "GET /api/route HTTP/1.1" 200 123 "http://localhost/mysite" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:120.0) Gecko/20100101 Firefox/120.0" "-" recorded:"true"

When I replace all my proxying with js_content logger.log; the subrequest is also not executed. It will only run with detached: false inside js_content :(

[xeioex]

Hi @Coronon,

Unfortunately, scheduling a subrequest at a logger phase is too late. Just after it, the current request is destroyed and its subrequests are not handled.

The detached subrequests work, but you have to schedule them earlier.
For logging purposes probably mirror module will be enough.

[Coronon]

Thank you for your quick reply @xeioex

That makes sense, thank you. Maybe this is something that could be added as a little footnote in the documentation?

I read that the mirror module will not fire when the response is taken from a content-cache of the original request. The reason I want to initiate the sub-request using njs is that a variable should always be evaluated and the logging (counter) request therefore fired :)

[xeioex]

@Coronon

Maybe this is something that could be added as a little footnote in the documentation?

thanks for pointing this out, I will see how we can improve the docs here.

[Coronon]

Thanks to your tip I was able to use the js_set function inside a location block that will simply rewrite the request to another internal location block which can then use content-caching without causing my subrequest not to run.

Just leaving the code here for other people if they also encounter this issue:

server.conf:

js_path "/etc/nginx/njs/";
js_import logger.js;

location /api/route {
    js_set $recorded logger.log;
   
    rewrite ^/api/route /internal/api/route$recorded last;
}

location /myloggingenpoint {
    internal;

    # Handle the request...
}

location /internal/api/route {
    internal;

    # Remove /internal prefix
    rewrite ^/internal(/.*)$ $1 break;

    proxy_pass http://my-api;

    proxy_http_version 1.1;
    proxy_set_header Upgrade $http_upgrade;
    proxy_set_header Connection "upgrade";

    proxy_redirect off;
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header X-Forwarded-Host $server_name;
}

logger.js:

function log(r) {
  r.subrequest("/myloggingenpoint", {detached: true});

  return '';
}

export default { log }

Thank you once again for your help! :)