Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Process exits even when catching: Uncaught (in promise) Http: connection closed before message completed #11595

Closed
johnspurlock opened this issue Aug 5, 2021 · 26 comments · Fixed by #11717
Assignees
Labels
bug Something isn't working correctly

Comments

@johnspurlock
Copy link
Contributor

johnspurlock commented Aug 5, 2021

deno 1.12.2 (release, x86_64-apple-darwin)
v8 9.2.230.14
typescript 4.3.5

Refreshing the browser quickly multiple times against a simple local http server can produce a situation where a promise is rejected that cannot be caught, and causes process exits. This is not good when trying to write a stable http server.

for await (const { request, respondWith } of httpConn) {
  try {
    const res = await computeResponse();
    await respondWith(res)
  } catch (e) {
    console.error('Error in respondWith', e);
  }
}

yields:

Error in respondWith Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:extensions/http/01_http.js:183:27)
    at async handle (file:///myfile.ts:87:13)
Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:extensions/http/01_http.js:183:27)
    at async handle (file:///myfile.ts:87:13)
error: Uncaught (in promise) Http: connection closed before message completed
            await respondWith(res);
            ^
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:extensions/http/01_http.js:183:27)
    at async handle (file:///myfile.ts:87:13)
<process exit>

Tried a .catch(), now none of my code appears in this stacktrace at all!

for await (const { request, respondWith } of httpConn) {
  const res = await computeResponse();
  respondWith(res).catch(e => console.log(`Error in respondWith`, e));
}

yields:

Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:extensions/http/01_http.js:183:27)
error: Uncaught (in promise) Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:extensions/http/01_http.js:183:27)
<process exit>

I'm at a loss for what to do here, especially since unhandled promise rejections cannot currently be caught globally (#7013)

Found older #10128 and #10380, but the code seems to have substantially changed since then, based on the stacktraces.

@GJZwiers
Copy link
Contributor

I have encountered the same problem on 1.12.2, and the error remains on 1.13.0 but I can catch it though. This is my code:

const server = Deno.listen({ port: 80 });

for await (const conn of server) {
  handle(conn);
}

async function handle(conn: Deno.Conn) {
  const httpConn = Deno.serveHttp(conn);

  for await (const requestEvent of httpConn) {
    try {
      await requestEvent.respondWith(new Response(
       "Hello World!", {
          status: 200,
          headers: {
            "content-type": "text/html",
          },
        },
      ),
    );
    } catch (e) {
      console.log(e);
    }
  }
}

Terminal will output:

Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async Object.respondWith (deno:extensions/http/01_http.js:183:27) 
    at async handle

I don't get this error when quickly refreshing localhost in a browser but when I leave the server idle for a bit and refresh after a longer interval (~20-30 seconds)

@johnspurlock
Copy link
Contributor Author

johnspurlock commented Aug 11, 2021

Frustrating - still happens on 1.13.0 for me when refreshing too fast from the browser.

deno 1.13.0 (release, x86_64-apple-darwin)

My server loop looks identical to yours @GJZwiers, except my response was awaited first

const res = await computeResponse();
await requestEvent.respondWith(res);

No matter where I place the try/catch, the process exits!

Possibly interesting, removing the await and using a .catch method instead does not prevent process exit either:

const res = await computeResponse();
requestEvent.respondWith(res).catch(e => console.log(`Error in respondWith`, e));

yields:

Error in respondWith Http: connection closed before message completed                                                         
    at deno:core/01_core.js:106:46                                                                                            
    at unwrapOpResult (deno:core/01_core.js:126:13)                                                                           
    at async respondWith (deno:extensions/http/01_http.js:183:27)                                                             
Http: connection closed before message completed                                                                              
    at deno:core/01_core.js:106:46                                                                                            
    at unwrapOpResult (deno:core/01_core.js:126:13)                                                                           
    at async respondWith (deno:extensions/http/01_http.js:183:27)                                                             
error: Uncaught (in promise) Http: connection closed before message completed                                                 
    at deno:core/01_core.js:106:46                                                                                            
    at unwrapOpResult (deno:core/01_core.js:126:13)                                                                           
    at async respondWith (deno:extensions/http/01_http.js:183:27)
