Error "Cannot read property 'w' of null at iterateHttpRequests" on aborted connections

[MarkTiedemann]

// server.ts
import { serve } from "https://deno.land/std/http/server.ts";

async function main() {
  for await (let req of serve(":80")) {
    req.respond({});
  }
}

main();

$ deno run --allow-net server.ts
/Users/<redacted>/Library/Caches/deno/deps/https/raw.githubusercontent.com/denoland/deno_std/master/http/server.ts:225:36
            await writeResponse(req.w, {
                                    ^
Uncaught TypeError: Cannot read property 'w' of null
    at iterateHttpRequests (file:///Users/<redacted>/Library/Caches/deno/deps/https/raw.githubusercontent.com/denoland/deno_std/master/http/server.ts:254:31)

$ autocannon localhost
Running 10s test @ localhost
10 connections

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼──────────┤
│ Latency │ 0 ms │ 0 ms │ 1 ms  │ 2 ms │ 0.07 ms │ 0.39 ms │ 11.05 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴──────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬──────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼──────────┼─────────┼────────┤
│ Req/Sec   │ 22879  │ 22879  │ 27695   │ 28287   │ 27145.46 │ 1494.03 │ 22871  │
├───────────┼────────┼────────┼─────────┼─────────┼──────────┼─────────┼────────┤
│ Bytes/Sec │ 869 kB │ 869 kB │ 1.05 MB │ 1.08 MB │ 1.03 MB  │ 56.8 kB │ 869 kB │
└───────────┴────────┴────────┴─────────┴─────────┴──────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

299k requests in 11.06s, 11.3 MB read

When I restarted the server and ran another load test, it crashed again. Might not be related to the high load, though.

[zekth]

@MarkTiedemann could you run it with --reload? you seem to not use the last version of the http server.

[MarkTiedemann]

Still the same.

/Users/<redacted>/Library/Caches/deno/deps/https/raw.githubusercontent.com/denoland/deno_std/master/http/server.ts:249:36
            await writeResponse(req.w, {
                                    ^
Uncaught TypeError: Cannot read property 'w' of null
    at iterateHttpRequests (file:///Users/<redacted>/Library/Caches/deno/deps/https/raw.githubusercontent.com/denoland/deno_std/master/http/server.ts:278:31)

[zekth]

Related to this: #443

[MarkTiedemann]

It seems to crash only at the end of the load test rather than because of the load. So probably when requests are being aborted.

[zekth]

It seems to crash only at the end of the load test rather than because of the load. So probably when requests are being aborted.

well that's a nice hint! On each run? I'll try to improve this.

[MarkTiedemann]

well that's a nice hint! On each run? I'll try to improve this.

Yes, on each autocannon run. I can basically watch the server and wait until it crashes to see when the load test is over.

I did try to reproduce it making different combinations of aborted and partial requests from Node, but couldn't reproduce it yet. Maybe it's the combination of a certain load and aborted requests or something of that sort.

[zekth]

After 9 runs no crash on my side. Running on OSX with deno 0.6. What's the env you're running on?
If you can maybe try to put a wait on the server side for keeping the request up and cancel it before write the response? Using : https://github.com/axios/axios#cancellation

[MarkTiedemann]

macOS 10.14.4, deno 0.6.0.

[MarkTiedemann]

After 9 runs no crash on my side.

Did you run autocannon with --duration or --amount?

I just ran autocannon --duration 1 localhost 10 times. Each time, the server handled ~16000 requests just fine, then crashed at the end.

When I ran autocannon --amount 16000 localhost 10 times, however, the server didn't crash a single time.

So I'm pretty sure that it has to do with how the connections are closed. When running with --amount, autocannon probably only sends as many requests as necessary. I'd guess, with --duration, it sends as many as possible, then aborts the remaining ones that haven't been answered yet at the end of the duration.

[zekth]

i've copied your example:
autocannon localhost

So i'll work on with your new investigation. Thanks

[MarkTiedemann]

Cloned deno_std and added a good old console log...

 if (bufStateErr instanceof Error) {
   // An error was thrown while parsing request headers.
+  console.error(bufStateErr);  
   await writeResponse(req.w, {
     status: 400,
     body: new TextEncoder().encode(`${bufStateErr.message}\r\n\r\n`)
   });
 }

❯ make
deno run --allow-net main.ts
[1/1] Compiling file:///Users/marktiedemann/dev/deno_std/http/server.ts
Error: read error
    at read (gen/cli/bundle/main.js:7036:17)
    at async BufReader._fill (/Users/marktiedemann/dev/deno_std/io/bufio.ts:53:22)
    at async BufReader.readSlice (/Users/marktiedemann/dev/deno_std/io/bufio.ts:272:13)
    at async BufReader.readLine (/Users/marktiedemann/dev/deno_std/io/bufio.ts:209:27)
    at async TextProtoReader.readLineSlice (/Users/marktiedemann/dev/deno_std/textproto/mod.ts:121:34)
    at async TextProtoReader.readLine (/Users/marktiedemann/dev/deno_std/textproto/mod.ts:40:27)
    at async readRequest (/Users/marktiedemann/dev/deno_std/http/server.ts:201:24)
    at async Server.iterateHttpRequests (/Users/marktiedemann/dev/deno_std/http/server.ts:231:38)
    at async Server.acceptConnAndIterateHttpRequests (/Users/marktiedemann/dev/deno_std/http/server.ts:276:9)
    at async MuxAsyncIterator.callIteratorNext (/Users/marktiedemann/dev/deno_std/util/async.ts:33:33)
/Users/marktiedemann/dev/deno_std/http/server.ts:250:36
            await writeResponse(req.w, {
                                    ^
Uncaught TypeError: Cannot read property 'w' of null
    at iterateHttpRequests (file:///Users/marktiedemann/dev/deno_std/http/server.ts:279:31)
make: *** [Makefile:3: all] Error 1

The req variable which is null comes from [req, bufStateErr] = await readRequest(bufr);. In readRequest there's an if (err) { return [null, err]; } block. So in this case, it is guaranteed that, if there is an err in readRequest, the req is null. The err from readRequest in this case is for the case that the HTTP status line can't be read, I assume because the underlying connection has been closed.

Not sure how to continue with this. Hope my investigation so far is helpful.

[MarkTiedemann]

In any case, we shouldn't try to send a HTTP 400 response when we can't read the status line of the request, right?

[zekth]

In any case, we shouldn't try to send a HTTP 400 response when we can't read the status line of the request, right?

Right. Because it can't be read as a HTTP request we don't have to answer.

Maybe @ry or @piscisaureus can confirm?

[MarkTiedemann]

On a side note, having the HTTP server in the std lib makes it surprisingly easy to debug. ❤️

[MarkTiedemann]

Here's a reliable reproduction:

// main.ts
// Run with `deno run --allow-net main.ts`

import { serve } from "https://deno.land/std/http/server.ts";

async function main() {
  for await (let req of serve(":80")) {
    req.respond({});
  }
}

main();

// repro.js
// Run with `node repro.js`

let net = require("net");

let client = net.createConnection({ port: 80 }, () => {
  client.write("GET / HTTP/1.0\r\n\r\n");
  client._destroy(new Error(), _ => {});
});

[manyuanrong]

Is there any follow-up to this?
I launched a more formal Deno application. But because of this problem. So it always breaks down.
https://denocn.org