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

fix(qe): fix error logging #16287

Merged
merged 18 commits into from Nov 25, 2022
Merged

fix(qe): fix error logging #16287

merged 18 commits into from Nov 25, 2022

Conversation

miguelff
Copy link
Contributor

@miguelff miguelff commented Nov 15, 2022

Fixes #16226

This patch ensures that errors resulting in a failed query generate an event if the error logger is enabled.

This aligns with the principle of least astonishment: The user expects errors to be logged, and due to the lack of a formal definition of what constitutes an error, the most sensible approach in my opinion (backed by bug reports like #14933) is to log any condition leading to an error in the processing of the query, which is, in turn, any of the four well-known classes of errors.

This is done now in the RequestHandler thus capturing any possible error condition happening during query processing. Before, every different engine was doing this differently, and errors were not properly captured.

A smoke test suite proves that NotFoundError errors in findXOrThrow are now properly emitted. I consider this enough, given that the code that handles the error is the same for every exception thrown during query execution.

@miguelff miguelff changed the title WIP: Fix error logging Fix(qe): fix error logging Nov 16, 2022
@miguelff miguelff added this to the 4.7.0 milestone Nov 17, 2022
@miguelff miguelff self-assigned this Nov 17, 2022
@miguelff miguelff changed the title Fix(qe): fix error logging fix(qe): fix error logging Nov 17, 2022
@miguelff miguelff force-pushed the fix/error-logging branch 4 times, most recently from 50932be to 84f0538 Compare November 21, 2022 13:18
@miguelff miguelff marked this pull request as ready for review November 21, 2022 18:59
@miguelff miguelff requested review from a team, aqrln, millsp and SevInf and removed request for a team November 21, 2022 18:59
@miguelff

This comment was marked as outdated.

@miguelff
Copy link
Contributor Author

miguelff commented Nov 23, 2022

Did the following:

  • Tampered the binary engine:
diff --git a/query-engine/request-handlers/src/graphql/handler.rs b/query-engine/request-handlers/src/graphql/handler.rs
index 39cb2e08e1..15690c5b47 100644
--- a/query-engine/request-handlers/src/graphql/handler.rs
+++ b/query-engine/request-handlers/src/graphql/handler.rs
@@ -26,7 +26,6 @@ impl<'a> GraphQlHandler<'a> {
 
     pub async fn handle(&self, body: GraphQlBody, tx_id: Option<TxId>, trace_id: Option<String>) -> PrismaResponse {
         tracing::debug!("Incoming GraphQL query: {:?}", &body);
-
         match body.into_doc() {
             Ok(QueryDocument::Single(query)) => self.handle_single(query, tx_id, trace_id).await,
             Ok(QueryDocument::Multi(batch)) => match batch.compact(self.query_schema) {
@@ -44,7 +43,7 @@ impl<'a> GraphQlHandler<'a> {
 
     async fn handle_single(&self, query: Operation, tx_id: Option<TxId>, trace_id: Option<String>) -> PrismaResponse {
         use user_facing_errors::Error;
-
+        dbg!("Running single {}", query.clone());
         let gql_response = match AssertUnwindSafe(self.handle_graphql(query, tx_id, trace_id))
             .catch_unwind()
             .await
@@ -201,6 +200,9 @@ impl<'a> GraphQlHandler<'a> {
         tx_id: Option<TxId>,
         trace_id: Option<String>,
     ) -> query_core::Result<ResponseData> {
+        if 2 > 1 {
+            panic!("Forced")
+        }
         self.executor
             .execute(tx_id, query_doc, self.query_schema.clone(), trace_id)
             .await
  • Ran Prisma against the binary engine. The connection is reset before the actual panic is processed asynchronously. In this case, the error is correctly received by the client

  • Ran Prisma against the library engine. The behavior is correct.

I think this is ready for another pass.

miguelff and others added 18 commits November 24, 2022 11:13
In case error logging is enabled in the client, a middleware
captures errors and uses the event emitter to notify about them. This way, errors are captured in the same way accross the different engines, by capturing errors one level above in the call stack (at the client level)

After this approach is validated, next commits will:
- Filter the kind of errors that should be logged
- Create the appropriate structure for the logging event being emitted
- Add unit tests to check the behavior with the binary engine.
Our middleware is FIFO (a queue rather than an actual stack) so the first middleware would call on other middlewares defined by the user before hitting the actual request. As we don't want to observe on users's middleware errors, I moved the logic from a middleware to the point where the request is being made.

Also notice we don't want to block on user handling code upon request resolving, so the error handling code runs asynchronously. This has a side effect. If the execution of the program halts, before the promise is resolved in the next event loop tick, then the error won't be logged. This might not be an acceptable trade-off, and I might change it in a follow-up commit.
Error will flow up the stack and be captured by the RequestHandler
Co-authored-by: Daniel Starns <danielstarns@hotmail.com>
This change is about:
1. getting rid of lastErrorLog, lastRustError, lastPanic
state and instead build all the error information when we parse a log line if that's pertinent

2. Let request errors flow up the stack instead to be emitted in the RequestHandler.

3. Only emit events explicitly during lifecycle management of the binary engine
Copy link
Member

@aqrln aqrln left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One comment/question, but other than that, looks very good to me! Thank you for the fix and for the nice refactoring!

@miguelff miguelff merged commit 1962d3a into main Nov 25, 2022
@miguelff miguelff deleted the fix/error-logging branch November 25, 2022 11:54
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Bug(qe): errors don't get logged
4 participants