Initial experiences with converting from legacy http2 module to core http2; Chunk repeat problem?

I have a large and complex application SPA that I am developing which up until now has been using the http2 module from molnarg/node-http2 repository. I thought I would give this new version a quick trial to get an idea for how much conversion effort I might need when this hits.

My immediate conclusion what was that theoretically I only needed to change one line of code, namely

this.server = require('http2').createServer(certs,async (req,res) => {

needed to become

this.server = require('http2').createSecureServer(certs,async (req,res) => {

However I have experienced other problems. Firstly there seems to be a problem around serve-static (or more probably the send module that it uses) in relation to completing requests. My application successfully loaded the first file (index.html), but immediately became stuck as it failed to complete loading of its first import. I couldn't get very far tracing down the problem as I can't get visual studio code debug to work with this latest version of node. It insists of providing --debug-brk flag which this version of node rejects.

So I have written my static file serving to to little more than fs.createReadSteam(filename).pipe(res)
Now it does load all the files but immediately fails as it tries to start running.

This application is a polymer based app (https://www.polymer-project.org/) and almost immediately the application crashes out with polymer-micro.html:310 Uncaught SyntaxError: Unexpected token
looking at this file as seen by the browser at that point (lines 298 to 321)

attributeChangedCallback: function (name, oldValue, newValue) {
this._attributeChangedImpl(name);
for (var i = 0, b; i < this.behaviors.length; i++) {
b = this.behaviors[i];
if (b.attributeChanged) {
b.attributeChanged.call(this, name, oldValue, newValue);
}
}
if (this.attributeChanged) {
this.attributeChanged(name, oldValue, newValue);
}
},
_attributeChangedImpl: function (namatus._makeReady();
});
},
_afterNextRenderQueue: [],
_waitingNextRender: false,
afterNextRender: function (element, fn, args) {
this._watchNextRender();
this._afterNextRenderQueue.push([
element,
fn,
args
]);

A quick comparison with the source file which was sent (with the fs.createReadStream().pipe(res)) shows that halfway along line 310, I suddenly get some code from further back up the file injected into the source, and the overall file has got more lines in it in the client than is in the file back on the server.

I am currently figuring out how I can get a better demonstration of the problem to you, but at least reckon I should report this to you as I find it.

@akc42

Thanks for your feedback @akc42! That's highly needed, and what we are looking for. Are you able to reproduce the problem you are having in isolation? Would you mind attaching a full example that demonstrate it?

This is my serve static replacement

  function get_content_type(filename) {
    const ext = path.extname(filename);
    switch(ext.toLowerCase()) {
      case '.html': return 'text/html';
      case '.js' : return 'text/javascript';
      case '.css': return 'text/css';
      case '.jpg' : case '.jpeg': return 'image/jpeg';
      case '.png': return 'image/png';
      case '.ico': return 'image/icon';
      default: return 'text/plain';
    }
  }

  //simple serve-static
  function staticFiles (cpath) {
    var clientPath = cpath;
    return (req, res, next) => {
      let reqURL = url.parse(req.url).pathname
      requestLog('Handling Static Path ', reqURL);
      if (reqURL === '/') reqURL = '/index.html'
      const filename = path.resolve(clientPath,reqURL.substring(1));
      fs.access(filename, fs.constants.R_OK, (err) => {
        if (err) {
          requestLog('FileName ', filename, ' Has Error')
          next();
          return;
        }
        requestLog('About to send FileName ', filename);
        res.writeHead(200,{'Content-Type': get_content_type(filename)});
        fs.createReadStream(filename).pipe(res);
      })
    };
  }

@mcollina

@mcollina Its a real problem showing the full application as

It is massive
Its not open source, I am developing it for a client.
I will have a look further at whether I can offer a cut down version, that still shows the issue as a repo on github

To solve this, we need a way to reproduce. Can you assemble a trimmed down version that shows the same problem by just using core http2 module?

Try this. Its a simple server and the polymer 2.0 (just released) starter kit as the client. It shows the corruption for me.

https://github.com/akc42/http2-corrupt

The README.md in this repository should show you how to set it up. You need to adjust dns for the certificate files, or (as is probably the case) you can replace them with your own.

@akc42

@akc42 FWIW I've done a similar migration from node-http2 to node-spdy to this native implementation. Perhaps this repo can be helpful to you: https://gitlab.com/sebdeckers/http2server/merge_requests/20 (This is the latest branch, implements push promises, static file serving, mime types, compression, etc.)

Here is another datapoint in case it is useful to anyone. I did a character count of the original file and the corrupted file. They are identical (21094 in the case of property-assessors.html, the first corrupted file when I run the http2-corrupt setup referenced above). I had originally thought that the corrupted file was longer than the original because the line numbering was higher at the end, but it turns out not to be the case.

I'll try and see if I can find the length of the chunk that is different.

I found another interesting fact. The first corrupted file corruption started at character (using wc -c on linux) 8158 and the next corrupted file I checked it started at character 7531 but the data that was used to corrupt the file came from character 4088 onwards in all three of the first three cases that I checked.

Makes me wonder if there is some form of pause restart problem.

It's entirely possible. I'll start running some tests that pass a large amount of data through on both the client and server and make sure we get good check sums on both.

I am happy to report now that I have just upgraded to the lastest version in master, that the corruption problems I referred to above no longer seem to be happening.

As a result of that success, I have started to use it with my "big" application. Here I have run into another problem which I haven't got to the bottom of yet. I am using the router module from npm (https://www.npmjs.com/package/router) and whilst, so far its routing static files and an ajax GET request, something is happening with the ajax POST request. I see it received by the server, but it disappears inside the router module and never comes out. After a delay of a couple of minutes I get a error

  pas:web request received for url  /logon +12s
events.js:182
      throw er; // Unhandled 'error' event
      ^

Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code 7
    at ServerHttp2Stream._destroy (internal/http2/core.js:1479:19)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at streams.forEach (internal/http2/core.js:911:40)
    at Map.forEach (native)
    at ServerHttp2Session.destroy (internal/http2/core.js:911:13)
    at TLSSocket.socketDestroy [as destroy] (internal/http2/core.js:1919:18)
    at emitOne (events.js:115:13)
    at ServerHttp2Session.emit (events.js:210:7)
    at process.nextTick (internal/http2/core.js:611:31)
    at _combinedTickCallback (internal/process/next_tick.js:134:7)
alan@kanga:~/dev/pasv5[newnode]$ ^C

I am closing in on the error. Its in body parser (json) https://www.npmjs.com/package/body-parser

It is expecting some events so it attaches to the request stream

  stream.on('aborted', onAborted)
  stream.on('close', cleanup)
  stream.on('data', onData)
  stream.on('end', onEnd)
  stream.on('error', onEnd)

I have attached breakpoints on all of these functions. It was only temporarily on onData (because everything times out whilst I am debugging) but it was called with the chunk of data that was the body), but I did a second run with breakpoints on the rest, and onEnd was never called, and after the long delay onAborted was called.

@akc42

@akc42 can you link those in body-parser source code? I can't find them right now.

@mcollina

@mcollina Its in a module called raw-body that body-parser obviously brings in

The lines referenced above are on lines 228 on index.js the functions are further down at 266 and beyond

I have been playing with this further today. As far as I can see this is a failure somewhere down the line to emit 'end' on the request stream. I can see that Http2Stream extends from Duplex, and to make that emit 'end', somewhere along the line someone has to call this.push(null) on it. (or emit('end' ...) specifically, but I can't find any of those).

As far as I can see there are only two viable places for that to happen, Either onSessionClose or onStreamClose. If I understand correctly, for a single request, it is the latter of those two functions that I should be examining. This happens in _destroy() function, which is called by node when an external entity called destroy(). And thats as far as I've got. _destroy() doesn't get called in my scenario until the timeout in about two minutes. Certainly not when all the 'data' chunks have been consumed.

I *believe* I have a fix for this bug. I was not ending the readable side correctly. I'll have a new pr later on today hopefully.

…

On Tue, Jul 11, 2017 at 11:01 AM Alan Chandler ***@***.***> wrote: I have been playing with this further today. As far as I can see this is a failure somewhere down the line to emit 'end' on the request stream. I can see that Http2Stream extends from Duplex, and to make that emit 'end', somewhere along the line someone has to call this.push(null) on it. (or emit('end' ...) specifically, but I can't find any of those). As far as I can see there are only two viable places for that to happen, Either onSessionClose or onStreamClose. If I understand correctly, for a single request, it is the latter of those two functions that I should be examining. This happens in _destroy() function, which is called by node when an external entity called destroy(). And thats as far as I've got. _destroy() doesn't get called in my scenario. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#126 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAa2eRXw5Lm4JnqftEeXtlyqLi_WwRGOks5sM7htgaJpZM4NcieG> .

@jasnell

@jasnell I think your fix has worked, I now have a server that seems to be receiving and responding to GET and PUSH requests just fine.

I am now just puzzling how to use the http2 client (which is another subprocess of my application) to send a POST request to the server. I "think" I have it, slightly different from http, but its late this evening here and my eyes need some rest before typing the changes in.

I've been doing some work with the core http2 client, you can see a very basic implementation here:
https://github.com/AndrewBarba/apns2/blob/node/http2/lib/http2-client.js

It shows how I'm setting http methods, but I definitely have questions about performance and best practices which I've raised here: #131 The client passed all the unit tests in that repo based on nodejs/http2 from a couple weeks back. Haven't had a chance to test again with all the new PR's

Basic usage would look like:

const Http2Client = require('http2-client')
const googleClient = new Http2Client("www.google.com", 443)

googleClient.post("/auth/login", { ... }).then(res => ...)

Navigation Menu

Repository navigation

Initial experiences with converting from legacy http2 module to core http2; Chunk repeat problem? #126

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Initial experiences with converting from legacy http2 module to core http2; Chunk repeat problem? #126

Description

Activity

mcollina commented on May 16, 2017

akc42 commented on May 16, 2017

akc42 commented on May 16, 2017

mcollina commented on May 16, 2017

akc42 commented on May 16, 2017

sebdeckers commented on May 16, 2017

akc42 commented on May 18, 2017

akc42 commented on May 18, 2017

jasnell commented on May 18, 2017

akc42 commented on Jul 5, 2017

akc42 commented on Jul 6, 2017

mcollina commented on Jul 6, 2017

akc42 commented on Jul 6, 2017

akc42 commented on Jul 11, 2017

jasnell commented on Jul 11, 2017

akc42 commented on Jul 14, 2017

AndrewBarba commented on Jul 14, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions