Question: Architecture: Why console.log, ngx.log, r.log writes to error_log ?

[yogeshgadge]

Background

Not trying to write a huge javascript server side application in njs but things like s3 signing, graphQL proxy are my use cases.
And where there is code there will be logs so I understand there are various ways to log things:

1. ngx.log
2. r.log
3. console.log

So the question is

When to use which of the console.log, ngx.log, r.log ?

Given that error_log cannot be JSON format how to perform logging so that the output is JSON ?

e.g.

console.log(JSON.stringify({info:true,debug:true}));

2023/11/14 09:30:57 [info] 50107#3441088: *6 js: {info:true,debug:true}

i.e. partial JSON.

When I deploy this nginx-njs app (say to k8s) and feed to ELK my JSON access logs and part JSON part string error_log can't be properly injected.

I want to be able to write logs in uniform fashion JSON format and while nginx inherently does not support formatting error log wondering Why console.log, ngx.log, r.log writes to error_log ?

If there is a way to change that to a access_log ?

Or if there is a possibility a log file can be opened across workers where logging can be streamed ? Since opening and closing files on eery request is not going to a good option.

[xeioex]

Hi @yogeshgadge,

Have you ever considered log_format escape=none?

Combine log_format with js_set variables returning serialized JSON.

[yogeshgadge]

Thank you @zeioex , yes started on something yesterday on similar path which probably means same thing:-

Documentation doesn't say it will "combine" access logs and error log. Unless I m mistaken ?

Anyways I did end up using escape=none.

Basically since each request is contained in a VM I just maintain a global constant array and accumulate any logs on it. As the code path logs it fills this array. Then js_set $logMsg main.getLogs which just returns a json string as shown below in logger.ts. This happens in the log phase at the end so it works but only in some senarios.

Any subrequets, auth situation I loose and the logs from only the first one survives in that chain.

That gets me thinking that I should use a shared dictionary instead of vm scoped variable since there is no provision for singleton objects/functions across workers/vm. Somehow I could tie all related logs - and they need to be only in string format - in a shared dictionary - perhaps using request_id or start a custom header on the first vm (x-log-id) and use its value as a key to retrieve in getLogs to finally assemble them and destroy these entries.

Now this seems quite the gymnastics. But doable. Wondering if I missed something simpler path ?

my simple solution that doesn't work well

# relevant snippet fro nginx.conf

  include ./logformat.conf;
  access_log access.log main_json;

  js_import main from ../dist/main.js;
  js_preload_object appConfig from ../config/application-__APP_ENV__.json;

  js_set $logMsg main.getLogs;
  js_set $logLevel main.getLogLevel;

# logformat.conf

log_format main_json escape=none '{ '
    '"@timestamp": "$time_iso8601", ' # local time in the ISO 8601 standard format
    '"level":"$logLevel", ' # sticky - will stick to ERROR, WAR as per priority
    '"request_path": "$request_uri", ' # full path and arguments if the request
    '"args": "$args", ' # args
    '"message":  $logMsg, ' # log messages from njs
    '"status": $status ' # response status code
    '}';

// logger.ts

// cardinal
export enum LogLevel {
  ERROR,
  WARN,
  INFO,
  TRACE
}

const PER_REQ_LOGS = [];
const PER_LOG_LEVEL = { level: LogLevel.INFO };

export function getLogs() {
  if (!PER_REQ_LOGS.length) return null;
  const msg = { logs: PER_REQ_LOGS };
  const v = JSON.stringify(msg);
  return v;
}
export function getLogLevel() {
  return LogLevel[PER_LOG_LEVEL.level];
}

class AccessLogAccumulatorLogger implements ILogger {
  protected level: LogLevel;
  constructor(
    protected _options: { level: string },
    protected comp: string
  ) {
    this.level = LogLevel[this._options.level];
  }

  trace(...args: any) {
    return this.log(LogLevel.TRACE, args);
  }
  warn(...args: any) {
    return this.log(LogLevel.WARN, args);
  }
  info(...args: any) {
    return this.log(LogLevel.INFO, args);
  }
  error(...args: any) {
    return this.log(LogLevel.ERROR, args);
  }

  log(level: LogLevel, args: any[]) {
    if (level > this.level) return null;
    const currLevel = PER_LOG_LEVEL.level;
    const newLevel = currLevel < level ? currLevel : level;
    PER_LOG_LEVEL.level = newLevel;
    const msg = this._msg(level, args);
    PER_REQ_LOGS.push(msg);
    return msg;
  }
  _msg(level: LogLevel, args: any = []): any {
    let messages: string = args.reduce((acc: string, a: string | Error) => {
      let m = a;
      if (a instanceof Error) {
        m = a.stack;
      } else if (typeof a === 'object') {
        m = JSON.stringify(a);
      }
      return `${acc} ${m}`;
    }, `${LogLevel[level]}:`);
    const msg = {};
    msg[`${this.comp}`] = messages;
    return msg;
  }
}

proposal js_log (like access_log/error_log) directive

expose streamWriter so that logging libraries can be used.

[yogeshgadge]

Round 2: Bit more improvement over the previous solution by using js_var.

According to documentation https://nginx.org/en/docs/http/ngx_http_js_module.html#js_var

The variable is not overwritten after a redirect unlike variables created with the set directive.

So same solution as above except instead of using vm scoped array PER_REQ_LOGS i use r.variables. PER_REQ_LOGS set using js_var PER_REQ_LOGS ''; in nginx.conf.

Then keep appending json object log entries as string and finally in js_set $logMsg getLog i assemble it like below:-
Construct array in string form and parse.

export function getLogs(_r: NginxHTTPRequest) {
  const varPER_REQ_LOGS = _r.variables.PER_REQ_LOGS;
  if (!varPER_REQ_LOGS) return null;
  const msg = { logs: JSON.parse(`[${varPER_REQ_LOGS}]`) }; // we need to parse this from string
  const v = JSON.stringify(msg);
  return v;
}

This works in subrequest/redirect situation.

Is this better than trying to open same file in append mode and write to it in every vm in ever request ?

[xeioex]

@yogeshgadge

Is this better than trying to open same file in append mode and write to it in every vm in ever request ?

It depends, opening a file is cheap operation actually.

[yogeshgadge]

@yogeshgadge

Is this better than trying to open same file in append mode and write to it in every vm in ever request ?

It depends, opening a file is cheap operation actually.

So on every request a files needs to opened in append mode. Thats same will be opened by other workers also in append mode. And we must close that file at the end of the work - somehow in log phase. Not sure f this is cheap than appending string to a js_var.

But I can benchmark it and post it one of these days.
Appreciate this wonderful njs - loving it - thank you !