<process exit>

The Deno 1.13 release notes mention that this api has been battle tested: @lucacasonato, @bartlomieju, @kitsonk, could you provide the battle-tested http server loop you've been using? Any hints on how to prevent these errors from automatically causing process exits? Happy to debug more if shown where to look, still pretty new to Deno

Thanks!

@bartlomieju
Copy link
Member

Thanks for reports @johnspurlock @GJZwiers, I saw this issue today and it is something we'll look into this week to release fixes for 1.13.1 on Monday. I'll get back to you once I debug the problem, but from the initial investigation it seems to be an error that should be handled internally - looks like client is closing the connection before server writes full response.

@bartlomieju bartlomieju self-assigned this Aug 12, 2021
@bartlomieju bartlomieju added the bug Something isn't working correctly label Aug 12, 2021
@bartlomieju
Copy link
Member

So I'm using following script for testing:

const server = Deno.listen({ port: 8080 });

for await (const conn of server) {
  handle(conn);
}

async function handle(conn: Deno.Conn) {
  const httpConn = Deno.serveHttp(conn);

  for await (const requestEvent of httpConn) {
    requestEvent.respondWith(
      new Response(
        "Hello World!",
        {
          status: 200,
          headers: {
            "content-type": "text/html",
          },
        },
      ),
    ).catch((e) => {
      console.error("uncaught in respondwith", e);
    });
  }
}

I've been able to trigger this error only 2 or 3 times when using the browser, but I'm able to trigger it more or less consistently using wrk. However in both cases the error is logged out and the server keeps working as expected.

@bartlomieju
Copy link
Member

Thanks to @asos-craigmorten for coming up with a test case, I added it in #11717, but again - error is properly caught and the there's no uncaught promise that causes the process to exit. I tested it against Deno 1.12.2 and 1.13.

@johnspurlock @GJZwiers is there any more code that you could share that could help us pinpoint the problem?

@johnspurlock
Copy link
Contributor Author

johnspurlock commented Aug 15, 2021

It's trivial to reproduce on my side on one of my projects, but the project is fairly complex. I'll work on coming up with a sharable-but-still-reproducible form of it later today (GMT-5)

In case it helps, the initial request loads among other things a webapp in debug mode, which in turn makes a flurry of additional requests back to the same server. So "refreshing too quickly" in the browser terminates possibly many simultaneous inflight requests at once.

@bartlomieju
Copy link
Member

It's trivial to reproduce on my side on one of my projects, but the project is fairly complex. I'll work on coming up with a sharable-but-still-reproducible form of it later today (GMT-5)

In case it helps, the initial request loads among other things a webapp in debug mode, which in turn makes a flurry of additional requests back to the same server. So "refreshing too quickly" in the browser terminates possibly many simultaneous inflight requests at once.

Thanks that's a good pointer. I'll try to come up with a test case that does the same.

@GJZwiers
Copy link
Contributor

GJZwiers commented Aug 15, 2021

I've been able to reproduce the error consistently by doing the following in a browser (Firefox):

  • Open localhost:8080 before running the server, wait for the unable to connect message from the browser
  • Start the server with deno run
  • Refresh the browser tab -> error shows in terminal

If I keep the server running and refresh it seems to happen very irregularly, I've basically let the server idle for a while on localhost and then refreshing, but it doesn't show any pattern so far. Tested with both Ubuntu WSL 2 terminal and PowerShell

@bartlomieju
Copy link
Member

I've been able to reproduce the error consistently by doing the following in a browser (Firefox):

  • Open localhost:8080 before running the server, wait for the unable to connect message from the browser
  • Start the server with deno run
  • Refresh the browser tab -> error shows in terminal

Unfortunately I'm unable to reproduce the error with those step.

Could you folks try with latest Deno canary (deno upgrade --canary) and tell me if the problem persists?

@GJZwiers
Copy link
Contributor

I've been able to reproduce the error consistently by doing the following in a browser (Firefox):

* Open localhost:8080 before running the server, wait for the unable to connect message from the browser

* Start the server with `deno run`

* Refresh the browser tab -> error shows in terminal

