|
| 1 | +# Meridio - logging |
| 2 | + |
| 3 | +Meridio uses structured logging implemented by |
| 4 | +[go-logr/logr](https://github.com/go-logr/logr). Structured logging |
| 5 | +means that printf-like formatted messages are not used, instead |
| 6 | +key/object pairs are passed to the log functions. |
| 7 | + |
| 8 | +```go |
| 9 | +import "github.com/nordix/meridio/pkg/log" |
| 10 | + |
| 11 | + var config Config |
| 12 | + err := envconfig.Process("ipam", &config) |
| 13 | + if err != nil { |
| 14 | + panic(err) // We can't log since we have no logger yet |
| 15 | + } |
| 16 | + logger := log.New("Meridio-ipam", config.LogLevel) |
| 17 | + logger.Info("Configuration read", "config", config) |
| 18 | +``` |
| 19 | + |
| 20 | +When executed this will produce (formatted with |
| 21 | +[jq](https://stedolan.github.io/jq/)); |
| 22 | + |
| 23 | +```json |
| 24 | +{ |
| 25 | + "severity": "info", |
| 26 | + "timestamp": "2022-08-31T09:04:03.482+00:00", |
| 27 | + "service_id": "Meridio-ipam", |
| 28 | + "message": "Configuration read", |
| 29 | + "version": "1.0.0", |
| 30 | + "extra_data": { |
| 31 | + "config": { |
| 32 | + "Port": 7777, |
| 33 | + "Datasource": "/run/ipam/data/registry.db", |
| 34 | + "TrenchName": "red", |
| 35 | + "NSPService": "meridio-nsp-red:7778", |
| 36 | + "PrefixIPv4": "172.16.0.0/16", |
| 37 | + "ConduitPrefixLengthIPv4": 20, |
| 38 | + "NodePrefixLengthIPv4": 24, |
| 39 | + "PrefixIPv6": "fd00::172.16.0.0/112", |
| 40 | + "ConduitPrefixLengthIPv6": 116, |
| 41 | + "NodePrefixLengthIPv6": 120, |
| 42 | + "IPFamily": "dualstack", |
| 43 | + "LogLevel": "DEBUG" |
| 44 | + } |
| 45 | + } |
| 46 | +} |
| 47 | +``` |
| 48 | + |
| 49 | +Structured logs can be scanned with [jq](https://stedolan.github.io/jq/). |
| 50 | + |
| 51 | +``` |
| 52 | +kubectl logs -n red meridio-load-balancer-6dbbb9556f-f5cc4 -c load-balancer \ |
| 53 | + | grep '^{' | jq 'select(.extra_data.class == "SimpleNetworkService")' |
| 54 | +kubectl logs -n red meridio-load-balancer-6dbbb9556f-f5cc4 -c load-balancer \ |
| 55 | + | grep '^{' | jq 'select(.extra_data.class == "SimpleNetworkService")|select(.message == "updateVips")' |
| 56 | +
|
| 57 | +``` |
| 58 | + |
| 59 | +## Logger from context |
| 60 | + |
| 61 | +A logger should be created in `main()` and be used for logging |
| 62 | +everywhere. The logger is not passed in every call but a |
| 63 | +[go context](https://pkg.go.dev/context) should. Functions should |
| 64 | +use the logger from the context; |
| 65 | + |
| 66 | +```go |
| 67 | +// In main(); |
| 68 | +ctx = logr.NewContext(ctx, logger) |
| 69 | +// In a function; |
| 70 | +logger = log.FromContextOrGlobal(ctx) |
| 71 | +``` |
| 72 | + |
| 73 | +Functions really should always have a context as first parameter but |
| 74 | +they might not. A global logger is provided; |
| 75 | + |
| 76 | +``` |
| 77 | +log.Logger.Info("Configuration read", "config", config) |
| 78 | +``` |
| 79 | + |
| 80 | +The global logger is set by the *first* call to `log.New`. A global logger |
| 81 | +named "Meridio" on INFO level is pre-installed before `log.New` is called. |
| 82 | + |
| 83 | + |
| 84 | + |
| 85 | +## Log levels |
| 86 | + |
| 87 | +Severity `debug`, `info`, `error` and `critical` are used (not |
| 88 | +`warning`). The `Info()` call can have different "verbosity", set with the |
| 89 | +`V(n)` method; |
| 90 | + |
| 91 | +```go |
| 92 | +logger.Info("This is a normal info message") |
| 93 | +logger.V(1).Info("This is a debug message") |
| 94 | +logger.V(2).Info("This is a trace message") |
| 95 | +``` |
| 96 | + |
| 97 | +There is no defined "trace" level in output so both trace and debug |
| 98 | +messages will have severity "debug". The level filtering is still valid |
| 99 | +though, trace messages are suppressed unless TRACE level is set. |
| 100 | + |
| 101 | +The `Fatal()` function logs on `critical` level. |
| 102 | + |
| 103 | +### Costly parameter computations |
| 104 | + |
| 105 | +**This is important!** |
| 106 | + |
| 107 | +Consider; |
| 108 | + |
| 109 | +```go |
| 110 | +logger.V(2).Info("Gathered data", "collected", verySlowFunction()) |
| 111 | +``` |
| 112 | + |
| 113 | +The `verySlowFunction()` will *always* be executed, even if not on |
| 114 | +`trace` level. A few of these may have a severe impact on |
| 115 | +performance but you may *really* want them for trace. Luckily there is |
| 116 | +a [trick](https://github.com/go-logr/logr/issues/149); |
| 117 | + |
| 118 | +``` |
| 119 | + if loggerV := logger.V(2); loggerV.Enabled() { |
| 120 | + loggerV.Info("Gathered data", "collected", verySlowFunction()) |
| 121 | + } |
| 122 | +``` |
| 123 | + |
| 124 | +Now the `verySlowFunction()` is *only* executed when trace level is set. |
| 125 | + |
| 126 | + |
| 127 | +## Fatal |
| 128 | + |
| 129 | +```go |
| 130 | +import "github.com/nordix/meridio/pkg/log" |
| 131 | + logger := log.New("Meridio-ipam", config.LogLevel) |
| 132 | + log.Fatal(logger, "Can't read crucial data", "error", err) |
| 133 | +``` |
| 134 | + |
| 135 | +The logger is a pure `logr.Logger` logger so there is no `Fatal()` |
| 136 | +method. However we want to print a termination message using the same |
| 137 | +formatting as other log items so the `logger` is passed as a parameter. |
| 138 | + |
| 139 | +Example output; |
| 140 | +```json |
| 141 | +{ |
| 142 | + "severity": "critical", |
| 143 | + "timestamp": "2022-08-31T13:42:29.345+02:00", |
| 144 | + "service_id": "Meridio-test", |
| 145 | + "message": "Can't read crucial data", |
| 146 | + "version": "1.1.0", |
| 147 | + "extra_data": { |
| 148 | + "error": "Not found" |
| 149 | + } |
| 150 | +} |
| 151 | +``` |
| 152 | + |
| 153 | + |
| 154 | +## Design patterns |
| 155 | + |
| 156 | +Patterns must evolve slowly to get really good so these are mere |
| 157 | +ideas. It is very easy to get carried away and impose some |
| 158 | +over-structured logging that floods the logs with useless data. |
| 159 | + |
| 160 | + |
| 161 | +### Class logger |
| 162 | + |
| 163 | +A logger used in a type (Class) can be decorated with `class` and |
| 164 | +`instance` records; |
| 165 | + |
| 166 | +```go |
| 167 | +type someHandler struct { |
| 168 | + ctx context.Context |
| 169 | + logger logr.Logger |
| 170 | + Adr *net.TCPAddr // (optional; capitalized to make it visible) |
| 171 | +} |
| 172 | + |
| 173 | +func newHandler(ctx context.Context, addr string) *someHandler { |
| 174 | + logger := log.FromContextOrGlobal(ctx).WithValues("class", "someHandler") |
| 175 | + adr, err := net.ResolveTCPAddr("tcp", addr) |
| 176 | + if err != nil { |
| 177 | + log.Fatal(logger, "ResolveTCPAddr", "error", err) |
| 178 | + } |
| 179 | + h := &someHandler{ |
| 180 | + ctx: ctx, |
| 181 | + logger: logger.WithValues("instance", adr), |
| 182 | + Adr: adr, |
| 183 | + } |
| 184 | + h.logger.Info("Created", "object", h) |
| 185 | + return h |
| 186 | +} |
| 187 | + |
| 188 | +func (h *someHandler) connect() error { |
| 189 | + logger := h.logger.WithValues("func", "connect") |
| 190 | + logger.Info("Called") |
| 191 | + return nil |
| 192 | +} |
| 193 | +``` |
| 194 | + |
| 195 | +The `class` is the name of the type and `instance` can be anything |
| 196 | +that identifies an instance. The instance field must be |
| 197 | +capitalized if you want it visible. |
| 198 | + |
| 199 | +The example shows a `func` entry to identify a function. This should |
| 200 | +*not* be used as a common pattern but may be handy in some cases. |
| 201 | + |
0 commit comments