Initial experiences with converting from legacy http2 module to core http2; Chunk repeat problem?
akc42 opened this issue · 17 comments
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.
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 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 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 can you link those in body-parser source code? I can't find them right now.
@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.
@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 => ...)