http2 pushPromise in 10.2.0+ #20992

bathos · 2018-05-28T02:35:24Z

Version: 10.2.0 and 10.2.1
Platform: OS X
Subsystem: http2

I’m afraid I may not be able to describe this well; a lot of HTTP2 stuff goes over my head. I’m aware this module is experimental, so it’s possible that there is an intentional but undocumented API or behavior change in play, but my gut says this is probably a bug.

When running the same code using HTTP2 without the compatibility API in 10.1.0 and 10.2.0 (or 10.2.1), I observe very different results (using chrome://net-internals to observe the back-and-forth) with an end result of no push promise adoption. No errors are thrown — I’ve found nothing observably different in the application — and I’m not at all sure what specifically accounts for the difference in behavior, but it was replicable across two different applications using the HTTP2 module and was consistent in Chrome and Firefox.

tl;dr: since 10.2.0, it seems like push promises stopped working

I’ve tried to put together the most minimal reproduction I could since I don’t have much else to offer for debugging this, though I don’t know of any way to test this that doesn’t involve certs:

const fs = require('fs');
const http2 = require('http2');
const path = require('path');

const SSL_CERT_PATH = path.resolve(__dirname, 'XXXXXXXXX.crt');
const SSL_KEY_PATH  = path.resolve(__dirname, 'XXXXXXXXX.key');
const HTTPS_PORT = XXXX;

const DEPENDENCY = {
  data: Buffer.from(`body { background: red; }`),
  path: '/dep',
  type: 'text/css',
  pushAssets: []
};

const DOCUMENT = {
  data: Buffer.from(`<!DOCTYPE html><link rel="stylesheet" href="/dep">`),
  path: '/',
  type: 'text/html',
  pushAssets: [ DEPENDENCY ]
};

const server = http2.createSecureServer({
  key: fs.readFileSync(SSL_KEY_PATH),
  cert: fs.readFileSync(SSL_CERT_PATH)
});

const serveAsset = (stream, asset) => {
  stream.respond({
    [http2.constants.HTTP2_HEADER_STATUS]: http2.constants.HTTP_STATUS_OK,
    [http2.constants.HTTP2_HEADER_CONTENT_LENGTH]: asset.data.length,
    [http2.constants.HTTP2_HEADER_CONTENT_TYPE]: asset.type
  });

  for (const pushAsset of asset.pushAssets) {
    stream.pushStream({
      [http2.constants.HTTP2_HEADER_PATH]: pushAsset.path
    }, (err, stream, h) => {
      if (err) return console.log(err);

      stream.respond({
        [http2.constants.HTTP2_HEADER_STATUS]: http2.constants.HTTP_STATUS_OK,
        [http2.constants.HTTP2_HEADER_CONTENT_LENGTH]: pushAsset.data.length,
        [http2.constants.HTTP2_HEADER_CONTENT_TYPE]: pushAsset.type
      });

      stream.end(pushAsset.data);
    });
  }

  stream.end(asset.data);
};

server.on('stream', (stream, reqHeaders) => {
  switch (reqHeaders[http2.constants.HTTP2_HEADER_PATH]) {
    case '/': return serveAsset(stream, DOCUMENT);
    case '/dep': return serveAsset(stream, DEPENDENCY);
  }
});

server.listen(HTTPS_PORT);

If we run this in Node 10.1.0, the dependency’s push promise is adopted.

Transcript (Node 10.1.0)

25756: HTTP2_SESSION
Start Time: 2018-05-27 22:24:12.292
t=4420 [st= 0]  HTTP2_SESSION_PING

--> is_ack = false

--> type = "sent"

--> unique_id = 1

t=4420 [st= 0]  HTTP2_SESSION_SEND_HEADERS

--> exclusive = true

--> fin = true

--> has_priority = true

--> :method: GET

:authority: snek.city:9443

:scheme: https

:path: /

pragma: no-cache

cache-control: no-cache

upgrade-insecure-requests: 1

user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36

accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8

accept-encoding: gzip, deflate, br

accept-language: en-US,en;q=0.9

--> parent_stream_id = 0

--> source_dependency = 25807 (HTTP_STREAM_JOB)

--> stream_id = 5

--> weight = 256

t=4420 [st= 0]  HTTP2_SESSION_RECV_HEADERS

--> fin = false

--> :status: 200

content-length: 50

content-type: text/html

date: Mon, 28 May 2018 02:24:12 GMT

--> stream_id = 5

t=4421 [st= 1]  HTTP2_SESSION_RECV_PUSH_PROMISE

--> :scheme: https

:authority: snek.city:9443

:method: GET

:path: /dep

--> id = 5

--> promised_stream_id = 6

t=4421 [st= 1]  HTTP2_STREAM_SEND_PRIORITY

--> exclusive = true

--> parent_stream_id = 5

--> stream_id = 6

--> weight = 110

t=4421 [st= 1]  HTTP2_SESSION_RECV_HEADERS

--> fin = false

--> :status: 200

content-length: 25

content-type: text/css

date: Mon, 28 May 2018 02:24:12 GMT

--> stream_id = 6

t=4421 [st= 1]  HTTP2_SESSION_RECV_DATA

--> fin = false

--> size = 50

--> stream_id = 5

t=4421 [st= 1]  HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = -50

--> window_size = 15728590

t=4421 [st= 1]  HTTP2_SESSION_RECV_DATA

--> fin = false

--> size = 25

--> stream_id = 6

t=4421 [st= 1]  HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = -25

--> window_size = 15728565

t=4421 [st= 1]  HTTP2_SESSION_PING

--> is_ack = true

--> type = "received"

--> unique_id = 1

t=4421 [st= 1]  HTTP2_SESSION_RECV_DATA

--> fin = true

--> size = 0

--> stream_id = 5

t=4421 [st= 1]  HTTP2_SESSION_RECV_DATA

--> fin = true

--> size = 0

--> stream_id = 6

t=4427 [st= 7]  HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 50

--> window_size = 15728615

t=4433 [st=13]  HTTP2_STREAM_ADOPTED_PUSH_STREAM

--> stream_id = 6

--> url = "https://snek.city:9443/dep"

t=4434 [st=14]  HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 25

--> window_size = 15728640

If we run this in either Node 10.2.0 or 10.2.1, instead the promise (which is seemingly received) is not adopted and the browser requests the dependency:

Transcript (Node 10.2.1)

26175: HTTP2_SESSION
snek.city:9443 (DIRECT)
Start Time: 2018-05-27 22:31:22.364
t=2704 [st= 0] +HTTP2_SESSION  [dt=?]

--> host = "snek.city:9443"

--> proxy = "DIRECT"

t=2704 [st= 0]    HTTP2_SESSION_INITIALIZED

--> protocol = "h2"

--> source_dependency = 26174 (SOCKET)

t=2704 [st= 0]    HTTP2_SESSION_SEND_SETTINGS

--> settings = ["[id:1 (SETTINGS_HEADER_TABLE_SIZE) value:65536]","[id:3 (SETTINGS_MAX_CONCURRENT_STREAMS) value:1000]","[id:4 (SETTINGS_INITIAL_WINDOW_SIZE) value:6291456]"]

t=2704 [st= 0]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 15663105

--> window_size = 15728640

t=2704 [st= 0]    HTTP2_SESSION_SEND_WINDOW_UPDATE

--> delta = 15663105

--> stream_id = 0

t=2704 [st= 0]    HTTP2_SESSION_SEND_HEADERS

--> exclusive = true

--> fin = true

--> has_priority = true

--> :method: GET

:authority: snek.city:9443

:scheme: https

:path: /

pragma: no-cache

cache-control: no-cache

upgrade-insecure-requests: 1

user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36

accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8

accept-encoding: gzip, deflate, br

accept-language: en-US,en;q=0.9

--> parent_stream_id = 0

--> source_dependency = 26170 (HTTP_STREAM_JOB)

--> stream_id = 1

--> weight = 256

t=2706 [st= 2]    HTTP2_SESSION_RECV_SETTINGS

t=2706 [st= 2]    HTTP2_SESSION_SEND_SETTINGS_ACK

t=2709 [st= 5]    HTTP2_SESSION_RECV_SETTINGS_ACK

t=2709 [st= 5]    HTTP2_SESSION_RECV_HEADERS

--> fin = false

--> :status: 200

content-length: 50

content-type: text/html

date: Mon, 28 May 2018 02:31:22 GMT

--> stream_id = 1

t=2709 [st= 5]    HTTP2_SESSION_RECV_PUSH_PROMISE

--> :scheme: https

:authority: snek.city:9443

:method: GET

:path: /dep

--> id = 1

--> promised_stream_id = 2

t=2709 [st= 5]    HTTP2_STREAM_SEND_PRIORITY

--> exclusive = true

--> parent_stream_id = 1

--> stream_id = 2

--> weight = 110

t=2709 [st= 5]    HTTP2_SESSION_RECV_HEADERS

--> fin = false

--> :status: 200

content-length: 25

content-type: text/css

date: Mon, 28 May 2018 02:31:22 GMT

--> stream_id = 2

t=2709 [st= 5]    HTTP2_SESSION_RECV_DATA

--> fin = false

--> size = 50

--> stream_id = 1

t=2709 [st= 5]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = -50

--> window_size = 15728590

t=2709 [st= 5]    HTTP2_SESSION_RECV_DATA

--> fin = false

--> size = 25

--> stream_id = 2

t=2709 [st= 5]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = -25

--> window_size = 15728565

t=2710 [st= 6]    HTTP2_SESSION_RECV_DATA

--> fin = true

--> size = 0

--> stream_id = 1

t=2711 [st= 7]    HTTP2_SESSION_RECV_RST_STREAM

--> error_code = "0 (NO_ERROR)"

--> stream_id = 2

t=2711 [st= 7]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 25

--> window_size = 15728590

t=2714 [st=10]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 50

--> window_size = 15728640

t=2722 [st=18]    HTTP2_SESSION_SEND_HEADERS

--> exclusive = true

--> fin = true

--> has_priority = true

--> :method: GET

:authority: snek.city:9443

:scheme: https

:path: /dep

pragma: no-cache

cache-control: no-cache

user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36

accept: text/css,/;q=0.1

referer: https://snek.city:9443/

accept-encoding: gzip, deflate, br

accept-language: en-US,en;q=0.9

--> parent_stream_id = 0

--> source_dependency = 26180 (HTTP_STREAM_JOB)

--> stream_id = 3

--> weight = 256

t=2723 [st=19]    HTTP2_SESSION_RECV_HEADERS

--> fin = false

--> :status: 200

content-length: 25

content-type: text/css

date: Mon, 28 May 2018 02:31:22 GMT

--> stream_id = 3

t=2723 [st=19]    HTTP2_SESSION_RECV_DATA

--> fin = false

--> size = 25

--> stream_id = 3

t=2723 [st=19]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = -25

--> window_size = 15728615

t=2723 [st=19]    HTTP2_SESSION_RECV_DATA

--> fin = true

--> size = 0

--> stream_id = 3

t=2724 [st=20]    HTTP2_SESSION_UPDATE_RECV_WINDOW

--> delta = 25

--> window_size = 15728640

Comparing the transcripts the first stand-out difference is (DIRECT). I don’t know what this means. But they’re so different altogether that I’m not sure what factors might be significant.

Apologies if I’m missing something painfully obvious.

The text was updated successfully, but these errors were encountered:

apapirovski · 2018-05-28T04:21:21Z

Chrome has a bug with self-signed certificates & push so I can't confirm there, but can confirm on Firefox & Safari. Looks like we introduced a bug when we fixed http2 not working in Safari & Edge.

Working on a fix.

Delay automatically closing the stream with setImmediate in order to allow any pushStreams to be sent first. PR-URL: #20997 Fixes: #20992 Reviewed-By: James M Snell <jasnell@gmail.com>

Delay automatically closing the stream with setImmediate in order to allow any pushStreams to be sent first. PR-URL: nodejs#20997 Fixes: nodejs#20992 Reviewed-By: James M Snell <jasnell@gmail.com>

Delay automatically closing the stream with setImmediate in order to allow any pushStreams to be sent first. Backport-PR-URL: #22850 PR-URL: #20997 Fixes: #20992 Reviewed-By: James M Snell <jasnell@gmail.com>

apapirovski added the confirmed-bug Issues with confirmed bugs. label May 28, 2018

apapirovski mentioned this issue May 28, 2018

http2: delay closing stream #20997

Closed

2 tasks

apapirovski closed this as completed in 87cd389 Jun 1, 2018

addaleax pushed a commit that referenced this issue Jun 1, 2018

http2: delay closing stream

2a9912c

Delay automatically closing the stream with setImmediate in order to allow any pushStreams to be sent first. PR-URL: #20997 Fixes: #20992 Reviewed-By: James M Snell <jasnell@gmail.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http2 pushPromise in 10.2.0+ #20992

http2 pushPromise in 10.2.0+ #20992

bathos commented May 28, 2018

apapirovski commented May 28, 2018

http2 pushPromise in 10.2.0+ #20992

http2 pushPromise in 10.2.0+ #20992

Comments

bathos commented May 28, 2018

apapirovski commented May 28, 2018