Add error logs for HTTP 500 error details

[joshdover]

Currently, whenever a 500 error is returned by a handler, there is no default logging of the details of that error. Instead, a generic InternalServerError is logged:

server   error  [18:42:47.536]  Error: Internal Server Error
    at HapiResponseAdapter.toError (/home/lizozom/Projects/kibana/src/core/server/http/router/response_adapter.ts:129:19)
    at HapiResponseAdapter.toHapiResponse (/home/lizozom/Projects/kibana/src/core/server/http/router/response_adapter.ts:79:19)
    at HapiResponseAdapter.handle (/home/lizozom/Projects/kibana/src/core/server/http/router/response_adapter.ts:74:17)
    at Router.handle (/home/lizozom/Projects/kibana/src/core/server/http/router/router.ts:264:34)
    at process._tickCallback (internal/process/next_tick.js:68:7)

This is different from the behavior of unexpected errors (cases where the handler does not have any try/catch logic that defaults to returning a res.internalError()) which does log the original error using log.error.

We should make this behavior more consistent rather than relying on all plugin HTTP handlers to implement this logging. This would improve the debugging experience for customers & support as well as the developer experience of "where in the world is this error coming from".

Relevant code:

kibana/src/core/server/http/router/router.ts

Lines 261 to 267 in 6a6deef

	try {
	const kibanaResponse = await handler(kibanaRequest, kibanaResponseFactory);
	return hapiResponseAdapter.handle(kibanaResponse);
	} catch (e) {
	this.log.error(e);
	return hapiResponseAdapter.toInternalError();
	}

[elasticmachine]

Pinging @elastic/kibana-platform (Team:Platform)

[pgayvallet]

This is different from the behavior of unexpected errors

I think this is the key point here. Logging runtime errors / uncatched exceptions thrown from the handler is obviously right, but I'm unsure we should really consider valid responses returned from the handler as actual errors because they got a status >= 400?

For example, should all SO routes log an error when they are 'forwarding' a 400 from ES?

Second point is, if we do: We don't have any context around the 'error' of a KibanaResponse with status > 400. We don't have an associated stacktrace, and when returned using res.custom(status, { body }) the body can be anything, from a string to an object or even a buffer. What should we log?

[lizozom]

@joshdover any update on this?

[mshustov]

Currently, whenever a 500 error is returned by a handler, there is no default logging of the details of that error.

I don't know whether such logs provide a lot of value. Let's see how internalError factory is used:

router.get({ path: '/my-plugin/api', validate: ... }, (context, req, res) => {
  try {
    //...
  } catch(e) {
    return res.internalError({ body: e.message });
  }
});

Note: internalError accepts an error body to be sent with the response. I'm not sure we need to log the same error again.
That's why it hasn't been implemented from the very beginning. But what I see that body property is optional in ErrorHttpResponseOptions

kibana/src/core/server/http/router/response.ts

Line 111 in feceb0f

body?: ResponseError;

In this way, the Kibana server relies on plugins to provide an error message to return res.internalError({...}); factory or log an error message before responding with return res.internalError();. As the current approach doesn't scale up, I'd suggest we make the body required for the response.internalError factory, even if it touches the code in several plugins., to enforce plugin to provide a meaningful error message.
Another alternative could be to make body required, log it automatically, but always respond with generic Internal error occurred. See Kibana logs for details.. As it looks like a bit of magic, so we can recommend plugin not to handle exceptions bubbled to the route handler but rely on the platform to log & handler them instead.

Wee still have 2 other ways to create internal error: response.customError & response.custom. Not sure we can adjust the response.custom interface as an empty response body is a valid use-case, but we can make body required for response.customError as well.

@elastic/kibana-platform WDYT?

[mshustov]

It seems to be that we should remove response.internalError completely. Plugins should classify an exception to provide an actionable message to the end-user. While 500 is reserved for Internal server errors, which aren't actionable for end-users, but for Kibana developers. We consider removing response.internalError to make the platform the only place handling unexpected errors, since we cannot make sure that all the plugin implement Internal server errors response correctly (log an exception, don't leak error details in a response, etc.). It will be a breaking change since almost in all cases plugins provide the whole error object in a response body (like

kibana/x-pack/plugins/snapshot_restore/server/routes/api/restore.ts

Line 88 in bf04235

return res.internalError({ body: e });

)

[pgayvallet]

Would limiting the allowed type of body of res.internalError to Error address that? We could then just 'rethrow' the error from our handler to reproduce the behavior of unexpected errors? But at this point removing res.internalError totally may make more sense.

[mshustov]

Would limiting the allowed type of body of res.internalError to Error address that?

It might be not clear for plugin authors that created Error is not provided in a response body to the end-users, but logged instead.

[afharo]

I've been looking at usages of res.internalError(). It looks like most plugins provide either the error or a message in the body when invoking that helper.

The cases where the method is called but no error/message is provided are, primarily in the security plugin where they log the error first, and then call res.internalError() with no params. I think the logger used in these scenarios is key:

1. In here, the error is logged to the audit logs:
   

   kibana/x-pack/plugins/security/server/authentication/index.ts

   Lines 110 to 113 in 2782204

   	} catch (err) {
   	authLogger.error(err);
   	return response.internalError();
   	}

2. The error is logged to the server's logs, but it has the [security][routes] tags/scope:
   

   kibana/x-pack/plugins/security/server/routes/authentication/common.ts

   Lines 162 to 165 in e46e662

   	} catch (err) {
   	logger.error(err);
   	return response.internalError();
   	}

IMHO, they are strong use cases that should be considered when tackling this issue.

That said, I agree with you all: 500 errors should behave equally, no matter if they come from throwing errors, res.internalError() or res.customError({statusCode: 500}).

How about applying the following changes?

1. In the piece of code linked in the description, before returning the output of hapiResponseAdapter.handle(kibanaResponse), we check the statusCode. If 500, we throw, letting the catch block work as expected.
2. Mark res.internalError() as deprecated, suggesting in the docs to throw instead.

I think that these changes will achieve our goal: log the error and respond "500 - Internal Error" with no changes needed on the plugins for now. Then, for use cases like the security ones, we can suggest devs to log their error as they like and throw a custom one that will be printed in the server's logs. Maybe something like throw new Error('Failed to authenticate. Check the audit logs for more details.')?

What do you think?

[afharo]

I've created this draft PR with the suggested changes in my previous comment: #85541