oakserver / oak

A middleware framework for handling HTTP with Deno, Node, Bun and Cloudflare Workers 🐿️ 🦕
https://oakserver.org
MIT License
5.17k stars 235 forks source link

[uncaught application error] log always shows response.status as 404 #630

Closed artze closed 9 months ago

artze commented 9 months ago

Hi,

There might be an issue with [uncaught application error] logger. No matter what uncaught errors are thrown in the app, the log always shows response.status=404.

Setup

import { oak } from "@src/deps.ts";

const app = new oak.Application();
const router = new oak.Router();

router.get("/", (ctx) => {
  ctx.throw(400);
});

app.use(router.routes());
app.listen({ port: 3000 });

Output

App logs:

[uncaught application error]: BadRequestError - Bad Request

request: { url: "http://localhost:3000/", method: "GET", hasBody: false }
response: { status: 404, type: undefined, hasBody: false, writable: true }  <== see response.status here

    at createHttpError (https://deno.land/x/oak_commons@0.4.0/http_errors.ts:202:10)
    at Context.throw (https://deno.land/x/oak@v12.6.2/context.ts:290:17)
    at file:///home/arthur/dev/artze/deno-oak-server-sample/src/app.ts:7:12
    at dispatch (https://deno.land/x/oak@v12.6.2/middleware.ts:80:13)
    at https://deno.land/x/oak@v12.6.2/router.ts:1287:20
    at dispatch (https://deno.land/x/oak@v12.6.2/middleware.ts:80:13)
    at composedMiddleware (https://deno.land/x/oak@v12.6.2/middleware.ts:83:12)
    at dispatch (https://deno.land/x/oak@v12.6.2/router.ts:1293:22)
    at dispatch (https://deno.land/x/oak@v12.6.2/middleware.ts:80:13)
    at composedMiddleware (https://deno.land/x/oak@v12.6.2/middleware.ts:83:12)

+++

Made the request with curl. The requester received the expected status code:

~$ curl -v http://localhost:3000
* Host localhost:3000 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
*   Trying [::1]:3000...
* connect to ::1 port 3000 from ::1 port 50526 failed: Connection refused
*   Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000
> GET / HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/8.5.0
> Accept: */*
>
< HTTP/1.1 400 Bad Request
< content-type: text/plain; charset=UTF-8
< vary: Accept-Encoding
< content-length: 11
< date: Sun, 21 Jan 2024 00:25:55 GMT
<

Expected Behavior

Environment

Thank you

artze commented 9 months ago

Had a look at the #handleError() in Application class.

It may be because the ApplicationErrorEvent is dispatched (see here) before the context.response.status is set on L433.

From what I can understand, if unset, the response.status defaults to 404 (if the response.body is empty). It looks like the uncaught error gets logged before the response.status is set, and takes the default value.

kitsonk commented 9 months ago

The ApplicationErrorEvent getting called before setting the context response status being set is intentional, because this allows the event handler to change the context/response based on error information.

It is worth looking into setting the status before calling the handler and still allow the handler to override the value.

SaTae66 commented 9 months ago

For me, the status code sent back to the client is still a 404 when using oak 13.0.0, am I missing something?

artze commented 9 months ago

@SaTae66

When using ctx.throw(400) like in my setup above (note that I do not have any error handling middleware defined), the correct status code is sent to the client (400), but the [uncaught application error] logs says something different (404).

SaTae66 commented 9 months ago

@artze if I do sth like router.use(ErrorMiddleware.unauthorized);

with

static async unauthorized(ctx: oak.RouterContext<string>, next: oak.Next) {
    const { response } = ctx;
    try {
      await next();
    } catch (err) {
      if (err instanceof oak.httpErrors.Unauthorized) {
        // required by https://www.rfc-editor.org/rfc/rfc9110#status.401
        response.headers.set("WWW-Authenticate", "Bearer");
      }
    }
  }

and throwing the error like

ctx.throw(401);

the WWW-Authenticate header is set (so the error caught is a 401), but the status received by the client is a 404. If I remove the ErrorMiddleware, I (obviously) receive an [uncaught application error]: UnauthorizedError - Unauthorized, but the client receives the correct 401 status code.

kitsonk commented 9 months ago

Caught errors do not automatically affect the response. It is only uncaught errors that are handled automatically and dispatch error events. If you still want automatic error processing to occur, don't catch the errors.

The observed behaviour aligns to the behaviour in these tests:

https://github.com/oakserver/oak/blob/43bcd82579ebb23fa4328c402d4ca1ebd39d3fce/application.test.ts#L715-L773

SaTae66 commented 9 months ago

Ah ok, thanks a lot for the clarification!