Problem
Error logs miss contextual data, which are important to understand and troubleshoot the problem.
Solution
Add log fields containing contextual error data.
If the error is raised deep in the call stack, then consider adding additional data to the returned error. Extract and add this contextual data to your structured logs when handling the error.
Example
Let’s consider that we have following HTTP request handler (full code):
func OrderHandler(w http.ResponseWriter, r *http.Request) {
var request struct {
Product string `json:"product"`
Quantity int `json:"quantity"`
}
json.NewDecoder(r.Body).Decode(&request)
log := logrus.WithField("request", request)
price, err := order(request.Product, request.Quantity)
if err != nil {
log.WithError(err).Error("order failed")
w.WriteHeader(http.StatusInternalServerError)
return
}
log.WithField("price", price).Info("order submitted")
fmt.Fprintf(w, "%.2f", price)
}
func order(product string, quantity int) (float64, error) {
productSHA := sha256.Sum256([]byte(product))
productCode := hex.EncodeToString(productSHA[:])
price, err := getPrice(productCode)
if err != nil {
return 0, fmt.Errorf("get price: %v", err)
}
return price * float64(quantity), nil
}
func getPrice(productCode string) (float64, error) {
resp, err := http.Get("https://price-service/" + productCode)
if err != nil {
return 0, fmt.Errorf("http get: %v", err)
}
defer resp.Body.Close()
body, err := ioutil.ReadAll(resp.Body)
if err != nil {
return 0, fmt.Errorf("read reponse: %v", err)
}
price, err := strconv.ParseFloat(string(body), 64)
if err != nil {
return 0, fmt.Errorf("parse response: %v", err)
}
return price, nil
}When getPrice fails we get a log like:
time="2009-11-10T23:00:00Z" level=error msg="order failed" error="get price: http get: Get https://price-service/9ed1515819dec61fd361d5fdabb57f41ecce1a5fe1fe263b98c0d6943b9b232e: dial tcp: Protocol not available" request="{pizza 2}"The problem is that productCode is not logged in a structured manner. For example, it would be difficult to efficiently extract all product codes from all error logs.
Solution 1 – Error Wrapping and Logger Formatter
To solve this issue we can use a custom error type, which supports adding contextual fields together with a logger formatter which is able to extract these fields from the error. This can be easily done using logrusutil‘s errfield package (full code):
// somewhere when bootstrapping the application: logrus.SetFormatter(&errfield.Formatter{})
func order(product string, quantity int) (float64, error) {
productSHA := sha256.Sum256([]byte(product))
productCode := hex.EncodeToString(productSHA[:])
price, err := getPrice(productCode)
if err != nil {
err := errfield.Add(err, "product_code", productCode)
return 0, fmt.Errorf("get price: %w", err) // notice %w instead of %v
}
return price * float64(quantity), nil
}Now the log contains the product_code field:
time="2009-11-10T23:00:00Z" level=error msg="order failed" error="get price: http get: Get https://price-service/9ed1515819dec61fd361d5fdabb57f41ecce1a5fe1fe263b98c0d6943b9b232e: dial tcp: Protocol not available" product_code=9ed1515819dec61fd361d5fdabb57f41ecce1a5fe1fe263b98c0d6943b9b232e request="{pizza 2}"Solution 2 – Refactoring
Often the code can (and should) be refactored in a way that would not require using the presented technique. In the above example, we can simply move the productCode generation to OrderHandler (full code):
func OrderHandler(w http.ResponseWriter, r *http.Request) {
var request struct {
Product string `json:"product"`
Quantity int `json:"quantity"`
}
json.NewDecoder(r.Body).Decode(&request)
log := logrus.WithField("request", request)
productSHA := sha256.Sum256([]byte(request.Product))
productCode := hex.EncodeToString(productSHA[:])
log = logrus.WithField("product_code", productCode)
productPrice, err := getPrice(productCode)
if err != nil {
log.WithError(err).Error("get price failed")
w.WriteHeader(http.StatusInternalServerError)
return
}
price := productPrice * float64(request.Quantity)
log.WithField("price", price).Info("order submitted")
fmt.Fprintf(w, "%.2f", price)
}
func getPrice(productCode string) (float64, error) {
resp, err := http.Get("https://price-service/" + productCode)
if err != nil {
return 0, fmt.Errorf("http get: %v", err)
}
defer resp.Body.Close()
body, err := ioutil.ReadAll(resp.Body)
if err != nil {
return 0, fmt.Errorf("read reponse: %v", err)
}
price, err := strconv.ParseFloat(string(body), 64)
if err != nil {
return 0, fmt.Errorf("parse response: %v", err)
}
return price, nil
}Log output:
time="2009-11-10T23:00:00Z" level=error msg="get price failed" error="http get: Get https://price-service/9ed1515819dec61fd361d5fdabb57f41ecce1a5fe1fe263b98c0d6943b9b232e: dial tcp: Protocol not available" product_code=9ed1515819dec61fd361d5fdabb57f41ecce1a5fe1fe263b98c0d6943b9b232eSimpler and better, don’t you agree?
However, there are times where this refactoring is almost impossible as the contextual data that you wish to log is deep in the call stack.
Advantages
- Detailed contextual data in a single error log.
- Makes it possible to handle the error once without losing important tracing data.
- [Solution 1] Easy to plugin with Go 1.13+ errors, pkg/errors or emperror.
Disadvantages
- [Solution 1] Adds and couples the code to new abstractions.
- [Solution 1] Adds additional computational complexity, because of unwrapping.
- [Solution 1] It is tricky. Log fields are magically added.
- Results in more code.
Closing
This pattern is very powerful but comes with design and readability trade-offs. In most of the cases, it should be considered as an anti-pattern. Always try to refactor the code in a way that would not require to use this pattern. Even though, I think that there are cases when this pattern helps a lot.
Robert Pajak - My Dev Diary 