Log debug / verbose output to stderr or make logging appender configurable

[dlouzan]

As part of https://github.com/wework/speccy/pull/270, I'm finding that oas-resolver (and I'm sure other packages in this repo) is logging its verbose output to stdout directly using console.log. This is biting me when piping speccy commands and activating verbose logs, since both the actual openAPI contents of a speccy resolve and its debug information will be mixed in stdout, making the output content incorrect.

Example:

$ ./speccy.js resolve openapi.yaml -v | ./speccy.js lint
GET /.../openapi.yaml
Could not read YAML/JSON from file: end of the stream or a document separator is expected at line 2, column 1:
    CACHED /.../openapi.yaml
    ^

I see two potential solutions:

Replace console.log by console.error

This is the easiest and most straightforward. This could potentially produce issues for people somehow building things depending on the verbose output and expecting nowadays that it goes to stdout, though I'm not sure why would anyone do that.

Another potential issue is execution on browsers, since from that point on, all output would be logged to the console debug error. I'm not sure though how bad that would be, and whether people actually use this in verbose mode directly in the browser outside of development mode.

Use a Logging Framework

Use any of the multiple logging frameworks available (morgan, winston, debug, ...) and then provide a way to configure the logging output. A user of the package could decide to which appender to send the verbose output.

This wouldn't be anyway a bad thing, independently of the stdout/stderr thing :-)

[MikeRalphson]

depending on the verbose output and expecting nowadays that it goes to stdout, though I'm not sure why would anyone do that.

The output goes to console.log as it is logging output, not errors or warnings. I'm equally not sure why verbose mode is necessary if you're wanting to pipe STDOUT to a file. All of oas-kit and Speccy as far as I know supports providing an output file on the command-line.

This is the easiest and most straightforward

Hmm, as above, the "easiest and most straighforward" is not to enable verbose mode when you want to pipe the output.

Feel free to convince me otherwise.

[dlouzan]

The GNU libc says this about the standard streams:

Variable: FILE * stdout The standard output stream, which is used for normal output from the program.

Variable: FILE * stderr The standard error stream, which is used for error messages and diagnostics issued by the program.

To me it sounds a lot that verbose is diagnostics and not normal output. I know that stderr is not very well named, but it's a historical thing.

There's some cases in which it's not easy to decide what is right, as an example let's take a web server, in that case I could understand that info output of the requests made went to stdout, though the case could be made for them to go to stderr; the actual answer to the client is going through a tcp socket anyway.

But in the case of speccy and oas-kit, if they're intended as cli tools (at least in some cases), it looks most naturally that resolve prints to stdout the actual resolved file and prints whatever errors and verbose output to stderr.

To be honest, this is not a big issue, this behaviour just feels... weird and unexpected. Most cli tools I know follow this convention if you set verbose mode on. On the top of my head I can think right now of ssh and curl. I would be surprised by a tool that didn't follow this convention and when I piped the output to a file, inserted weird diagnostics data in the middle.

But hey, I'm a unix-head :-)

[MikeRalphson]

@pderaaij @padamstx Thoughts?

[pderaaij]

If I deliberately choose verbose mode I would say the output belongs to stdout as it is information I requested for and not an error that should be placed on stderr, at least.. that's the feeling I have about it.

But, if I do the following: curl -v https://petstore.swagger.io/v2/swagger.json | jq '.info.version'

I see the behavior described by @dlouzan. It makes sense to align with this behavior.

[padamstx]

My 2 cents... Lots of commands are designed/intended to be used as a "filter" where they read their primary input from stdin and write their primary output to stdout. Also, lots of commands are NOT designed/intended to operate that way... instead, they support explicit options to specify their input and/or output streams (typically a file). If the oas-kit-related tools are intended to behave like a filter, then (IMO) their default behavior probably should be to read from stdin and write to stdout, while any logging of info/warning/error messages would need to be written to stderr so that the primary output (e.g. for s2o this is the converted apispec) is not intermingled with those other progress/debug messages, etc.

Personally, i don't think using a tool like swagger2openapi as a filter is necessarily the primary use case, but it is one of the use cases. I don't think there would be much risk in modifying s2o to write all its messages to stderr while writing the converted apispec to stdout (assuming the -o option wasn't used). In the case of s2o I think it comes down to this: 1) Do we want the default behavior (absent a -o option) to be that s2o writes its converted apispec to stdout? 2) Do we want info/warning/debug messages to be written to stdout? I don't think we can have both :) If we choose 1, then I think we need to write all info/warning/error/debug messages to stderr.

I suppose one could get clever and implement this in a flexible way where if -o is specified, then info/warning/debug messages are written to stdout while the converted apispec is written to the specified file, and if -o is not specified then the converted apispec is written to stdout and ALL messages are written to stderr.

How's that for sitting on the fence? :)

[MikeRalphson]

Status: convinced.

[MikeRalphson]

Successfully published:

• oas-linter@3.0.1
• oas-resolver@2.2.1
• oas-validator@3.2.1
• reftools@1.0.7
• swagger2openapi@5.2.1