Noisy output from HTTP2 stack

[sffc]

Node.js appears to be configured to print noisy debug output from http2 to stderr, and there is no way to suppress these messages. I originally filed this bug as googleapis/nodejs-logging#668, and was pointed to NodeSource, where I filed nodesource/distributions#995, and they ultimately pointed me here, which is why I'm filing this issue.

Steps to reproduce:

Install Node.js 10.x on Centos 8 from the NodeSource repository (consider starting from a cleanroom environment like the centos:centos8 dockerhub image):

$ curl -sL https://rpm.nodesource.com/setup_10.x | bash -
$ sudo yum install -y nodejs

Note: this also reproduces on the 12.x stream, and according to nodesource/distributions#995 (comment), this also reproduces in other builds of Node.js, not just NodeSource.

Run the following Node.js program from googleapis/nodejs-logging#668 (comment):

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();

Expected: There should be nothing logged to standard error.

Actual: A lot of messages are printed, such as:

send: reset nghttp2_active_outbound_item
send: aob->item = (nil)
stream: adjusting kept idle streams num_idle_streams=0, max=100
stream: adjusting kept idle streams num_idle_streams=0, max=100
send: end transmission of client magic
send: reset nghttp2_active_outbound_item
send: aob->item = (nil)
send: next frame: payloadlen=0, type=4, flags=0x00, stream_id=0
send: start transmitting frame type=4, length=9
stream: adjusting kept idle streams num_idle_streams=0, max=100
send: end transmission of a frame
send: reset nghttp2_active_outbound_item
send: aob->item = 0x5652b4afcfc8
stream: dep_add dep_stream(0x5652b4af38b8)=0, stream(0x5652b4af2f28)=1
deflatehd: deflating :scheme: https
deflatehd: name/value match index=6
deflatehd: emit indexed index=6, 1 bytes
deflatehd: deflating :authority: www.google.com:443
deflatehd: name match index=0
...
inflatehd: 11 bytes read
inflatehd: header emission: vary: Accept-Encoding
recv: proclen=13
inflatehd: start state=2
inflatehd: all input bytes were processed
inflatehd: in_final set
recv: proclen=0
stream: adjusting kept idle streams num_idle_streams=0, max=100
recv: connection recv_window_size=0, local_window=65535
...
recv: [IB_READ_HEAD]
recv: payloadlen=8, type=6, flags=0x00, stream_id=0
recv: PING
recv: [IB_READ_NBYTE]
recv: readlen=8, payloadleft=0, left=0
send: reset nghttp2_active_outbound_item
send: aob->item = (nil)

System info:

[sffc@oo-back6t ~]$ node -v
v10.16.3
[sffc@oo-back6t ~]$ uname -a
Linux oo-back6t 4.18.0-80.11.2.el8_0.x86_64 #1 SMP Tue Sep 24 11:32:19 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
[sffc@oo-back6t ~]$ sudo yum info nodejs
Last metadata expiration check: 2:27:35 ago on Thu 13 Feb 2020 04:24:37 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.

[mscdex]

FWIW I just tested this on Linux with node built from source and did not get any extra output like you're showing.

Judging by the nghttp2 source code, it looks like debug information is only printed to stderr when nghttp2 is built with the DEBUGBUILD macro defined or --enable-debug is passed to nghttp2's ./configure. This would only matter if node was built against a shared nghttp2 library though.

The only other way DEBUGBUILD could be defined is if the built-in copy of nghttp2 from node was used and --debug-nghttp2 was passed to node's ./configure.

Looking at nodejs.spec from nodejs-10.16.3-2.module_el8.0.0+186+542b25fc.src.rpm I see the following:

#%if ! 0%%{?bootstrap}
%if %{with bootstrap}
./configure --prefix=%{_prefix}
--shared-openssl
--shared-zlib
--without-dtrace
--with-intl=small-icu
--debug-nghttp2
--openssl-use-def-ca-store
%else
./configure --prefix=%{_prefix}
--shared-openssl
--shared-zlib
--shared-libuv
--shared-http-parser
--shared-nghttp2
--with-dtrace
--with-intl=%{icu_flag}
--debug-nghttp2
--openssl-use-def-ca-store
%endif

As you can see, the --debug-nghttp2 is being passed, which is the cause of the debug output. So this issue needs to be raised with the CentOS package maintainers (or whoever maintains the "AppStream" repo).

[sffc]

Thanks for the info; I should have thought about looking at the rpm spec sooner! I filed an issue on the CentOS bug tracker, which is the best place I could find to report an issue in AppStream:

https://bugs.centos.org/view.php?id=17047