Something I see a lot, especially in node applications, is duplicate messages logged due to an exception being caught and logged in several places as the stack unwinds. For example with the following (contrived) code:
const httpCall = () => {
const url = 'http://example.com';
try {
throw new Error('Something went wrong!');
} catch (error: any) {
log(error.message, { url });
throw error;
}
};
The real error is here in httpCall, but some context about the error needs to be logged, so it is caught, logged and rethrown.
const callService = () => {
const someContext = 'The service we called';
try {
httpCall();
} catch (error: any) {
log(`Service failed: ${error.message}`, { someContext });
throw error;
}
};
httpCall is called from a service wrapper, which has its own context which needs to be logged, so again the error is caught, logged and rethrown.
const getController = () => {
try {
callService();
} catch (error: any) {
log(error.message, { error });
}
};
Finally the service wrapper is called from a controller and the error is caught and logged again. This results in three separate log messages which are all the same (or in some cases much the same) with three different context objects each giving slightly different information about what was happening at various points in the call stack:
[ERROR] Something went wrong! { url: 'http://example.com' }
[ERROR] Service failed: Something went wrong! { someContext: 'The service we called' }
[ERROR] Something went wrong! {
error: Error: Something went wrong!
at httpCall (/.../problem.js:7:15)
at callService (/.../problem.js:17:9)
A simple, partial solution is to only catch the error at the top of the call stack, in this case in the controller. This would still maintain the original error message, but a whole load of context is lost. This context might be needed, for example, to determine which HTTP status code should be returned.
Another solution might be to use JavaScript’s Error class’s cause option as described here. Similar features are supported by other languages. However, this doesn’t support adding extra context to the error, without some type manipulation, and would require additional logic to extract the cause(s) for the logger when caught, which could be better encapsulated into a new type. This also wouldn’t allow for adding further explicit context, such as an indication of the logging level or HTTP response code for the error.
Another solution is to use node’s AsyncLocalStorage and add all the necessary context to a global storage object at the points of catch and rethrow. While some loggers support taking the context out of local storage automatically, it is more likely that extra logic would be required to retrieve the context for the logger when the error is caught. To me this also feels a bit like magic, with the context being squirrelled away in one part of the code and retrieved in another elsewhere. AsyncLocalStorage can also come with a performance overhead.
A better solution is to use a Hierarchical Error as you can handle context and encapsulate creating a context object for the logger from any causes:
interface HierarchicalContextItem {
message: string;
cause?: HierarchicalContextItem | any;
context?: any;
}
class HierarchicalError extends Error {
readonly cause;
readonly context;
constructor(message: string, context?: any, cause?: any) {
super(message);
this.cause = cause;
this.context = context;
}
toContextJson = (): HierarchicalContextItem => ({
message: this.message,
context: this.context,
cause: this.cause instanceof HierarchicalError ? this.cause.toContextJson() : this.cause,
});
}
This allows the error message and context to be recorded at each point in the call stack. For example in httpCall:
const httpCall = () => {
const someContext = 'the url we called';
try {
throw new Error('Something went wrong!');
} catch (error: any) {
throw new HierarchicalError(error.message, { someContext }, error);
}
};
The original error message, context and the original error are used to construct a new instance of HierarchicalError which is then thrown. Notice that nothing is logged at this point now. Then in callService:
const callService = () => {
const someContext = 'The service we called';
try {
httpCall();
} catch (error: any) {
throw new HierarchicalError(`Service failed.`, { someContext }, error);
}
};
The error is caught, and used to create a new instance of HierarchicalError which adds its own error message and adds more context. Notice again that nothing is logged at this point.
Finally in the controller:
const get = () => {
try {
callService();
} catch (error: any) {
if (error instanceof HierarchicalError) {
log(error.message, error.toContextJson());
} else {
log(error);
}
}
};
if the caught exception is an HierarchicalError its message is logged along with the all the previous errors as context, which results in a single log message:
[ERROR] Service failed: Something went wrong! {
message: 'Service failed.',
context: { someContext: 'The service we called' },
cause: {
message: 'Something went wrong!',
context: { url: 'http://example.com' },
cause: Error: Something went wrong!
at httpCall (/.../solution.js:19:15)
at callService (/.../solution.js:28:9)
at get (/.../solution.js:36:9)
at main (/.../solution.js:48:5)
...
}
}
This is not a perfect solution which will work in all cases. Errors are often treated specially by loggers. They do not serialise well, so loggers often check the type and have special handling code. A custom toJSON method, which incorporates the toContextJSON method and the error message may be a good solution here.
Hierarchical errors provide a structured and more efficient way of managing error logging in complex applications, particularly those with multiple layers of function calls, as is common in node applications.
By encapsulating the original error, its context, and any additional information at each layer of the call stack, hierarchical errors allow for a more comprehensive view of what went wrong without unnecessary duplication in the logs. This approach also ensures that relevant context is preserved, which can be crucial for debugging and understanding the flow of execution.
By using the HierarchicalError class, developers can maintain the integrity of the error message while preventing log clutter and improving the clarity of error reports, ultimately making troubleshooting much easier and more effective.
Thank you to Dom Davis, Maxi Maxwell and Steve Cresswell for their contributions.
const httpCall = () => {
const url = 'http://example.com';
try {
throw new Error('Something went wrong!');
} catch (error: any) {
log(error.message, { url });
throw error;
}
};
The real error is here in httpCall, but some context about the error needs to be logged, so it is caught, logged and rethrown.
const callService = () => {
const someContext = 'The service we called';
try {
httpCall();
} catch (error: any) {
log(`Service failed: ${error.message}`, { someContext });
throw error;
}
};
httpCall is called from a service wrapper, which has its own context which needs to be logged, so again the error is caught, logged and rethrown.
const getController = () => {
try {
callService();
} catch (error: any) {
log(error.message, { error });
}
};
Finally the service wrapper is called from a controller and the error is caught and logged again. This results in three separate log messages which are all the same (or in some cases much the same) with three different context objects each giving slightly different information about what was happening at various points in the call stack:
[ERROR] Something went wrong! { url: 'http://example.com' }
[ERROR] Service failed: Something went wrong! { someContext: 'The service we called' }
[ERROR] Something went wrong! {
error: Error: Something went wrong!
at httpCall (/.../problem.js:7:15)
at callService (/.../problem.js:17:9)
A simple, partial solution is to only catch the error at the top of the call stack, in this case in the controller. This would still maintain the original error message, but a whole load of context is lost. This context might be needed, for example, to determine which HTTP status code should be returned.
Another solution might be to use JavaScript’s Error class’s cause option as described here. Similar features are supported by other languages. However, this doesn’t support adding extra context to the error, without some type manipulation, and would require additional logic to extract the cause(s) for the logger when caught, which could be better encapsulated into a new type. This also wouldn’t allow for adding further explicit context, such as an indication of the logging level or HTTP response code for the error.
Another solution is to use node’s AsyncLocalStorage and add all the necessary context to a global storage object at the points of catch and rethrow. While some loggers support taking the context out of local storage automatically, it is more likely that extra logic would be required to retrieve the context for the logger when the error is caught. To me this also feels a bit like magic, with the context being squirrelled away in one part of the code and retrieved in another elsewhere. AsyncLocalStorage can also come with a performance overhead.
A better solution is to use a Hierarchical Error as you can handle context and encapsulate creating a context object for the logger from any causes:
interface HierarchicalContextItem {
message: string;
cause?: HierarchicalContextItem | any;
context?: any;
}
class HierarchicalError extends Error {
readonly cause;
readonly context;
constructor(message: string, context?: any, cause?: any) {
super(message);
this.cause = cause;
this.context = context;
}
toContextJson = (): HierarchicalContextItem => ({
message: this.message,
context: this.context,
cause: this.cause instanceof HierarchicalError ? this.cause.toContextJson() : this.cause,
});
}
This allows the error message and context to be recorded at each point in the call stack. For example in httpCall:
const httpCall = () => {
const someContext = 'the url we called';
try {
throw new Error('Something went wrong!');
} catch (error: any) {
throw new HierarchicalError(error.message, { someContext }, error);
}
};
The original error message, context and the original error are used to construct a new instance of HierarchicalError which is then thrown. Notice that nothing is logged at this point now. Then in callService:
const callService = () => {
const someContext = 'The service we called';
try {
httpCall();
} catch (error: any) {
throw new HierarchicalError(`Service failed.`, { someContext }, error);
}
};
The error is caught, and used to create a new instance of HierarchicalError which adds its own error message and adds more context. Notice again that nothing is logged at this point.
Finally in the controller:
const get = () => {
try {
callService();
} catch (error: any) {
if (error instanceof HierarchicalError) {
log(error.message, error.toContextJson());
} else {
log(error);
}
}
};
if the caught exception is an HierarchicalError its message is logged along with the all the previous errors as context, which results in a single log message:
[ERROR] Service failed: Something went wrong! {
message: 'Service failed.',
context: { someContext: 'The service we called' },
cause: {
message: 'Something went wrong!',
context: { url: 'http://example.com' },
cause: Error: Something went wrong!
at httpCall (/.../solution.js:19:15)
at callService (/.../solution.js:28:9)
at get (/.../solution.js:36:9)
at main (/.../solution.js:48:5)
...
}
}
This is not a perfect solution which will work in all cases. Errors are often treated specially by loggers. They do not serialise well, so loggers often check the type and have special handling code. A custom toJSON method, which incorporates the toContextJSON method and the error message may be a good solution here.
Hierarchical errors provide a structured and more efficient way of managing error logging in complex applications, particularly those with multiple layers of function calls, as is common in node applications.
By encapsulating the original error, its context, and any additional information at each layer of the call stack, hierarchical errors allow for a more comprehensive view of what went wrong without unnecessary duplication in the logs. This approach also ensures that relevant context is preserved, which can be crucial for debugging and understanding the flow of execution.
By using the HierarchicalError class, developers can maintain the integrity of the error message while preventing log clutter and improving the clarity of error reports, ultimately making troubleshooting much easier and more effective.
Thank you to Dom Davis, Maxi Maxwell and Steve Cresswell for their contributions.
This seems reasonable, but is mainly needed because Javascript has such a loosely-defined error concept. In java, this notion is already built in to every error and exception from the base Throwable class upwards, and is therefore supported by all Java logging frameworks.
ReplyDeleteThis is excellent advice. I particularly dislike seeing an error message when it's been recovered from further up the call stack, perhaps with a retry, at which point it's only a warning at best. Only the caller knows the real outcome and how it should be presented.
ReplyDeleteI first came across this pattern under the name Diagnostic Context as part of Neil Harrison's pattern language "Patterns for logging diagnostic messages" in Pattern Languages of Program Design vol. 3 [1997]. It become the basis of my own attempts to extend this to the distributed world in the late 2000's, which I wrote up for ACCU in 2013 as Causality – Relating Distributed Diagnostic Contexts (https://accu.org/journals/overload/21/114/oldwood_1870/).
Another timeless pattern language around errors is The Generation, Management and Handling of Errors (Parts 1 & 2) from Andy Longshaw and Eoin Woods. (https://accu.org/journals/overload/17/92/longshaw_1575/)