If I keep the server running and refresh it seems to happen very irregularly, I've basically let the server idle for a while on localhost and then refreshing, but it doesn't show any pattern so far. Tested with both Ubuntu WSL 2 terminal and PowerShell

So this doesn't seem to work when I have a firefox console/debugger open at the same time :/ On the canary I still get the error if I open a single new firefox instance, open localhost:8080 before running the server and then refresh once it's up. But connecting to it from Deno with a Deno.connect seems to work fine. I think @johnspurlock 's code will probably be of more help to find the cause since I don't see how to debug this from the browser side of things.

@johnspurlock
Copy link
Contributor Author

Could you folks try with latest Deno canary (deno upgrade --canary) and tell me if the problem persists?

Still able to reproduce the process exit on canary

deno 1.13.0+d1fe03d (canary, x86_64-apple-darwin)
v8 9.3.345.11
typescript 4.3.5

os: macos 11.5.2 (20G95)

I ensured my server loop is character for character the same as yours, @bartlomieju

The only differences are that I destructure the requestEvent, I have one line that computes the response via await instead of hardcoding an inline response, and I'm including the request url in the error msg for debugging, to see if it fails on the initial request, or any of the followup requests from the webapp

const { request, respondWith } = requestEvent;
const res = await localRequestServer.fetch(request);
respondWith(res).catch((e) => { console.error(`uncaught in respondwith ${request.url}`, e); });

Run command:

deno run --unstable --allow-read --allow-net --allow-env server.ts || echo "process exit code $?"

Browser command-r (refresh) quickly on brave/chrome/safari/ff on mac yields:

uncaught in respondwith http://localhost:3002/ Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:ext/http/01_http.js:183:27)
Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:ext/http/01_http.js:183:27)
error: Uncaught (in promise) Http: connection closed before message completed
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:ext/http/01_http.js:183:27)
process exit code 1

I'll start working on narrowing my server down to something shareable

@bartlomieju
Copy link
Member

@johnspurlock I used this code:

const server = Deno.listen({ port: 8080 });

const localRequestServer = {
    fetch: async (_req) => {
        await Promise.resolve();
        return new Response(
            "Hello World!",
            {
              status: 200,
              headers: {
                "content-type": "text/html",
              },
            },
          )
    },
};

for await (const conn of server) {
  handle(conn);
}

async function handle(conn: Deno.Conn) {
  const httpConn = Deno.serveHttp(conn);

  for await (const requestEvent of httpConn) {
    const { request, respondWith } = requestEvent;
    const res = await localRequestServer.fetch(request);
    respondWith(res).catch((e) => { console.error(`uncaught in respondwith ${request.url}`, e); });
  }
}

with

$ deno run --unstable --allow-read --allow-net --allow-env --no-check test_server.ts || echo "process exit code $status"

(I use fish so had to change the echo command).

I'm refreshing browser tab multiple times, or even holding Cmd + R to trigger a lot of "canceled" requests and I can't even trigger the same error. In the test cases I wrote the error can be triggered but it's still properly handled. I'm afraid without full reproduction code including you localRequestServer I might not be able to find the problem. What does the localRequestServer do?

Aslo, are you running on Mac M1?

@johnspurlock
Copy link
Contributor Author

Also, are you running on Mac M1?

Nope, MacBook Pro (16-inch, 2019) 2.4 GHz 8-Core Intel Core i9

Working right now on getting a smaller shareable version of my server, hard because it's rendered using data from services needing account secrets etc.

Another possible culprit is that my root resource (the url that gets reloaded by the user) Response body is a ReadableStream<Uint8Array>, the readable side of a TransformStream<Uint8Array> - possibly something for you to try in the meantime?

@johnspurlock
Copy link
Contributor Author

In case it helps, the initial request loads among other things a webapp in debug mode, which in turn makes a flurry of additional requests back to the same server. So "refreshing too quickly" in the browser terminates possibly many simultaneous inflight requests at once.

Repros trivially when the webapp is completely disabled, so this does not seem to be the culprit.

@johnspurlock
Copy link
Contributor Author

Another possible culprit is that my root resource (the url that gets reloaded by the user) Response body is a ReadableStream<Uint8Array>, the readable side of a TransformStream<Uint8Array>

Alright, this should demonstrate the issue in a minimal way.

function sleep(ms: number) {
    return new Promise(resolve => setTimeout(resolve, ms));
}

async function computeResponse(): Promise<Response> {
    await sleep(200);
    const { readable, writable } = new TransformStream<Uint8Array>();
    const writer = writable.getWriter();
    try {
        writer.write(new TextEncoder().encode('written to the writable side of a TransformStream'));
    } catch (e) {
        console.log(`Error in writer.write`, e);
    }
    writer.close();
    return new Response(readable);
}

async function handle(conn: Deno.Conn) {
    const httpConn = Deno.serveHttp(conn);
    for await (const { request, respondWith } of httpConn) {
        const res = await computeResponse();
        respondWith(res).catch((e) => { console.error(`uncaught in respondWith ${request.url}`, e); });
    }
}

const server = Deno.listen({ port: 3002 });

for await (const conn of server) {
    handle(conn);
}

Refreshing the site slowly in a browser will work, but once you refresh too quickly, or hold down command-r, the process will crash no matter where you place a try/catch.

Depending on how fast your machine is, you may need to increase the sleep ms a bit, but this is set pretty high already and reproduces easily on my machine.

@bartlomieju
Copy link
Member

Thanks @johnspurlock I'm getting the panic now. I will try to fix it for tomorrow.

@bartlomieju
Copy link
Member

bartlomieju commented Aug 16, 2021

@johnspurlock so with help from @lucacasonato and @ry we've debugged the problem.

Firstly, there's a problem with stack trace that doesn't give useful information, the best I could get was:

error: Uncaught (in promise) Http: connection closed before message completed
            const res = await computeResponse();
                                             ^
    at deno:core/01_core.js:106:46
    at unwrapOpResult (deno:core/01_core.js:126:13)
    at async respondWith (deno:ext/http/01_http.js:183:27)
    at async file:///Users/biwanczuk/dev/deno/cli/tests/unit/http_test.ts:835:46

which points that there's unresolved promise in the computeResponse function.

There's also problem in your code in that you don't await writer.write and writer.close which both are promises and that was the root cause of the uncaught promise rejecetion.

If you rewrite your code like so:

async function writeResponse(writer): Promise<Response> {
    try {
        await writer.write(new TextEncoder().encode('written to the writable side of a TransformStream'));
    } catch (e) {
        console.log(`Error in writer.write`, e);
    }
    await writer.close();
    
}

async function handle(conn: Deno.Conn) {
    const httpConn = Deno.serveHttp(conn);
    for await (const { request, respondWith } of httpConn) {
        const { readable, writable } = new TransformStream<Uint8Array>();
        const writer = writable.getWriter();
        writeResponse(writer).catch((e) => { console.error(`uncaught in writeResponse ${request.url}`, e); });
        const res = new Response(readable);
        const res = await computeResponse();
        respondWith(res).catch((e) => { console.error(`uncaught in respondWith ${request.url}`, e); });
    }
}

const server = Deno.listen({ port: 3002 });

for await (const conn of server) {
    handle(conn);
}

the problem goes away. (Writing of response needs to be done in an async IIFE because of WHATWG streams backpressure).

There's also a bug in internal code that doesn't properly clean up one resource that I'm working on a fix for, but I'm afraid it might be released in 1.13.2 in a week as there's some refactors I need to do before that can be fixed. This should be released in 1.13.1 after all.

Thanks for providing this test case - this is quite an esoteric bug but I'm glad we got to the bottom of it.

@asos-craigmorten
Copy link
Contributor

asos-craigmorten commented Aug 16, 2021

There's also a bug in internal code that doesn't properly clean up one resource that I'm working on a fix for

What resource is this @bartlomieju? I've noticed that if code throws prior to calling respondWith() successfully you are left with a hanging responseSender resource even if you have closed the underlying listener and httpConn - just in case it's the same thing and not to worry about raising an issue 🙃

REF: https://github.com/denoland/deno_std/pull/1128/files#diff-dd523d06e796c772903dc7b7b2211ac9a7f8eceeeb160258acbda240444187a8R373

@bartlomieju
Copy link
Member

There's also a bug in internal code that doesn't properly clean up one resource that I'm working on a fix for

