Should Libraries Log or Propagate Errors?
9 points by veqq
9 points by veqq
My assumption was always: Applications log (and err), libraries err.
Today, I was shocked to learn that various ecosystems love logging things in libraries (such that silencing those logs is even an important task). My view of logs has been around wide discrete events OR (for small scale personal things) writing errs in a file.
I was particularly surprised to learn this was an important consideration of making Go's slog, since you can easily propagate and enrich errors... Why not just err (and handle them by e.g. adding to the log context then retrying)? Or pass extra details in the return package?
What workflows etc. make this desirable? All I've been able to think of is the ability to change the log level and silence random extra information.
What if a library wants to report something other than an error? e.g. if it wants to log that an upstream service is degraded, but still functional (thus not necessarily an error).
How can the application surface that to the user?
I don't have a stable image URL to offer you but it's my recollection that Firefox annotates a lot of its chrome with yellow /!\ icons when it is sad, and Windows for sure has a long history of doing that
My point is more how would the application layer consume these logs if they wanted to do something with them, for example what you described. The application would have to consume and parse logs if the library were logging service degradation, rather than surfacing this data in a structured way.
Depends on the user persona, if the user persona is one that would read the logs, such as an administrator. I suppose logs are fine, if there is no administrator persona separation reasonable for the library then it's an issue of the interface of the library.
One use case I can think of is developer-facing extra error checkings that's too expensive to enable in production (thus, the public APIs of libraries often don't propagate those errors either). And examples coming to mindiare Vulkan validation layers and debug-mode only assertions
Question you should ask is if the information is actionable.
If it's a non-fatal error and there is nothing the user or caller can do based on the error message or error, then it doesn't make sense to tell them about it (unless on an optional debug log).
A good corner case to think about is close(2), which can fail, something everything that wraps the syscall has to deal with. There's realistically nothing you can do about it, and there are good reasons to avoid a retry if you get an error[1]. Some APIs (e.g. Java) throws an exception on this, but there's no way to handle it other than to just log it, so it just makes the API more annoying and boilerplaty for no benefit[2]. User may want to learn that their system is in a bad state or they may have lost data, so a log line would maybe be the most appropriate.
[1] close(2) man page says: Retrying the close() after a failure return is the wrong thing to do, since this may cause a reused file descriptor from another thread to be closed. This can occur because the Linux kernel always releases the file descriptor early in the close operation, freeing it for reuse; the steps that may return an error, such as flushing data to the filesystem or device, occur only later in the close operation.
[2] Every time you close a stream you have to do this
try {
is.close();
}
catch (IOException ex) {
logger.error("close failed", ex);
}
(or you build or use a wrapper that does this because why would the API itself have this built in; though try-with-resources sort of makes this a bit more tolerable)
I ran man 2 close on macOS and did not see that language, so it's a Linux-ism and this paragraph is available if others want the gory details https://manpages.ubuntu.com/manpages/resolute/man2/close.2.html#Dealing_with_error_returns_from_close() The very last sentence says Linux behavior differs from POSIX.1-2024 but they are happy with that
For the side of the coin: https://pubs.opengroup.org/onlinepubs/9799919799.2024edition/functions/posix_close.html#:~:text=portable%20applications%20should%20only%20retry%20a%20close
common use case: http libraries or similar exposing state machine information for connection state machines or similar. i would not say that they are expected to provide request logging (though many applications would likely desire to have such a request log as a feature); IMO most debugging scenarios of network traffic are solved better by supporting SSLKEYLOGFILE anyway.
nevertheless, i am increasingly becoming of the view that logging of anything but wide events is largely ineffective as a methodology and updating my practices accordingly.
oh, another hot take that i have just formed and not thought through: reasonable observability in a system involves two fundamental types of things: wide events and trace points. once the wide events point in the direction of the problem, the trace points should let you dtrace closer to the cause.
How do you to decide where to place trace points and how do you go through the data when investigating?
I'm not them but I'd guess the answer is driven by your own experiences while developing the library, and/or supplemented with when flow of control crosses a component boundary (web, http, database, filesystem, things that could take noticable time or fail in non-obvious ways)
As for going through the data, that's the theory behind OTel is that one can ship them into their favorite collection toy and explore them using its UX, which also includes (in theory) dev-null-ing the collection operation if the collector is not specified. So there would be a local method call to enregister the span but then it just gets flushed into the ether if no one is listening. I don't have as much experience with dtrace and its rr-project friend but I would image they are similar
One possible edge case you might want to consider is operators of software that use your library. If the software using your library has bad logging, operators might benefit from enabling logging in your library.
The question is a bit general; IMHO it depends a bit on the language and the ecosystem. (E.g. in languages with exceptions I suspect logging errors in libraries is much less useful than in languages with errors as values.)
it depends a bit on the language and the ecosystem
Understanding which ecosystems is the most interesting part!
in languages with exceptions I suspect logging errors in libraries is much less useful than in languages with errors as values
This is the exact opposite of my intuition, could you explain why you suspect this? I figured errors as values lets you handle the error to inform yourself without stopping operation - so logging would be less useful there.
I was mostly thinking about code that receives an error from somewhere else and does not propagate it. You wouldn't have much insight on those unless there's some logging. But really I'm not coming up with any great example. (And likely on languages with exceptions, the library would catch an exception to and not propagate it, so it should log it for visibility... so there's not much difference.)
One case where this was desirable for me was in an X.509 certification path processing library. We had one API call whose job was to construct and validate a certification path if possible, then return it along with a status to the user.
Depending on the configuration and the environment, a widely variable number of candidate paths could be evaluated, sometimes with remote resource fetches involved. It was possible for the library to successfully build and validate a path, but take a long time doing it. Detailed logging was really the only way to determine what aspect of a configuration or the environment was causing a slowdown. We made it granular, so that the developer (or operator) could enable only the interesting parts, but that library couldn't have reasonably propagated failed paths; logging was really the only effective choice.
ODBC libraries can produce logs. How much is logged is up to the application, but only the library knows the details.
For example, the library may read data from the network that is misencoded. The information cannot be rendered in the application’s specified character set, so perhaps is replaced by ‘?’ characters. There is literally nowhere for it to put what was actually read except in a log message.