Unstoppable console log message when misconfigured

[chadjaros]

Reopening https://github.com/googleapis/nodejs-error-reporting/issues/525

The above ticket was closed without addressing the issue described in the ticket.

tl/dr; The error management and logging facilities don't actually allow you to disable logging messages to console.log.

1. Is this a client library issue or a product issue?

client library

2. Did someone already solve this?

don't think so

3. Do you have a support contract?

Yes, but was told to log the issue here anyways.

Environment details

• OS: Mac OS 10.15.7
• Node.js version: v12.16.2
• npm version: 6.14.4
• @google-cloud/error-reporting version: ^2.0.0

Steps to reproduce

1. Instantiate library with incorrect configuration:

const errorReporting = new ErrorReporting({
            projectId: 'trash',
            reportMode: 'always',
            serviceContext: { server: 'myServer', version: '1.0.0' },
            logLevel: 0
        });

2. Fire an error, and include a callback

errorReporting.report(error, undefined, undefined, (err) => {
                if (err) {
                    console.log('Failed to report error', err);
                }
            });

Observe the following long error message is printed to stdout even though logLevel is set to 0 and a callback is provided. The callback configured above results in printing a subset of the following error a second time.

ERROR:@google-cloud/error-reporting: Proxy for some error message text emitted by the google API, the specific error message text doesn't matter. The fact that the message goes to console.log is the problem.
    at new ApiError (/Users/---/node_modules/@google-cloud/common/build/src/util.js:59:15)
    at Util.parseHttpRespBody (/Users/---/node_modules/@google-cloud/common/build/src/util.js:194:38)
    at Util.handleResp (/Users/---/node_modules/@google-cloud/common/build/src/util.js:135:117)
    at /Users/---/node_modules/@google-cloud/common/build/src/util.js:434:22
    at onResponse (/Users/---/node_modules/retry-request/index.js:214:7)
    at /Users/---/node_modules/teeny-request/src/index.ts:325:11
    at processTicksAndRejections (internal/process/task_queues.js:97:5) {
  code: 403,
  errors: undefined,
  response: Gunzip {
    _writeState: Uint32Array(2) [ 16273, 0 ],
    _readableState: ReadableState {
      objectMode: false,
      highWaterMark: 16384,
      buffer: BufferList { head: null, tail: null, length: 0 },
      length: 0,
      pipes: null,
      pipesCount: 0,
      flowing: true,
      ended: true,
      endEmitted: true,
      reading: false,
      sync: false,
      needReadable: false,
      emittedReadable: false,
      readableListening: false,
      resumeScheduled: false,
      emitClose: true,
      autoDestroy: false,
      destroyed: false,
      defaultEncoding: 'utf8',
      awaitDrain: 0,
      readingMore: false,
      decoder: null,
      encoding: null,
      [Symbol(kPaused)]: false
    },
    readable: false,
    _events: [Object: null prototype] {
      prefinish: [Function: prefinish],
      end: [Function],
      error: [Array],
      data: [Function]
    },
    _eventsCount: 4,
    _maxListeners: undefined,
    _writableState: WritableState {
      objectMode: false,
      highWaterMark: 16384,
      finalCalled: false,
      needDrain: false,
      ending: true,
      ended: true,
      finished: true,
      destroyed: false,
      decodeStrings: true,
      defaultEncoding: 'utf8',
      length: 0,
      writing: false,
      corked: 0,
      sync: false,
      bufferProcessing: false,
      onwrite: [Function: bound onwrite],
      writecb: null,
      writelen: 0,
      afterWriteTickInfo: null,
      bufferedRequest: null,
      lastBufferedRequest: null,
      pendingcb: 0,
      prefinished: true,
      errorEmitted: false,
      emitClose: true,
      autoDestroy: false,
      bufferedRequestCount: 0,
      corkedRequestsFree: [Object]
    },
    writable: false,
    allowHalfOpen: true,
    _transformState: {
      afterTransform: [Function: bound afterTransform],
      needTransform: false,
      transforming: false,
      writecb: null,
      writechunk: null,
      writeencoding: 'buffer'
    },
    _hadError: false,
    bytesWritten: 113,
    _handle: null,
    _outBuffer: <Buffer 7b 0a 20 20 22 65 72 72 6f 72 22 3a 20 7b 0a 20 20 20 20 22 63 6f 64 65 22 3a 20 34 30 33 2c 0a 20 20 20 20 22 6d 65 73 73 61 67 65 22 3a 20 22 55 73 ... 16334 more bytes>,
    _outOffset: 111,
    _chunkSize: 16384,
    _defaultFlushFlag: 2,
    _finishFlushFlag: 2,
    _defaultFullFlushFlag: 3,
    _info: undefined,
    _level: -1,
    _strategy: 0,
    statusCode: 403,
    statusMessage: 'Forbidden',
    request: {
      agent: [Agent],
      headers: [Object],
      href: 'https://clouderrorreporting.googleapis.com/v1beta1/projects/trash/events:report?'
    },
    body: '{\n' +
      '  "error": {\n' +
      '    "code": 403,\n' +
      '    "message": "User not authorized.",\n' +
      '    "status": "PERMISSION_DENIED"\n' +
      '  }\n' +
      '}\n',
    headers: {
      'alt-svc': 'h3-Q050=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"',
      'cache-control': 'private',
      'content-encoding': 'gzip',
      'content-type': 'application/json; charset=UTF-8',
      date: 'Mon, 26 Oct 2020 19:47:56 GMT',
      server: 'ESF',
      'transfer-encoding': 'chunked',
      vary: 'Origin, X-Origin, Referer',
      'x-content-type-options': 'nosniff',
      'x-frame-options': 'SAMEORIGIN',
      'x-xss-protection': '0'
    },
    toJSON: [Function: toJSON],
    [Symbol(kCapture)]: false
  },
  message: 'User not authorized.'
}

I would assume that either utilizing a callback or setting the logLevel to 0 would prevent this error from being printed. My app logs using JSON format, and when this message is printed it clutters the logs with a bunch of statements that aren't independently useful.

[freelerobot]

Hi @chadjaros , I reproduced your issue with the snippet:

const errors = new ErrorReporting(
    {
      projectId: 'trash',
      reportMode: 'always',
    }
);

// This line (A) writes the error message to error-reporting api
errors.report("this is an error message", (err) => {
  if (err) {
    // This line (B) specifies how your code handles any issues with calling the error-reporting api
    console.log('Failed to report error', err);
  }
});

Line B is where you configured the library to log any failed error-reporting API calls to your stderr stream. If you don't want errors caused by using this library emitted, just omit this line. Or better yet, write them to a different logstream (e.g. a local file or something).

Setting logLevel to 0 only controls what logs are written (via line A) & sent to the error-reporting API. It has nothing to do with console.log logstream.

[chadjaros]

Thanks for looking at this @nicoleczhu

The problem is that if you comment out the line console.log('Failed to report error', err);, the error is still printed to console - stderr specifically. The code snippet above results in the error being printed twice, once to stdout and once to stderr.

[freelerobot]

Ah yes, I was able to reproduce this. Yes, this library should let users reconfigure where library-originated errors are emitted. Marking this as a feature request. Thank you for making us aware of this.

There's actually a WIP here: https://github.com/feywind/node-debug-logging that might be applied across all libraries to standardize library debug/logging. Will adapt any solutions here once that's finalized.

[chadjaros]

I really like the pattern that SLF4J uses, and a similar thing can be built in JS. We've built a package like this where I work and it's very flexible. Unfortunately nothing like this is open source and widely adopted in JS/TS yet.