Errors: to log, or not to log?

https://konradreiche.com/blog/effective-error-monitoring-in-go

Most of the times errors are returned to the calling code. What happens at the end though? Log the error? Logging every error results in a monitoring system which is noisy and easy to ignore.

What if we let errors define whether they should be logged or not? This way errors can be categorized, tracked as metric and communicate to the calling code what to do with the error.

Lightning Talk, GopherCon 2022, Chicago
https://www.youtube.com/watch?v=R3PKNFU3GMw

Transcript

1. Errors to log, or not to log? Konrad Reiche By Renée French (CC)
2. if err != nil { return nil, err }
3. if err != nil { return nil, err }
4. cmd, err := rdb.Get(ctx, "key") if err != nil { return nil, err }
5. resp, err := handler(ctx, req) middleware.go
6. resp, err := handler(ctx, req) if err != nil { log.Error(err) } middleware.go
7. [ERROR] client update: read tcp: i/o timeout [ERROR] dial tcp: lookup redis: i/o timeout [ERROR] write tcp 10.101.244.225:46470->192.168.22.191: i/o timeout [ERROR] redis: read tcp 10.101.244.225:46470->192.168.22.191:6379: i/o timeout [ERROR] fetch data: invalid parameter type: int [ERROR] context canceled [ERROR] unexpected end of JSON input [ERROR] read tcp 10.108.131.55:46078->192.168.10.169:9090: read: connection reset by peer [ERROR] internal error [ERROR] rpc error: code = Unknown desc = no actions were found to be valid [ERROR] rpc error: code = Canceled desc = context canceled [ERROR] context canceled [ERROR] context canceled [ERROR] HTTP 500: write tcp 10.108.251.133:9090->10.111.167.92:33674: i/o timeout [ERROR] rpc error: code = Unknown desc = no actions were found to be valid
8. Noisy Error Monitoring System - Time consuming to find critical errors - Error log is ignored altogether - Logging errors in the first place becomes pointless
9. [ERROR] client update: read tcp: i/o timeout [ERROR] dial tcp: lookup redis: i/o timeout [ERROR] write tcp 10.101.244.225:46470->192.168.22.191: i/o timeout [ERROR] redis: read tcp 10.101.244.225:46470->192.168.22.191:6379: i/o timeout [ERROR] fetch data: invalid parameter type: int [ERROR] context canceled [ERROR] unexpected end of JSON input [ERROR] read tcp 10.108.131.55:46078->192.168.10.169:9090: read: connection reset by peer [ERROR] internal error [ERROR] rpc error: code = Unknown desc = no actions were found to be valid [ERROR] rpc error: code = Canceled desc = context canceled [ERROR] context canceled [ERROR] context canceled [ERROR] HTTP 500: write tcp 10.108.251.133:9090->10.111.167.92:33674: i/o timeout [ERROR] rpc error: code = Unknown desc = no actions were found to be valid
10. [ERROR] client update: read tcp: i/o timeout [ERROR] dial tcp: lookup redis: i/o timeout [ERROR] write tcp 10.101.244.225:46470->192.168.22.191: i/o timeout [ERROR] redis: read tcp 10.101.244.225:46470->192.168.22.191:6379: i/o timeout [ERROR] context canceled [ERROR] rpc error: code = Canceled desc = context canceled [ERROR] context canceled [ERROR] context canceled [ERROR] HTTP 500: write tcp 10.108.251.133:9090->10.111.167.92:33674: i/o timeout
11. resp, err := handler(ctx, req) if err != nil { log.Error(err) } middleware.go
12. resp, err := handler(ctx, req) if err != nil { log.Error(err) } middleware.go
13. resp, err := handler(ctx, req) if err != nil { var e net.Error if errors.As(err, &e) && e.Timeout() { timeouts.Inc() return } log.Error(err) } middleware.go
14. resp, err := handler(ctx, req) if err != nil { var e net.Error if errors.As(err, &e) && e.Timeout() { timeouts.Inc() return } if errors.Is(err, context.Canceled) { contextsCanceled.Inc() return } log.Error(err) } middleware.go
15. cmd, err := rdb.Get(ctx, "key") if err != nil { return nil, err } redis.go middleware.go ... ...
16. cmd, err := rdb.Get(ctx, "key") if err != nil { return nil, err } redis.go middleware.go ... ...
17. cmd, err := rdb.Get(ctx, "key") if err != nil { var e net.Error if errors.As(err, &e) && e.Timeout() { timeouts.Inc() // ??? } return nil, err } redis.go middleware.go ... ...
18. type loggable interface { error Log() bool }
19. type ObservedError struct { cause error } func (e ObservedError) Log() bool { return false } func (e ObservedError) Unwrap() error { return e.cause }
20. cmd, err := rdb.Get(ctx, "key") if err != nil { var e net.Error if errors.As(err, &e) && e.Timeout() { timeouts.Inc() // ??? } return nil, err } redis.go middleware.go ... ...
21. cmd, err := rdb.Get(ctx, "key") if err != nil { var e net.Error if errors.As(err, &e) && e.Timeout() { timeouts.Inc() err = metrics.NewObservedError(err) return nil, err } return nil, err } redis.go middleware.go ... ...
22. resp, err := handler(ctx, req) if err != nil { var e loggable if errors.As(err, &e) && !e.Log() { return } log.Error(err) } middleware.go
23. [ERROR] client update: read tcp: i/o timeout [ERROR] dial tcp: lookup redis: i/o timeout [ERROR] fatal error: concurrent map read and map write [ERROR] redis: read tcp 10.101.244.225:46470->192.168.22.191:6379: i/o timeout [ERROR] fetch data: invalid parameter type: int [ERROR] context canceled [ERROR] unexpected end of JSON input [ERROR] read tcp 10.108.131.55:46078->192.168.10.169:9090: read: connection reset by peer [ERROR] internal error [ERROR] rpc error: code = Unknown desc = no actions were found to be valid [ERROR] rpc error: code = Canceled desc = context canceled [ERROR] context canceled [ERROR] context canceled [ERROR] HTTP 500: write tcp 10.108.251.133:9090->10.111.167.92:33674: i/o timeout [ERROR] rpc error: code = Unknown desc = no actions were found to be valid
24. [ERROR] fatal error: concurrent map read and map write [ERROR] fetch data: invalid parameter type: int
25. Thank you [@|u/]konradreiche[.com]