ConsoleLogger logs to stderr

[tripodsan]

Following the intention that logging should behave similar than console.log, it is suprising to see that the ConsoleLogger uses console.error() to log the messages; which effectively logs to stderr.

Especially for CLI programs, where CLI output might be interspersed with log messages, logging to different streams might be a problem.

Of course, when building a pipe-able program, one might explicitely only log to stderr.

Suggestion:

• make it configurable in the ConsoleLogger, which stream to use.
• default to stdout

ps: I would use stdout/stderr directly, and not using console.[log|error]. it is unlikely ATM that helix-log is used in the browser (also, since it tries to load the package.json :-).

[koraa]

Hmmm, so there are a couple of reasons I chose to implement the console logger the way I did:

I chose to output log messages to stderr because stderr is – by convention – for error messages and other meta information, while stdout is for the actual output of the programm; I realize this is different from console, but I do believe it is the right choice for logging. This setup also preserves some features useful when working in the shell; e.g. you can silence the error stream simply by using '2>/dev/null'. I would expect that if a nodejs script is generating actual output, it would still use console.log as opposed to helix-log.

Especially for CLI programs, where CLI output might be interspersed with log messages, logging to different streams might be a problem.

Could you elaborate on that?

I would rather not use the nodejs stream abstraction (console._stderr/console._stdout) for writing, because it is asynchronous, while console.log/error is completely synchronous.

Of course we could use the streams directly by using the FileLogger:

class ConsoleLogger extends FileLogger {
  constructor(opts = {}) {
    super(2, {formatter: messageFormatConsole});
  }
};

FileLogger uses sync writes so this would preserve synchronicity.

[tripodsan]

process.stdout and process.stderr are both synchornous when writing to a tty in posix. see https://nodejs.org/api/process.html#process_a_note_on_process_i_o

also, there is no difference if using console.log() or process.stdout.write()

but, for example in an openwhisk action, when both stdout and stderr are piped into the activation logs, they might be out of order when using stderr and stdout.

---

I think in helix-cli we might use log.info instead of console.logorprocess.stdout` to communicate with the user. for example the progress bar is using stdout, but the messages before and after are using log.info.... but let's see how to deal with this later.

[koraa]

process.stdout and process.stderr are both synchornous when writing to a tty in posix

In this case, I would accept a PR rewriting ConsoleLogger to use process.stderr.

when both stdout and stderr are piped into the activation logs, they might be out of order when using stderr and stdout

Not sure the out of order problem would actually happen; if both are pointing at the same fd and writes are really sync (no buffering), the ordering of writes should be preserved (as really they are just writes to the same resource as far as the kernel is concerned).

for example the progress bar is using stdout

I mean, personally I would point the progress bar to stderr too… I would think that the result would be the same whether log.info or console.log is used, regardless of whether stderr or stdout was used…

[tripodsan]

Not sure the out of order problem would actually happen;

for example in openwhisk actions, where both streams are forwarded to the same pipe. since the pipes are async, the order is not guaranteed.

see the following 2 requests to the identical action: once stdout is added first, once after. also see the mangled timestamps:

$ wsk activation logs 078b05ef00d046b18b05ef00d036b1f3
2019-09-24T04:30:08.985Z       stdout: configured coralogix logger.
2019-09-24T04:30:08.986Z       stdout: configured papertrail logger.
2019-09-24T04:30:08.985Z       stderr: [ERROR] this is a test
2019-09-24T04:30:08.988Z       stderr: [INFO] GET /ping 200 - 0.91 ms

$ wsk activation logs 8d2f126a6766456aaf126a6766656a42
2019-09-24T04:30:43.186Z       stderr: [ERROR] this is a test
2019-09-24T04:30:43.190Z       stderr: [INFO] GET /ping 200 - 0.76 ms
2019-09-24T04:30:43.186Z       stdout: configured coralogix logger.
2019-09-24T04:30:43.188Z       stdout: configured papertrail logger.

[adobe-bot]

:tada: This issue has been resolved in version 2.1.0 :tada:

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot :package::rocket: