Skip to content

http2 pushPromise in 10.2.0+ #20992

New issue
Jump to bottom
New issue
Jump to bottom
Closed
Closed
http2 pushPromise in 10.2.0+#20992
Labels
confirmed-bugIssues with confirmed bugs.
@bathos

Description

@bathos
bathos
opened on May 28, 2018
  • 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.

screen shot 2018-05-27 at 10 23 58 pm

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:

screen shot 2018-05-27 at 10 31 24 pm

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.

Metadata

Assignees

No one assigned

    Labels

    confirmed-bugIssues with confirmed bugs.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions