A re-used client agent does not handle every second client request until the next one is made

acarstoiu commented 8 years ago

After quite some testing with the latest node-spdy version (3.3.3) in the view of sending Apple push notifications using their HTTP 2 API, I isolated this strange behaviour. Given an agent configured with the following options

    var agent = new spdy.Agent({
        host: "api.development.push.apple.com",
        port: 443,
        keepAlive: true,
        maxSockets: 1000,
        maxFreeSockets: 0,
        protocol: 'https:',
        cert: appleCert,
        key: appleKey,
        passphrase: applePassphrase,
        spdy: {
            protocols: ['h2'],
            maxStreams: 1000
        }
    });

the second attempt to send a notification is delayed until the third one is made, the fourth attempt until the fifth is made and so on. And it's not a callback timing problem; no, those notifications after the first one are really received in pairs on the destination Apple device.

Here is a full log for the first three requests, spaced at 30s (this interval is irrelevant, at 15s all happens the same):

>>> Sending request
  spdy:client connected protocol="h2" +0ms
  spdy:priority add node=0 parent=-1 weight=1 exclusive=0 +4ms
  spdy:window:client id=0 side=recv setMax=1048576 +3ms
  spdy:connection:client id=0 version=4 +6ms
  spdy:framer preface +2ms
  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 +3ms
  spdy:scheduler queue sync +3ms [ <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 +0ms
  spdy:scheduler queue sync +1ms [ <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 +3ms
  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/577fbe50ea6203aada59c5b6b6faf6137a63b1775132a5d64206b636fef03f53"},{"name":":scheme","value":"https"},{"name":":authority","value":"api.development.push.apple.com"},{"name":"apns-id","value":"87b9b3f4-f0b3-b288-94b8-1fda0d8aee5c","neverIndex":false,"huffman":true}] +3ms
  spdy:scheduler tick sync pending=5 +10ms [ <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 +1ms
  spdy:scheduler tick sync pending=4 +1ms [ <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 +0ms
  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 +4ms
  spdy:scheduler queue sync +1ms [ <Buffer 00 00 78 01 24 00 00 00 01>,
  <Buffer 00 00 00 00 0f 83 44 b5 61 96 24 2f 73 10 ac 36 eb b2 c6 56 c0 51 b8 20 32 31 c8 36 df 23 71 b9 1b 92 8e 57 02 cb a3 71 98 c2 eb ad 85 91 0d b9 1c 68 ... >,
  <Buffer 1d 66 5e 42 f7 2d 07 ae 92 d4 95 eb b5 13 ae 3a eb a0 ab 90 f4 ff 40 85 1d 75 21 63 49 9a 79 d8 df 8d 99 5a 5a 50 46 ca d1 89 e7 96 7d a8 de 58 32 c8 ... > ]
  spdy:scheduler tick sync pending=3 +0ms [ <Buffer 00 00 78 01 24 00 00 00 01>,
  <Buffer 00 00 00 00 0f 83 44 b5 61 96 24 2f 73 10 ac 36 eb b2 c6 56 c0 51 b8 20 32 31 c8 36 df 23 71 b9 1b 92 8e 57 02 cb a3 71 98 c2 eb ad 85 91 0d b9 1c 68 ... >,
  <Buffer 1d 66 5e 42 f7 2d 07 ae 92 d4 95 eb b5 13 ae 3a eb a0 ab 90 f4 ff 40 85 1d 75 21 63 49 9a 79 d8 df 8d 99 5a 5a 50 46 ca d1 89 e7 96 7d a8 de 58 32 c8 ... > ]
  spdy:scheduler after tick sync pending=0 +1ms
  spdy:stream:client id=1 presend=95 +1ms
  spdy:window:client id=1 side=send update by=-95 [65440/65535] +0ms
  spdy:stream:client id=1 send=95 +1ms
  spdy:framer id=1 type=DATA +1ms
  spdy:window:client id=0 side=send update by=-95 [65440/65535] +1ms
  spdy:scheduler queue async priority=1 stream=1 +0ms [ <Buffer 00 00 5f 00 00 00 00 00 01>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler tick async index=0 start=1 +0ms
  spdy:scheduler tick async pending=2 +4ms [ <Buffer 00 00 5f 00 00 00 00 00 01>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler after tick pending=0 +1ms
  spdy:stream:client id=1 postsend=95 +0ms
  spdy:framer id=1 type=DATA +2ms
  spdy:window:client id=0 side=send update by=0 [65440/65535] +0ms
  spdy:scheduler queue async priority=1 stream=1 +1ms [ <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 +1ms
  spdy:connection:client id=0 frame +6ms { type: 'SETTINGS',
  settings: 
   { header_table_size: 4096,
     max_concurrent_streams: 500,
     max_frame_size: 16384,
     max_header_list_size: 8000 } }
  spdy:framer id=0 type=SETTINGS +1ms
  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 +1ms
  spdy:client connected protocol="h2" +1ms
  spdy:priority add node=0 parent=-1 weight=1 exclusive=0 +1ms
  spdy:window:client id=0 side=recv setMax=1048576 +1ms
  spdy:connection:client id=0 version=4 +3ms
  spdy:framer preface +0ms
  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 cached settings +1ms
  spdy:scheduler queue sync +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:connection:client id=0 session window drain, update by 983041 +0ms
  spdy:framer id=0 type=WINDOW_UPDATE +0ms
  spdy:scheduler queue sync +1ms [ <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:scheduler tick sync pending=5 +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:scheduler after tick sync pending=4 +2ms
  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 +0ms
  spdy:connection:client id=0 frame +1ms { type: 'SETTINGS',
  settings: 
   { header_table_size: 4096,
     max_concurrent_streams: 500,
     max_frame_size: 16384,
     max_header_list_size: 8000 } }
  spdy:framer id=0 type=SETTINGS +1ms
  spdy:scheduler queue sync +2ms [ <Buffer 00 00 00 04 01 00 00 00 00> ]
  spdy:scheduler tick sync pending=1 +0ms [ <Buffer 00 00 00 04 01 00 00 00 00> ]
  spdy:scheduler after tick sync pending=0 +1ms
  spdy:connection:client id=0 frame +187ms { type: 'ACK_SETTINGS' }
  spdy:connection:client id=0 frame +7ms { type: 'HEADERS',
  id: 1,
  priority: { parent: 0, exclusive: false, weight: 16 },
  fin: true,
  writable: true,
  headers: 
   { ':status': '200',
     'apns-id': '87b9b3f4-f0b3-b288-94b8-1fda0d8aee5c' },
  path: undefined }
>>> Response status code 200
  spdy:stream:client id=1 end +5ms
  spdy:connection:client id=0 remove stream=1 +1ms
  spdy:stream:client id=1 already closed +3ms
  spdy:connection:client id=0 frame +11ms { type: 'ACK_SETTINGS' }

>>> Sending request
  spdy:priority creating default node +29s
  spdy:priority add node=3 parent=0 weight=16 exclusive=0 +0ms
  spdy:connection:client id=0 add stream=3 +1ms
  spdy:framer:extra compressing headers=[{"name":":method","value":"POST"},{"name":":path","value":"/3/device/577fbe50ea6203aada59c5b6b6faf6137a63b1775132a5d64206b636fef03f53"},{"name":":scheme","value":"https"},{"name":":authority","value":"api.development.push.apple.com"},{"name":"apns-id","value":"8e375b9a-0e99-aa7e-a320-d6ad41958dbd","neverIndex":false,"huffman":true}] +0ms

  spdy:framer id=3 type=HEADERS +30s
  spdy:scheduler queue sync +0ms [ <Buffer 00 00 25 01 24 00 00 00 03>,
  <Buffer 00 00 00 00 0f 83 c0 87 bf 7e 9a 78 ac ba dc 6f 8d 60 15 f7 d6 18 dd 2a c3 64 40 5a 47 07 23 41 7d b7 a4 8e 4f> ]
  spdy:scheduler tick sync pending=2 +1ms [ <Buffer 00 00 25 01 24 00 00 00 03>,
  <Buffer 00 00 00 00 0f 83 c0 87 bf 7e 9a 78 ac ba dc 6f 8d 60 15 f7 d6 18 dd 2a c3 64 40 5a 47 07 23 41 7d b7 a4 8e 4f> ]
  spdy:scheduler after tick sync pending=0 +0ms
  spdy:stream:client id=3 presend=95 +0ms
  spdy:window:client id=3 side=send update by=-95 [65440/65535] +1ms
  spdy:stream:client id=3 send=95 +0ms
  spdy:framer id=3 type=DATA +0ms
  spdy:window:client id=0 side=send update by=-95 [65345/65535] +0ms
  spdy:scheduler queue async priority=0.5 stream=3 +0ms [ <Buffer 00 00 5f 00 00 00 00 00 03>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler tick async index=0 start=0.5 +4ms
  spdy:scheduler tick async pending=2 +0ms [ <Buffer 00 00 5f 00 00 00 00 00 03>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler after tick pending=0 +0ms
  spdy:stream:client id=3 postsend=95 +0ms
  spdy:framer id=3 type=DATA +1ms
  spdy:window:client id=0 side=send update by=0 [65345/65535] +0ms
  spdy:scheduler queue async priority=0.5 stream=3 +0ms [ <Buffer 00 00 00 00 01 00 00 00 03> ]
  spdy:scheduler tick async index=0 start=0.5 +0ms
  spdy:scheduler tick async pending=1 +0ms [ <Buffer 00 00 00 00 01 00 00 00 03> ]
  spdy:scheduler after tick pending=0 +0ms
>>> Sending request
  spdy:priority creating default node +6ms
  spdy:priority add node=5 parent=0 weight=16 exclusive=0 +0ms
  spdy:connection:client id=0 add stream=5 +1ms
  spdy:framer:extra compressing headers=[{"name":":method","value":"POST"},{"name":":path","value":"/3/device/577fbe50ea6203aada59c5b6b6faf6137a63b1775132a5d64206b636fef03f53"},{"name":":scheme","value":"https"},{"name":":authority","value":"api.development.push.apple.com"},{"name":"apns-id","value":"8e2e626e-2354-90db-a69d-fb59fcb5527c","neverIndex":false,"huffman":true}] +0ms
  spdy:framer id=5 type=HEADERS +206ms
  spdy:scheduler queue sync +1ms [ <Buffer 00 00 25 01 24 00 00 00 05>,
  <Buffer 00 00 00 00 0f 83 c1 87 c0 7e 9a 78 a2 2b 82 70 ab 09 96 da 59 f0 49 1a c3 71 f9 16 96 36 df 94 91 b6 d8 9d 27> ]
  spdy:scheduler tick sync pending=2 +0ms [ <Buffer 00 00 25 01 24 00 00 00 05>,
  <Buffer 00 00 00 00 0f 83 c1 87 c0 7e 9a 78 a2 2b 82 70 ab 09 96 da 59 f0 49 1a c3 71 f9 16 96 36 df 94 91 b6 d8 9d 27> ]
  spdy:scheduler after tick sync pending=0 +0ms
  spdy:stream:client id=5 presend=95 +0ms
  spdy:window:client id=5 side=send update by=-95 [65440/65535] +1ms
  spdy:stream:client id=5 send=95 +0ms
  spdy:framer id=5 type=DATA +0ms
  spdy:window:client id=0 side=send update by=-95 [65250/65535] +0ms
  spdy:scheduler queue async priority=0.33333333333333337 stream=5 +0ms [ <Buffer 00 00 5f 00 00 00 00 00 05>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler tick async index=0 start=0.33333333333333337 +0ms
  spdy:scheduler tick async pending=2 +0ms [ <Buffer 00 00 5f 00 00 00 00 00 05>,
  <Buffer 7b 22 61 22 3a 31 2c 22 62 22 3a 74 72 75 65 2c 22 61 70 73 22 3a 7b 22 63 6f 6e 74 65 6e 74 2d 61 76 61 69 6c 61 62 6c 65 22 3a 31 2c 22 61 6c 65 72 ... > ]
  spdy:scheduler after tick pending=0 +1ms
  spdy:stream:client id=5 postsend=95 +0ms
  spdy:framer id=5 type=DATA +0ms
  spdy:window:client id=0 side=send update by=0 [65250/65535] +0ms
  spdy:scheduler queue async priority=0.33333333333333337 stream=5 +1ms [ <Buffer 00 00 00 00 01 00 00 00 05> ]
  spdy:scheduler tick async index=0 start=0.33333333333333337 +0ms
  spdy:scheduler tick async pending=1 +0ms [ <Buffer 00 00 00 00 01 00 00 00 05> ]
  spdy:scheduler after tick pending=0 +0ms
  spdy:connection:client id=0 frame +1ms { type: 'HEADERS',
  id: 3,
  priority: { parent: 0, exclusive: false, weight: 16 },
  fin: true,
  writable: true,
  headers: 
   { ':status': '200',
     'apns-id': '8e375b9a-0e99-aa7e-a320-d6ad41958dbd' },
  path: undefined }
>>> Response status code 200
  spdy:stream:client id=3 end +5ms
  spdy:connection:client id=0 remove stream=3 +1ms
  spdy:stream:client id=3 already closed +0ms
  spdy:connection:client id=0 frame +212ms { type: 'HEADERS',
  id: 5,
  priority: { parent: 0, exclusive: false, weight: 16 },
  fin: true,
  writable: true,
  headers: 
   { ':status': '200',
     'apns-id': '8e2e626e-2354-90db-a69d-fb59fcb5527c' },
  path: undefined }
>>> Response status code 200
  spdy:stream:client id=5 end +2ms
  spdy:connection:client id=0 remove stream=5 +0ms
  spdy:stream:client id=5 already closed +0ms

The lines prefixed with >>> are mine, from outside node-spdy. I noticed a few things that may be related:

two TCP connections are opened to the server, with consecutive local port numbers: why is that, when one connection would be more than enough?
in the log above streams appear with odd numbers only: what happens with the even-numbered streams?

Lastly and unrelated, there is something about which I'm curious: the design choice of opening the connection(s) at agent creation time. For one, the connection creation should be delayed until it is truely needed. Secondly, this forces the user to bind the agent to a certain destination host-port pair and use different agents for different destinations.

acarstoiu commented 8 years ago

I forgot to mention the Node.js version: 6.1.0.

acarstoiu commented 8 years ago

Reproduceable with Node.js 6.2.1. I finally managed to isolate (somehow) the cause in the pile of modules and interactions that comprise node-spy. It's a function call scheduled with process.nextTick that just doesn't get called until the next use of timers (the event loop is simply blocked or so it seems). The blocked call is here in readable-stream when trying to send the headers frame.

Unfortunately this problem shows up only when some in-house developed native module gets called before each call to node-spdy - and apparently every second call heals Node's frozen state. I never suspected this module, nor do I suspect it now; this looks like a V8 bug which happens to manifest when some native code is also run. Anyway, we'll have a look at it, just in case.

On a side note, the existence of two TCP connections was due to my code, sorry about that.

acarstoiu commented 8 years ago

The native module was changed to use nan and the issue reported here is gone.

spdy-http2 / node-spdy

A re-used client agent does not handle every second client request until the next one is made #259