feat: structured error logging / propagation#32
Conversation
hainsdominic
requested review from
DuncanUszkay1,
adampetro,
andrewhassan and
davejcameron
| .into_inner(); | ||
| let output: serde_json::Value = serde_json::from_slice(output.as_slice()) | ||
| .map_err(|e| anyhow!("Couldn't decode Function Output: {}", e))?; | ||
| let output = serde_json::from_slice(raw_output.as_slice()).unwrap_or_default(); |
There was a problem hiding this comment.
If we fail to parse the output as JSON, we might want to show the user the raw string value instead of null so they can more easily debug what's happening. I'm thinking of a case where the function has a bug in it that causes it to output invalid JSON.
There was a problem hiding this comment.
+1. Also I wonder if it makes sense to use serde_json::Value::Null as the default here because that is also a possible output from the function. What if we had an enum like this:
enum FunctionOutput<'a> {
Json(serde_json::Value),
Other(&'a [u8]), // not sure what the best value is here
}and then for the Other variant we could output it but maybe using red on the header with a note that it was invalid JSON
There was a problem hiding this comment.
The very last thing a Function does is returning its result, if the Function fails before returning, it will no return anything. "Returning" here is printing to stdout. However, if the value returned is not valid JSON, then an other error will occur. I forgot about this edge case and I'll update this PR with a fix. I really like the FunctionOutput enum idea, I'll play with that also.
| .into_inner(); | ||
| let output: serde_json::Value = serde_json::from_slice(output.as_slice()) | ||
| .map_err(|e| anyhow!("Couldn't decode Function Output: {}", e))?; | ||
| let output = serde_json::from_slice(raw_output.as_slice()).unwrap_or_default(); |
There was a problem hiding this comment.
+1. Also I wonder if it makes sense to use serde_json::Value::Null as the default here because that is also a possible output from the function. What if we had an enum like this:
enum FunctionOutput<'a> {
Json(serde_json::Value),
Other(&'a [u8]), // not sure what the best value is here
}and then for the Other variant we could output it but maybe using red on the header with a note that it was invalid JSON
Co-authored-by: Adam Petro <adamapetro@gmail.com>
| let title = " Benchmark Results ".black().on_bright_green(); | ||
| let title = " Benchmark Results " | ||
| .black() | ||
| .on_truecolor(150, 191, 72); |
There was a problem hiding this comment.
Why did we change the color?
There was a problem hiding this comment.
The first one is Shopify's green color, the second one (for the logs) is blue. The third one, for successful JSON I chose green and where there is an error it it red. I changed the first green to not have 2 of the same color as headers.
| writeln!( | ||
| f, | ||
| "{}\n\n{}", | ||
| " Invalid Output ".black().on_bright_red(), |
There was a problem hiding this comment.
Is there any value in stating why the output is invalid (cannot be parsed as JSON)?
There was a problem hiding this comment.
What do you mean?
There was a problem hiding this comment.
As a user, all I see is Invalid Output. How do I know why it is invalid?
There was a problem hiding this comment.
Right. I'll add the Json parsing error to the logs section
There was a problem hiding this comment.
When the output is nothing:
When the output is something invalid:
There was a problem hiding this comment.
Is it possible this could lead to confusion since we are mixing logs from the function and logs from function-runner?
There was a problem hiding this comment.
I think this is solved by adding the JSON deserialization error message. What else do you think would be good?
There was a problem hiding this comment.
Possibly. I find it a bit confusing that we are combining the function logs (STDERR) and errors that function-runner encountered (non-zero exit code, output that cannot be parsed to JSON). I wonder if we would benefit from taking a similar approach to what we have in partner's dashboard where logs (STDERR) and the errors we encounter are in separate sections. Just an idea; open to what others think.
There was a problem hiding this comment.
I think it'd be good to split them out to make it clear that you won't see the same error in production. I could imagine debugging this and thinking "Why am I getting a JSON deserialization error logged locally but not in production? What's logging that?"
There was a problem hiding this comment.
I splitted the Json error from the logs by tweaking the enum
4 participants
Why
Currently, when a function reaches the
unreachableinstruction (panics), the output will look like this:2x "Error:", no separation between logs and performance metrics and even no info at all opposed to what you would get by running a working function. Also, some logging info is lost, so it makes debugging harder.
How
This is how the new error reporting looks like:
There is now the headers between the "results" and the "logs" that were previously only visible on successful functions.
There is now an "Error" header/block that displays the error reported by the Wasm engine.
In the logs, there is now the panic message from the Wasm binary itself. This will help debugging, because it allows to see the panic message and it even shows on what line the panic occurred.
Detail
Before, the structured output was not displayed, because the engine run function panicked because it was not able to serialize the output from the function. That was fixed by setting the output to null if the function did not output (as it happens when it panics).