search

spdy-http2 / node-spdy

SPDY server on Node.js
2.81k stars 196 forks source link

Bug in node-spdy agent code #281

Closed anandsuresh closed 7 years ago

anandsuresh commented 7 years ago

Consider the following test code:

const https = require('https');
const spdy = require('spdy');
const agent = new spdy.Agent({
  host: 'api.development.push.apple.com',
  port: 443
});
const data = JSON.stringify({
  aps: {
    'alert': 'APNS notification alert message'
  },
  payload: {
    data: 'my data blob'
  }
});

var body = '';
https.request({
  agent: agent,
  method: 'POST',
  endpoint: 'api.development.push.apple.com',
  path: '/3/device/some_unknown_device_id',
  headers: {
    'content-type': 'application/json',
    'content-length': data.length,
    'apns-topic': 'com.apple'
  },
  data: data
}, function(res) {
  console.log('Success! StatusCode: %d, Headers: %j', res.statusCode, res.headers);

  res.on('data', function(chunk) {
    body += chunk;
    console.log('Received data event: %s', body);
  }).on('end', function() {
    console.log('Received end event: %s', body);
  }).on('error', function(err) {
    console.log('Received error event: %s', body);
  }).on('aborted', function() {
    console.log('Received aborted event: %s', body);
  });
}).on('error', function(err) {
  console.log('Request Error: %s', err);
}).end();

setTimeout(process.exit, 5000);

I then run the test code with 2 different versions of node, namely v4.5.0 and v6.7.0. Here is the output from the test runs:

anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $ npm install spdy
/Users/anand/github/tmp/spdy-agent-test
└── spdy@3.4.2

npm WARN enoent ENOENT: no such file or directory, open '/Users/anand/github/tmp/spdy-agent-test/package.json'
npm WARN spdy-agent-test No description
npm WARN spdy-agent-test No repository field.
npm WARN spdy-agent-test No README data
npm WARN spdy-agent-test No license field.
anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $ nvm use v4.5.0
Now using node v4.5.0 (npm v3.3.10)
anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $ DEBUG="spdy:*" NODE_DEBUG=https,http,net node test.js
HTTPS 75423: createConnection { NPNProtocols: [ 'h2', 'spdy/3.1', 'spdy/3', 'spdy/2', 'http/1.1', 'http/1.0' ],
  ALPNProtocols: [ 'h2', 'spdy/3.1', 'spdy/3', 'spdy/2', 'http/1.1', 'http/1.0' ],
  servername: 'api.development.push.apple.com',
  port: 443,
  host: 'api.development.push.apple.com' }
NET 75423: pipe false undefined
NET 75423: connect: find host api.development.push.apple.com
NET 75423: connect: dns options { family: undefined, hints: 3072 }
HTTP 75423: call onSocket 0 0
NET 75423: _read
NET 75423: Socket._read readStart
HTTP 75423: outgoing message end.
NET 75423: _read
NET 75423: _read wait for connection
NET 75423: onSocketFinish
NET 75423: oSF: not ended, call shutdown()
NET 75423: afterConnect
NET 75423: _read
NET 75423: Socket._read readStart
  spdy:client activating fallback +0ms
NET 75423: destroy undefined
NET 75423: destroy
NET 75423: close
NET 75423: close handle
NET 75423: emit close

When testing with node v4.5.0, the test exits after activating fallback mode. My theory here is that the fallback is activated because node v4.5.0 does not support ALPN extensions, while the Apple Push Notification Service doesn’t support NPN extension. In the absence of a common extension to negotiate the application-level protocol, the node-spdy agent activates fallback mode. Given that ALPN support was added in node v5, all prior versions will encounter this problem and activate fallback mode, with the result that node-spdy cannot be used with ALPN-only servers while running < node v5. #280 allows the developer to specify an optional protocol in such cases and proceed. In the absence of a specified protocol, it activates the fallback when no protocol is specified.

Moving on to testing with node v6.7.0, I get the following:

anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $ nvm use v6.7.0
Now using node v6.7.0 (npm v3.10.3)
anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $ DEBUG="spdy:*" NODE_DEBUG=https,http,net node test.js
HTTPS 75574: createConnection { NPNProtocols: [ 'h2', 'spdy/3.1', 'spdy/3', 'spdy/2', 'http/1.1', 'http/1.0' ],
  ALPNProtocols: [ 'h2', 'spdy/3.1', 'spdy/3', 'spdy/2', 'http/1.1', 'http/1.0' ],
  servername: 'api.development.push.apple.com',
  port: 443,
  host: 'api.development.push.apple.com' }
NET 75574: pipe false undefined
NET 75574: connect: find host api.development.push.apple.com
NET 75574: connect: dns options { family: undefined, hints: 1024 }
HTTP 75574: call onSocket 0 0
NET 75574: _read
NET 75574: Socket._read readStart
HTTP 75574: outgoing message end.
NET 75574: _read
NET 75574: _read wait for connection
NET 75574: onSocketFinish
NET 75574: oSF: not ended, call shutdown()
NET 75574: afterConnect
NET 75574: _read
NET 75574: Socket._read readStart
  spdy:client connected protocol="h2" +0ms
  spdy:priority add node=0 parent=-1 weight=1 exclusive=0 +2ms
  spdy:window:client id=0 side=recv setMax=1048576 +2ms
  spdy:connection:client id=0 version=4 +3ms
  spdy:framer preface +1ms
  spdy:scheduler queue sync +0ms [ <Buffer 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a> ]
  spdy:framer id=0 type=SETTINGS +1ms
  spdy:scheduler queue sync +2ms [ <Buffer 00 00 12 04 00 00 00 00 00>,
  <Buffer 00 02 00 00 00 01 00 04 00 10 00 00 00 06 00 01 40 00> ]
  spdy:connection:client id=0 session window drain, update by 983041 +0ms
  spdy:framer id=0 type=WINDOW_UPDATE +1ms
  spdy:scheduler queue sync +0ms [ <Buffer 00 00 04 08 00 00 00 00 00>, <Buffer 00 0f 00 01> ]
  spdy:window:client id=0 side=recv update by=983041 [1048576/1048576] +0ms
  spdy:priority creating default node +1ms
  spdy:priority add node=1 parent=0 weight=16 exclusive=0 +0ms
  spdy:connection:client id=0 add stream=1 +1ms
  spdy:framer:extra compressing headers=[{"name":":method","value":"POST"},{"name":":path","value":"/3/device/some_unknown_device_id"},{"name":":scheme","value":"https"},{"name":":authority","value":"api.development.push.apple.com"},{"name":"content-type","value":"application/json","neverIndex":false,"huffman":true},{"name":"content-length","value":"85","neverIndex":false,"huffman":true},{"name":"apns-topic","value":"com.apple","neverIndex":false,"huffman":true}] +1ms
  spdy:scheduler tick sync pending=5 +4ms [ <Buffer 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a> ]
  spdy:scheduler after tick sync pending=4 +0ms
  spdy:scheduler tick sync pending=4 +0ms [ <Buffer 00 00 12 04 00 00 00 00 00>,
  <Buffer 00 02 00 00 00 01 00 04 00 10 00 00 00 06 00 01 40 00> ]
  spdy:scheduler after tick sync pending=2 +1ms
  spdy:scheduler tick sync pending=2 +0ms [ <Buffer 00 00 04 08 00 00 00 00 00>, <Buffer 00 0f 00 01> ]
  spdy:scheduler after tick sync pending=0 +1ms
  spdy:framer id=1 type=HEADERS +1ms
  spdy:scheduler queue sync +1ms [ <Buffer 00 00 5a 01 24 00 00 00 01>,
  <Buffer 00 00 00 00 0f 83 44 97 61 96 24 2f 73 10 ac 20 f4 96 2b 6a eb 51 fc 55 14 85 ee 62 16 23 49 87 41 96 1d 66 5e 42 f7 2d 07 ae 92 d4 95 eb b5 13 ae 3a ... >,
  <Buffer 3d 4c 74 41 ea 5c 82 79 bf 40 87 1d 75 21 64 9e b3 13 87 21 e9 5c 75 d7 41 7f> ]
  spdy:scheduler tick sync pending=3 +0ms [ <Buffer 00 00 5a 01 24 00 00 00 01>,
  <Buffer 00 00 00 00 0f 83 44 97 61 96 24 2f 73 10 ac 20 f4 96 2b 6a eb 51 fc 55 14 85 ee 62 16 23 49 87 41 96 1d 66 5e 42 f7 2d 07 ae 92 d4 95 eb b5 13 ae 3a ... >,
  <Buffer 3d 4c 74 41 ea 5c 82 79 bf 40 87 1d 75 21 64 9e b3 13 87 21 e9 5c 75 d7 41 7f> ]
  spdy:scheduler after tick sync pending=0 +0ms
NET 75574: afterWrite 0
NET 75574: afterWrite call cb
  spdy:framer id=1 type=DATA +1ms
  spdy:window:client id=0 side=send update by=0 [65535/65535] +0ms
NET 75574: afterShutdown destroyed=false ReadableState {
  objectMode: false,
  highWaterMark: 16384,
  buffer: BufferList { head: null, tail: null, length: 0 },
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: true,
  ended: false,
  endEmitted: false,
  reading: true,
  sync: false,
  needReadable: true,
  emittedReadable: false,
  readableListening: false,
  resumeScheduled: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }
  spdy:scheduler queue async priority=1 stream=1 +2ms [ <Buffer 00 00 00 00 01 00 00 00 01> ]
  spdy:scheduler tick async index=0 start=1 +0ms
  spdy:scheduler tick async pending=1 +0ms [ <Buffer 00 00 00 00 01 00 00 00 01> ]
  spdy:scheduler after tick pending=0 +0ms
NET 75574: onread 33
NET 75574: got data
NET 75574: _read
  spdy:connection:client id=0 frame +3ms { type: 'SETTINGS',
  settings:
   { header_table_size: 4096,
     max_concurrent_streams: 1,
     max_frame_size: 16384,
     max_header_list_size: 8000 } }
  spdy:framer id=0 type=SETTINGS +0ms
  spdy:scheduler queue sync +0ms [ <Buffer 00 00 00 04 01 00 00 00 00> ]
  spdy:scheduler tick sync pending=1 +1ms [ <Buffer 00 00 00 04 01 00 00 00 00> ]
  spdy:scheduler after tick sync pending=0 +0ms
NET 75574: afterWrite 0
NET 75574: afterWrite call cb
NET 75574: afterWrite 0
NET 75574: afterWrite call cb
NET 75574: onread 9
NET 75574: got data
NET 75574: _read
  spdy:connection:client id=0 frame +66ms { type: 'ACK_SETTINGS' }
NET 75574: onread 9
NET 75574: got data
NET 75574: _read
NET 75574: onread 41
NET 75574: got data
NET 75574: _read
  spdy:connection:client id=0 frame +3ms { type: 'HEADERS',
  id: 1,
  priority: { parent: 0, exclusive: false, weight: 16 },
  fin: false,
  writable: true,
  headers:
   { ':status': '403',
     'apns-id': 'C7F9C05B-1C02-54E1-200B-F465F422CD97' },
  path: undefined }
HTTP 75574: AGENT incoming response!
HTTP 75574: AGENT isHeadResponse false
Success! StatusCode: 403, Headers: {"apns-id":"C7F9C05B-1C02-54E1-200B-F465F422CD97"}
NET 75574: onread 9
NET 75574: got data
NET 75574: _read
NET 75574: onread 33
NET 75574: got data
  spdy:window:client id=0 side=recv update by=-33 [1048543/1048576] +4ms
  spdy:connection:client id=0 frame +0ms { type: 'DATA',
  id: 1,
  fin: true,
  data: <Buffer 7b 22 72 65 61 73 6f 6e 22 3a 22 4d 69 73 73 69 6e 67 50 72 6f 76 69 64 65 72 54 6f 6b 65 6e 22 7d> }
  spdy:stream:client id=1 recv=33 +0ms
  spdy:window:client id=1 side=recv update by=-33 [1048543/1048576] +1ms
NET 75574: onread 33
NET 75574: got data
Received data event: {"reason":"MissingProviderToken"}
NET 75574: _read
  spdy:stream:client id=1 end +0ms
NET 75574: _read
  spdy:connection:client id=0 remove stream=1 +1ms
NET 75574: onread -4095
NET 75574: EOF
NET 75574: destroy undefined
NET 75574: destroy
NET 75574: close
NET 75574: close handle
  spdy:stream:client id=1 already closed +1ms
NET 75574: onSocketEnd ReadableState {
  objectMode: false,
  highWaterMark: 16384,
  buffer: BufferList { head: null, tail: null, length: 0 },
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: true,
  ended: true,
  endEmitted: false,
  reading: false,
  sync: false,
  needReadable: false,
  emittedReadable: false,
  readableListening: false,
  resumeScheduled: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }
NET 75574: destroy undefined
NET 75574: destroy
NET 75574: already destroyed, fire error callbacks
NET 75574: emit close
HTTP 75574: HTTP socket close
Received aborted event: {"reason":"MissingProviderToken"}
NET 75574: destroy undefined
NET 75574: destroy
NET 75574: already destroyed, fire error callbacks
Received end event: {"reason":"MissingProviderToken"}
anand@Anands-MacBook-Pro:~/github/tmp/spdy-agent-test $

When testing with node v6.7.0, because of the presence of ALPN extensions, the code is able to successfully connect to the APNS server and negotiate the use of the http/2 protocol. However, right after that, is a bug wherein the response fires data, aborted and end events in that sequence. The aborted event causes an otherwise successful response (granted that it returned a 403, but that is a valid HTTP response given that we've not specified any certificate or private key for the agent) to fail.

Searching the node-spdy and related code-bases, I came across https://github.com/indutny/node-spdy/blob/master/lib/spdy/handle.js#L55-L58. Nowhere in any of the code paths executed is state.ending set to true, resulting in the request being aborted.