What resource is this @bartlomieju? I've noticed that if code throws prior to calling respondWith() successfully you are left with a hanging responseSender resource even if you have closed the underlying listener and httpConn - just in case it's the same thing and not to worry about raising an issue 🙃

Yes, it's the same one, it's actually called responseBody.

@johnspurlock
Copy link
Contributor Author

There's also problem in your code in that you don't await writer.write and writer.close which both are promises and that was the root cause of the uncaught promise rejecetion.

Thanks for looking into this. Unfortunately in my case I can't change that function - I'm writing a framework, and my sample was simplified, but imagine that computeResponse() actually import()s and runs a user-supplied script that makes those calls.

  1. The stack trace is misleading, is this not something that could be improved? It would at least point the user of my framework to the true source of the issue, and not to the highest-level http responder. It would have also saved me a bunch of time trying to investigate an issue with the server loop : )

  2. I guess this ends up being a special case of being able to catch unhandled rejections (onunhandledrejection for globalThis? #7013), I'll add my use case to that feature request.

@bartlomieju
Copy link
Member

There's also problem in your code in that you don't await writer.write and writer.close which both are promises and that was the root cause of the uncaught promise rejecetion.

Thanks for looking into this. Unfortunately in my case I can't change that function - I'm writing a framework, and my sample was simplified, but imagine that computeResponse() actually import()s and runs a user-supplied script that makes those calls.

  1. The stack trace is misleading, is this not something that could be improved? It would at least point the user of my framework to the true source of the issue, and not to the highest-level http responder. It would have also saved me a bunch of time trying to investigate an issue with the server loop : )

Yes, I agree the situation is very unfortunate and there is some problem with stack traces, but I'm afraid we're constrained to what V8 gives us. There's #7644 that could alleviate the problem, but the V8 APIs are missing.

  1. I guess this ends up being a special case of being able to catch unhandled rejections (onunhandledrejection for globalThis? #7013), I'll add my use case to that feature request.

Thanks a good idea.

@JumpLink
Copy link

JumpLink commented Dec 12, 2021

If I reload the browser before the response from the server arrives I get the error too, how can I catch this error so that the application does not crash?

Example:

const sleep = (ms: number) => {
  return new Promise(resolve => setTimeout(resolve, ms))
}

const server = Deno.listen({ port: 8000 });

console.log("http://localhost:8000/");

try {
  for await (const conn of server) {
    (async () => {
      const httpConn = Deno.serveHttp(conn);
      for await (const { respondWith } of httpConn) {
        // Placeholder for some calculations or requests from other services
        // This makes the difference
        await sleep(200);
        respondWith(new Response("hello world", {
          status: 200,
        }));
      }
    })();
  }
} catch (error) {
  // Note: This is not called for the error: "Http: connection closed before message completed"
  console.warn("Error", error);
}

Start this with deno run --allow-net app.ts

If I remove await sleep(200); it also happens when I hold down the F5 key of the browser so that many requests are generated in a short time.

@JumpLink
Copy link

JumpLink commented Dec 13, 2021

Seems to be fixed in the new HTTP server API: denoland/std#1128

Example

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

const sleep = (ms: number) => {
  return new Promise(resolve => setTimeout(resolve, ms))
}

const requestHandler: Handler = async (/*request, connInfo*/) => {
  await sleep(200);
  const resp = new Response("hello world");
  return resp;
}

const listener = Deno.listen({ port: 8000 });
serveListener(listener, requestHandler);

@irustm
Copy link

irustm commented Dec 26, 2021

@JumpLink I think a new issue should be created

@greergan
Copy link

deno 1.32.3 (release, x86_64-unknown-linux-gnu)
v8 11.2.214.9
typescript 5.0.3

error: Uncaught (in promise) Http: connection closed before message completed
at async Object.respondWith (ext:deno_http/01_http.js:248:9)

Not doing anything special.

Basically using the code from the example page: https://deno.land/[email protected]/examples/http_server

I can definitely say that this issue is random. This happened just now after starting my server and sending 2 requests.

@tbitcomb
Copy link

tbitcomb commented Sep 3, 2023

I'm experiencing the same thing on 1.36.4.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working correctly
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants