3 ms·

I would add couple more things to it: * use some kind of context for the transaction to include unique id that is common theme through the system (maybe unique

I would add couple more things to it: * use some kind of context for the transaction to include unique id that is common theme through the system (maybe unique id originating from external system). This is called mapped diagnostic context in Log4j. This lets you grep all your logs for information about single transaction. Even better if you do this consistently for all services. * offload metrics from logs to appropriate tool * offload audit information from logs. I have a service that gathers all information of type (service A called service B and got C result for transaction D) and I have a simple page that can find information for transaction D and produce sequence graph where lanes are services involved. * do not log an information twice. Don't log an error and throw the error (either you throw it or handle and log). It is ok to log additional information when passing error that would otherwise be lost.

skissane 6y ago
> use some kind of context for the transaction to include unique id that is common theme through the system (maybe unique id originating from external system) Oracle has this concept called "ECID" (Execution Context ID), where the first component in the system to get a HTTP request assigns it an ID, and then that gets passed down as a custom HTTP header through the system. Since a HTTP request can produce sub-requests (e.g. talking to backend micro-services), the ECID becomes hierarchical in which subrequest identifiers get appended to the ECID of the original request. The ECID can even get passed through JDBC into the RDBMS so you can correlate database logs with logs at the higher layers. > do not log an information twice. Don't log an error and throw the error (either you throw it or handle and log) Unfortunately, my personal experience is you can't always trust your caller to log exceptions properly. (Especially when you are just working on one component in some huge system over which you lack overall control.) Throw and log can add noise to the logs (the same exceptions gets logged two or more times), but it also reduces the risk that the exception just disappears and never gets logged at all. (Or gets logged incompletely – don't get me started about Java apps and libraries that rethrow exceptions without setting the cause, meaning you lose information on the root cause of the exception.)
- lmilcin 6y ago
  1. The ID should ideally be from external system so that it is possible to always locate the records by ID known to the user. Let's say I am support and I want to figure out what happened, the user gives me the ID and I can use it to find the logs for this unique transaction, even if the user did not get any response. 2. Well, it is ok to log the error when it crosses component boundaries, this is basically what you do when you log an error before returning it from your service to another service. Ideally, there would be some coding guidelines that would enforce rather uniform error logging. We are enforcing this on code review.
- oftenwrong 6y ago
  >Unfortunately, my personal experience is you can't always trust your caller to log exceptions properly. (Especially when you are just working on one component in some huge system over which you lack overall control.) Throw and log can add noise to the logs (the same exceptions gets logged two or more times), but it also reduces the risk that the exception just disappears and never gets logged at all. (Or gets logged incompletely – don't get me started about Java apps and libraries that rethrow exceptions without setting the cause, meaning you lose information on the root cause of the exception.) I know this to be 100% true. I deal with it at my dayjob. However, I will always take the hard-line stance that the caller needs to be fixed in these cases.
boyter 6y ago
Agree with the unique log. While filename/line number seems good at first, its more mental overhead to find the file and then go to the line number. I tend to add a unique id based which is usually just the first 7 characters from any hash function. Something like date | md5sum | cut 1-7 which gives you something unique for each log message making it really easy to identify where it happened in any codebase using your search tool of choice. You have to embed the value into the code itself for the benefit, but its really useful in the short/long term. I was debugging a lot of lambda functions and this really ended up saving a lot of time as at runtime that was about the only information you could get. One other thing I found useful was to use JSON format for logs. I know there are many against this, but I found being able to add additional params without breaking existing tooling was a massive win, plus it formatted nicely in cloud-trail. Later on I realised most of our logs were processed by humans second and computers first, so having a machine readable format was really a benefit. Additional we were using Scalyr at the the time, so each new value in the JSON became an additional filter which was a very nice outcome.

skissane 6y ago

> use some kind of context for the transaction to include unique id that is common theme through the system (maybe unique id originating from external system) Oracle has this concept called "ECID" (Execution Context ID), where the first component in the system to get a HTTP request assigns it an ID, and then that gets passed down as a custom HTTP header through the system. Since a HTTP request can produce sub-requests (e.g. talking to backend micro-services), the ECID becomes hierarchical in which subrequest identifiers get appended to the ECID of the original request. The ECID can even get passed through JDBC into the RDBMS so you can correlate database logs with logs at the higher layers. > do not log an information twice. Don't log an error and throw the error (either you throw it or handle and log) Unfortunately, my personal experience is you can't always trust your caller to log exceptions properly. (Especially when you are just working on one component in some huge system over which you lack overall control.) Throw and log can add noise to the logs (the same exceptions gets logged two or more times), but it also reduces the risk that the exception just disappears and never gets logged at all. (Or gets logged incompletely – don't get me started about Java apps and libraries that rethrow exceptions without setting the cause, meaning you lose information on the root cause of the exception.)

lmilcin 6y ago
1. The ID should ideally be from external system so that it is possible to always locate the records by ID known to the user. Let's say I am support and I want to figure out what happened, the user gives me the ID and I can use it to find the logs for this unique transaction, even if the user did not get any response. 2. Well, it is ok to log the error when it crosses component boundaries, this is basically what you do when you log an error before returning it from your service to another service. Ideally, there would be some coding guidelines that would enforce rather uniform error logging. We are enforcing this on code review.
oftenwrong 6y ago
>Unfortunately, my personal experience is you can't always trust your caller to log exceptions properly. (Especially when you are just working on one component in some huge system over which you lack overall control.) Throw and log can add noise to the logs (the same exceptions gets logged two or more times), but it also reduces the risk that the exception just disappears and never gets logged at all. (Or gets logged incompletely – don't get me started about Java apps and libraries that rethrow exceptions without setting the cause, meaning you lose information on the root cause of the exception.) I know this to be 100% true. I deal with it at my dayjob. However, I will always take the hard-line stance that the caller needs to be fixed in these cases.

boyter 6y ago

Agree with the unique log. While filename/line number seems good at first, its more mental overhead to find the file and then go to the line number. I tend to add a unique id based which is usually just the first 7 characters from any hash function. Something like date | md5sum | cut 1-7 which gives you something unique for each log message making it really easy to identify where it happened in any codebase using your search tool of choice. You have to embed the value into the code itself for the benefit, but its really useful in the short/long term. I was debugging a lot of lambda functions and this really ended up saving a lot of time as at runtime that was about the only information you could get. One other thing I found useful was to use JSON format for logs. I know there are many against this, but I found being able to add additional params without breaking existing tooling was a massive win, plus it formatted nicely in cloud-trail. Later on I realised most of our logs were processed by humans second and computers first, so having a machine readable format was really a benefit. Additional we were using Scalyr at the the time, so each new value in the JSON became an additional filter which was a very nice outcome.