Noisy output when uploading logs to Stackdriver

[sffc]

When calling functions that upload logs to the server, like .write(), a large amount of lines get written to standard out. Example:

...
stream: adjusting kept idle streams num_idle_streams=0, max=100
send: next frame: payloadlen=8, type=6, flags=0x00, stream_id=0
send: start transmitting frame type=6, length=17
stream: adjusting kept idle streams num_idle_streams=0, max=100
send: end transmission of a frame
send: reset nghttp2_active_outbound_item
...
deflatehd: deflating :scheme: https
deflatehd: name/value match index=6
deflatehd: emit indexed index=6, 1 bytes
deflatehd: deflating :path: /google.logging.v2.LoggingServiceV2/WriteLogEntries
deflatehd: name match index=3
deflatehd: emit indname index=3, valuelen=51, indexing_mode=1
deflatehd: emit string str=/google.logging.v2.LoggingServiceV2/WriteLogEntries, length=51, huffman=1, encoded_length=37
deflatehd: deflating :method: POST
deflatehd: name/value match index=2
deflatehd: emit indexed index=2, 1 bytes
...
inflatehd: decoded integer is 64
inflatehd: index=64
inflatehd: header emission: content-disposition: attachment
recv: proclen=1
inflatehd: start state=2
inflatehd: all input bytes were processed
inflatehd: in_final set
recv: proclen=0
...

I can't find a way to disable this noisy output. This is problematic because I need to control the standard out of my program.

Environment details

• OS: Centos 8
• Node.js version: v10.16.3
• npm version: 6.13.4
• @google-cloud/logging version: 6.0.0

Steps to reproduce

Run the example code that creates a log entry and writes it to Stackdriver

[stephenplusplus]

@callmehiphop @bcoe Is that gRPC making all that noise? Is there a way to disable whatever it is?

[bcoe]

@sffc what environment are you running this script in, the detailed output looks like logging that one would enable via an environment variable -- I actually don't recognize the logging from our gRPC library, looks like it's potentially coming directly from an HTTP2 library.

CC: @alexander-fenster @murgatroid99

[alexander-fenster]

It's coming from Node.js HTTP2 stack:

https://github.com/nodejs/node/blob/7ae13c360b3a6e3c843432312f7b6f4f137d3cb9/deps/nghttp2/lib/nghttp2_hd.c#L918

DEBUGF("deflatehd: emit table_size=%zu\n", table_size);

From those sources, it seems like the DEBUGF macro can only be enabled in compile time, when DEBUGBUILD flag is enabled:

https://github.com/nodejs/node/blob/8b4af64f50c5e41ce0155716f294c24ccdecad03/deps/nghttp2/lib/nghttp2_debug.h#L34-L41

#ifdef DEBUGBUILD
#define DEBUGF(...) nghttp2_debug_vprintf(__VA_ARGS__)
void nghttp2_debug_vprintf(const char *format, ...);
#else
#define DEBUGF(...)                                                            \
  do {                                                                         \
  } while (0)
#endif

So... the main question is, which version of Node.js do you use? Any chance it's a manually built version with debugging enabled, e.g. by using debug_nghttp2 option or setting DEBUGBUILD flag? (maybe you used a bazel build, or something like that?)

[sffc]

Thanks for the investigation!

I use Node.js from the NodeSource Centos repository:

https://github.com/nodesource/distributions/blob/master/README.md#enterprise-linux-based-distributions

$ sudo yum info nodejs
Last metadata expiration check: 2:54:53 ago on Wed 08 Jan 2020 05:30:50 AM UTC.
Installed Packages
Name         : nodejs
Epoch        : 1
Version      : 10.16.3
Release      : 2.module_el8.0.0+186+542b25fc
Arch         : x86_64
Size         : 44 M
Source       : nodejs-10.16.3-2.module_el8.0.0+186+542b25fc.src.rpm
Repo         : @System
From repo    : AppStream
Summary      : JavaScript runtime
URL          : http://nodejs.org/
License      : MIT and ASL 2.0 and ISC and BSD
Description  : Node.js is a platform built on Chrome's JavaScript runtime
             : for easily building fast, scalable network applications.
             : Node.js uses an event-driven, non-blocking I/O model that
             : makes it lightweight and efficient, perfect for data-intensive
             : real-time applications that run across distributed devices.

[alexander-fenster]

@sffc Thank you for confirming!

Can you please run this small sample (adapted from here) with your Node binary and see if it prints those debug messages? (you can compare with an official Node.js binary)

If it does, the problem should be reported to NodeSource.

Thank you!

const http2 = require('http2');
const client = http2.connect('https://www.google.com');
client.on('error', (err) => console.error(err));

const req = client.request({ ':path': '/' });

req.on('response', (headers, flags) => {
  for (const name in headers) {
    console.log(`${name}: ${headers[name]}`);
  }
});

req.setEncoding('utf8');
let data = '';
req.on('data', (chunk) => { data += chunk; });
req.on('end', () => {
  console.log(`\nReceived ${data.length} bytes of data.`);
  client.close();
});
req.end();

[sffc]

Filed an upstream issue: nodesource/distributions#995

Thanks for helping diagnose the problem!