Discussion continuation: current design decision for error.cause is surprising and confusing #126
Comments
|
Hey! I'm building the alternative approach, serializing everything, here: https://github.com/derangeddk/serialize-every-error#readme I think it's absolutely fine to have options, and fortunately it's easy to configure alternate serializers. Perhaps making it easier to discover them could be useful? Hope you'll check out my work, give feedback or contribute if you want a serializer that takes a different approach from the standard 😁 |
Hey @hypesystem ! I saw your library and am planning to check it out. Thank you for your work and constant positivity 🙏 |
|
Fair enough—from my perspective the case is settled, and the pino team have made their direction clear. I respect that 😁 More than that, I think consistency (here in what to expect per default) is really important for users of libs. So now that they have set out their position clearly, my position is to back that |
Discussions are always welcome as they keep being respectful and well intended. We do not have a moderation team and we are all quite busy. If a discussion gets too heated (like it happened for this previously), we swiftly close it. I'll respond on the subject of this asap. |
Thank you! Looking forward to your response. |
|
First of all I agree with the current behavior, and that has been a deliberate choice. I do not think that fully exposing Error objects in logs is a good default behavior, mostly because this exposes at unexpected privacy risks (including GDPR violations). Consider an error object coming from a failing SQL query that contained all parameters: it would lead to a GDPR violation in most systems. Another example is post-processing. Right now I'm all ears for a better serialization algorithm that retains the current principles and it's simpler to parse/manipulate. Wdyt @voxpelli? Given how this is a heated discussion, I would be ok in having an official/blessed serializer that can be configured to cater for those cases - however this must be a user deliberate choices. |
|
Thank you for your comments.
If that's the concern leading to the "error.cause" implementation, then it's just as valid a concern for the regular error serialization implementation. Currently if I log an "err" that has sensitive fields- they will be printed. I don't see why this behavior should be different between the top level error and its error.cause, as they're both just as likely to have sensitive fields. I agree that this is an extremely valid concern, but I do think this concern has other valid solutions currently:
I'm not sure I understand what would break in this case, happy to take a look at it! I think the simplest API for pino is having the error object behave like all other objects (no special serialization except maybe making sure
I really tried to avoid making this a heated discussion. Sorry if I didn't succeed! |
|
Consider this example: const logger = require('pino')()
try {
const e = new Error('kaboom')
e.foo = 'bar'
const b = new Error('cause')
b.something = 'private'
e.cause = b
throw e
} catch (err) {
logger.error({ err }, 'something went wrong')
}This generates: Personally the only thing that I would change is: into Mostly because I find that additional What would you like to generate?
The different is that if I'm logging a given error, I'm pretty sure I'm deliberately logging that object. This is a bit harder to know for objects that are 3-4 level deep.
We are not in agreement. The concern here is that they would have these properties added to their logs at different levels (can be even 3-4 level deep) without them deliberately deciding to log those. I would be very happy to have a |
|
Like @mcollina I'm currently quite busy as well, but will try to give some quick response: First and foremost: I think it would be good with some references to prior art that shows the use of the alternative way of logging Error Causes. Eg these approaches are similar to the current approach:
Then you want a generic object serializer, not an error serializer? You don't have to use an error serializer?
I like the What I like about it is that it shows a clear difference between a Eg: Personally I have found the latter of the two much more useful when grouping errors on error messages, something that is useful to do in eg the ELK stack. But I'm open to scrap it if people find it odd, but I would for sure add it back for my personal use. |
|
Hello, I just ran into essentially this issue today after one of our developer complained about his error's cause not showing up in his logs. We then went down the rabbithole of how fastify->pino gets setup when you pass logger options to your fastify server all the way down to finally digging into the implementation of pino-std-serializer. Based on just this experience I would say that the current behaviour is potentially too far from the developer's expectations, and thats for the developers who actually notice that the |
@jordanebelanger Could you share some more insight into where the developer expected what and hence why the way they got it was not what they expected? |
|
Actually, and I think we concluded this in an earlier thread on this matter, I think the wrong behavior is maybe to actually copy all the other keys: #27 As copying all the other keys can make it weird when |
|
It seems that the experience (which I also had) of expecting everything to be logged and being disappointed is common. Perhaps highlighting alternative serializers in the docs could be an approach for solving this experience. I completely understand your reasons for the standard being as it is, but maybe it could be highlighted in the main pino docs, with links to documentation on how to replace the serializers? If this seems like a reasonable compromise I'm more than happy to put in some work on this, whichever way you want to go 😄 |
@hypesystem If so I would like to highlight use cases where one or the other makes sense. I'm still looking for someone to describe the full use case of the alternative approach. I myself have used VError in production a long time with eg. ELK stacks, AWS logging etc and the current serialization method mimics that and is as useful as any VError logging ever was? |
|
@voxpelli In my case it is usually down to doing complex nested errors, that is, errors where the nested cause has important context for debugging added as fields. We tend to write "pretty" top-level errors that place an error in context (and e.g. ensure it fails nicely) but have context for why exactly the error occurred in (sometimes custom) nested errors, often using fields that aren't serialized by pino's standard error serializer. I hope that makes sense - trying to keep it short - otherwise I'm happy to elaborate |
|
In a similar vein, If I might rephrase my point from earlier this week, it's not a question of error logging best practices but rather a question of developers' expectations. Now that But, I agree 100% that there are better logging practices, and even that we might be encouraging bad practices by doing this, but at the same time it's probably not the role of a |
Can we please refrain from making claims of speaking for the wider developer community when we have no other references to point to than our own perceptions? Expectation wise from the current solutions point of view:
Keeping with the established logging practices of +10 years of VError logging can't be entirely against all developer expectations? |
I'm sorry, I didn't mean to speak for anybody. To be completely honest, I was trying to be polite. So full disclosure, rather then pursue the idea that this is about other developers expectations, I'll just be blunt and say that personally I think it's just common sense that the cause field would be logged by the std serializer now that the field is officially part of es2022. This is my personal opinion, I don't mean to speak for anybody else, and I am fully open to the idea that views could be divergent or that I could be straight up wrong and it's illogical. |
The VError field gets standardized and because it got standardized it should be logged in a different way? It might be useful to point out that the current implementation actually supports both VError and Error Causes, enabling seamless logging of legacy causes and standardized causes. |
|
Hey @voxpelli, did you see the case I explained? #126 (comment) Is there anything you'd like elaborated? Does it make sense to you? |
I mostly see an explanation of how you're creating errors, not how you actually consume them in the log outputs. The data logged needs to be consumable in a way that is usable and sensible and I would want to see some use cases where the nested error model is usefully consumed |
|
I think the definitions of "usable" and "sensible" are are really far into subjective territory. The open question, as I see it, is how opinionated the pino project wants to be. There are people creating and consuming errors in ways where they expect the cause field to be serialized fully. That sould be evident from this discussion popping up again and again. Is it suboptimal to different ways of structuring errors? Perhaps, but that's also kind of not the point. The point is that people would like pino to cater to their use cases rather than adjusting their code bases to a narrow set of expectations from pino. I'm honestly a bit confused about the slightly combative tone I'm seeing from you @voxpelli and what the point is of taking this hard stance on exactly one narrow way of doing things, unless people can prove to you that their approaches are better --- by your assessment. In the name of not turning this heated (to use the words of @mcollina) I think I'mma tap out and leave you all to figure it out. I hope you consider how your communication comes off, though... |
|
@hypesystem My defensive tone is because I don't see anyone who wants to weigh the pros and cons of both options.
This is precisely what I'm asking to get to know, which ways exists where people are having these expectations? I want to get to know these use cases. |
|
Just going to reiterate: I'm not going to participate further here. I would like to help with this package and make it the best it can possibly be. But we're not going to find that in a discussion that keeps devolving to this. |
|
😮💨 Let's dial it back a bit here. In my view, the current implementation is as it is because 1. we cannot satisfy everyone's requirements, 2. we cannot keep going back and forth on the implementation, and 3. @voxpelli has put in the work. The purpose of I completely agree that it can be surprising that That being said, I think it would be quite reasonable to add an |
|
+1 for errWithCause serializer |
- Created new serializer called "errWithCause". This serializer acts very similarly to the default "err" serializer. The differences: When it encounters an "error.cause" field, it serializes it recursively to create a nested object of errors. This is as opposed to the default error serializer, in which the resulting serialized object has no "cause" field, and the causes' messages & stack traces are appended to the original error.message and error.stack - Since some logic is reused between the existing err serializer and the new one, I moved some logic to the err-helpers file - Created a test-file for the new serializer. It is very similar to the existing err serializer test file since they should behave nearly identically. The differences are in the tests that test for the "cause" related behavior. - Upgrade tsconfig.json "lib" to support error.cause fields. pinojs#126
Yes, opened a PR here: #130 |
Hi maintainers, love your library - thank you so much. We've been using it for over 2 years at our startup and it's great.
I know that the behavior surrounding
error.causeis intentional, as discussed mainly in #110 (the discussion there is now locked)This issue is meant to express a personal experience and opinion.
If discussions issues are not welcome here, I apologize. Please let me know if there's a different communication channel for constructive discussion regarding
pinoserializers (or maybe none at all).If that's the case, I'll close this issue and happily use the suggested configurations to fix my issue.
Current design advantages
I completely agree that just printing the full error + causes serialized object causes duplication in the stack trace. However, I believe the solution is less useful than doing nothing (explained below), and I also think that there is a "win win" solution here, detailed below.
Current design cons
Currently, by default,
error.causes are entirely omitted from the log output. In their stead, the original error's message and stack traces are concatenated as a string. I believe this behavior is surprising and detrimental. I'm not going to do a deep dive in to the reasons since they were very well explained by @hypesystem in this comment. In short:messageandstackTraceis unexpected and weird since serialization usually does not change string valuesRebuttal to design decision
optimizing for usefulness per size (message and stack are concatenated but causes are not serialized in full)(link):I think the usefulness of the error stack trace is reduced dramatically, so the goal of the design choice is not achieved. The common use case of
error.causeis wrapping an infrastructure library (like Apollo, TypeORM, express etc.) with a userland error. In these cases, the userland error explains the context of the error creation (e.g "error while trying to create user"), and the "cause" error explains the technical reasons for the error (e.g "duplicate primary key"). If the "cause" error includes extra fields, they're usually extremely helpful. Examples:I think that for 90% of the use cases a summary of the cause chain is good enough.(link):I disagree with this, but this is anecdotal. I don't think either of us has numbers to justify their opinion, so this is merely opinion. When it comes to matters of opinion, yours matters more than mine since you're the maintainers of this library, but I hope you're open to others' opinions.
Proposed solution
I think we can implement a solution that:
My solution is to fully serialize the error.cause object (even if nested), but to remove all "caused by" rows from the stack traces, such that each error's stack trace only includes their own lines, and there's zero duplication.
I believe this is a win-win solution that caters to everybody's wants, and I'm happy to implement it if the maintainers agree that this is an acceptable solution.
I don't even believe this is a breaking change since is only adds fields to the response. It does removes parts of the "stackTrace" and "message" fields, but these were strings and I wouldn't expect anybody to rely on their parsing. To be safe, this can be added in the next major version.
This is a long post. I tried to make it as clear as possible. I hope the maintainers take a moment to read this. It was aimed to be positive and constructive. If this is not welcome, I'll simply use a custom serializer as suggested, but I'd rather have a professional discussion surrounding this issue.
Thank you!
The text was updated successfully, but these errors were encountered: