feat: replace logrus with zap

[GeorgeMac]

Closes: #964
Supports: #992 (with a little work to add supporting config)

This swaps out logrus for zap. I thought I could whip this up quickly for a comparison to aid the discussion.

Zap supports a lot of different configuration.
In fact, the config itself is JSON serializable and could be added to Flipt's own config.

https://pkg.go.dev/go.uber.org/zap#Config

However, for now, I decided to copy and adjust the default “development” config to best match Flips current flag configuration.

I went through a number of call-sites and adjusted the logging to match zap conventions.
I have favoured using zap fields and non-sugared logger.
Which, will make the output more favourable to structured encoding (like JSON).
Furthermore, it should reduce the logging overhead as it removes a bunch of string interpolation.

Before:

 _____ _ _       _
|  ___| (_)_ __ | |_
| |_  | | | '_ \| __|
|  _| | | | |_) | |_
|_|   |_|_| .__/ \__|
          |_|

Version: dev
Commit:
Build Date:
Go Version: go1.19

DEBU[0000] migrations up to date
DEBU[0000] store: "sqlite" enabled                       server=grpc
DEBU[0000] starting grpc server                          server=grpc
DEBU[0001] starting http server                          server=http

API: http://0.0.0.0:8080/api/v1
UI: http://0.0.0.0:8080

DEBU[0014] list flags                                    request= server=grpc
DEBU[0014] list flags                                    response= server=grpc
INFO[0014] finished unary call with code OK              grpc.code=OK grpc.method=ListFlags grpc.service=flipt.Flipt grpc.start_time="2022-09-09T11:27:15+01:00" grpc.time_ms=0.459 peer.address="127.0.0.1:54494" server=grpc span.kind=server system=grpc
DEBU[0022] create flag                                   request="key:\"foo\"  name:\"foo\"  description:\"The foo flag\"" server=grpc
DEBU[0022] create flag                                   response="key:\"foo\"  name:\"foo\"  description:\"The foo flag\"  created_at:{seconds:1662719243  nanos:535598000}  updated_at:{seconds:1662719243  nanos:535598000}" server=grpc
INFO[0022] finished unary call with code OK              grpc.code=OK grpc.method=CreateFlag grpc.service=flipt.Flipt grpc.start_time="2022-09-09T11:27:23+01:00" grpc.time_ms=3.778 peer.address="127.0.0.1:54494" server=grpc span.kind=server system=grpc
DEBU[0022] get flag                                      request="key:\"foo\"" server=grpc
DEBU[0022] get flag                                      response="key:\"foo\"  name:\"foo\"  description:\"The foo flag\"  created_at:{seconds:1662719243  nanos:535598000}  updated_at:{seconds:1662719243  nanos:535598000}" server=grpc
INFO[0022] finished unary call with code OK              grpc.code=OK grpc.method=GetFlag grpc.service=flipt.Flipt grpc.start_time="2022-09-09T11:27:23+01:00" grpc.time_ms=0.719 peer.address="127.0.0.1:54494" server=grpc span.kind=server system=grpc

After:

 _____ _ _       _
|  ___| (_)_ __ | |_
| |_  | | | '_ \| __|
|  _| | | | |_) | |_
|_|   |_|_| .__/ \__|
          |_|

Version: dev
Commit:
Build Date:
Go Version: go1.19

2022-09-09T11:23:04.720+0100	DEBUG	sql/migrator.go:83	first run, running migrations...	{"server": "grpc"}
2022-09-09T11:23:04.725+0100	DEBUG	sql/migrator.go:90	migrations complete	{"server": "grpc"}
2022-09-09T11:23:04.726+0100	DEBUG	flipt/main.go:410	store enabled	{"server": "grpc", "driver": "sqlite"}
2022-09-09T11:23:04.727+0100	DEBUG	flipt/main.go:506	starting grpc server	{"server": "grpc"}
2022-09-09T11:23:05.717+0100	DEBUG	flipt/main.go:625	starting http server	{"server": "http"}

API: http://0.0.0.0:8080/api/v1
UI: http://0.0.0.0:8080

2022-09-09T11:23:07.065+0100	DEBUG	server/flag.go:22	list flags	{"server": "grpc", "request": ""}
2022-09-09T11:23:07.066+0100	DEBUG	server/flag.go:35	list flags	{"server": "grpc", "response": ""}
2022-09-09T11:23:07.066+0100	INFO	zap/options.go:212	finished unary call with code OK	{"server": "grpc", "grpc.start_time": "2022-09-09T11:23:07+01:00", "system": "grpc", "span.kind": "server", "grpc.service": "flipt.Flipt", "grpc.method": "ListFlags", "peer.address": "127.0.0.1:54039", "grpc.code": "OK", "grpc.time_ms": 0.464}
2022-09-09T11:23:44.116+0100	DEBUG	server/flag.go:41	create flag	{"server": "grpc", "request": "key:\"foo\" name:\"Foo\" description:\"The foo flag\""}
2022-09-09T11:23:44.124+0100	DEBUG	server/flag.go:43	create flag	{"server": "grpc", "response": "key:\"foo\" name:\"Foo\" description:\"The foo flag\" created_at:{seconds:1662719024 nanos:116544000} updated_at:{seconds:1662719024 nanos:116544000}"}
2022-09-09T11:23:44.124+0100	INFO	zap/options.go:212	finished unary call with code OK	{"server": "grpc", "grpc.start_time": "2022-09-09T11:23:44+01:00", "system": "grpc", "span.kind": "server", "grpc.service": "flipt.Flipt", "grpc.method": "CreateFlag", "peer.address": "127.0.0.1:54039", "grpc.code": "OK", "grpc.time_ms": 8.483}
2022-09-09T11:23:44.226+0100	DEBUG	server/flag.go:14	get flag	{"server": "grpc", "request": "key:\"foo\""}
2022-09-09T11:23:44.227+0100	DEBUG	server/flag.go:16	get flag	{"server": "grpc", "response": "key:\"foo\" name:\"Foo\" description:\"The foo flag\" created_at:{seconds:1662719024 nanos:116544000} updated_at:{seconds:1662719024 nanos:116544000}"}
2022-09-09T11:23:44.227+0100	INFO	zap/options.go:212	finished unary call with code OK	{"server": "grpc", "grpc.start_time": "2022-09-09T11:23:44+01:00", "system": "grpc", "span.kind": "server", "grpc.service": "flipt.Flipt", "grpc.method": "GetFlag", "peer.address": "127.0.0.1:54039", "grpc.code": "OK", "grpc.time_ms": 0.814}

[codecov-commenter]

Codecov Report

Merging #1020 (266b727) into main (ce4354a) will decrease coverage by 0.04%.
The diff coverage is 75.00%.

@@            Coverage Diff             @@
##             main    #1020      +/-   ##
==========================================
- Coverage   81.31%   81.26%   -0.05%     
==========================================
  Files          17       17              
  Lines        1798     1799       +1     
==========================================
  Hits         1462     1462              
- Misses        262      263       +1     
  Partials       74       74              

Impacted Files	Coverage Δ
server/server.go	0.00% <0.00%> (ø)
storage/sql/migrator.go	28.78% <0.00%> (-0.45%)	⬇️
server/middleware.go	61.21% <14.28%> (ø)
server/evaluator.go	91.69% <87.50%> (ø)
internal/telemetry/telemetry.go	68.23% <100.00%> (ø)
server/flag.go	82.35% <100.00%> (ø)
server/rule.go	78.57% <100.00%> (ø)
server/segment.go	82.00% <100.00%> (ø)

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[GeorgeMac]

Cheers @markphelps, I adjusted those log lines and introduced a zapcore.Config which captures your suggestions.

• Dropped the caller
• Formatted time as RFC3339
• Added a little colour (with a u) to the log level.

Technically, if byte for byte encoding match with logrus was required, a zapcore.Encoder could be implemented.
However, I sense from reading the current console implementation; doing it right is possible, but might not be worth the investment.

[GeorgeMac]

Also, just for context, I also tried out installing zap as the internal gRPC logger implementation.

It works: grpc_zap.ReplaceGrpcLoggerV2WithVerbosity(logger, 0) This is all that is needed.

However, it does bring a lot more chatter into the logs.

2022-09-11T08:46:25+01:00	INFO	[core][Channel #1] Channel Connectivity change to IDLE	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core][Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core]pickfirstBalancer: UpdateSubConnState: 0x140003cc150, {CONNECTING <nil>}	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core][Channel #1] Channel Connectivity change to CONNECTING	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core][Channel #1 SubChannel #2] Subchannel picks a new address "0.0.0.0:9000" to connect	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core]CPU time info is unavailable on non-linux environments.	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core][Channel #1 SubChannel #2] Subchannel Connectivity change to READY	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core]pickfirstBalancer: UpdateSubConnState: 0x140003cc150, {READY <nil>}	{"server": "grpc", "system": "grpc", "grpc_log": true}
2022-09-11T08:46:25+01:00	INFO	[core][Channel #1] Channel Connectivity change to READY	{"server": "grpc", "system": "grpc", "grpc_log": true}

We could make setting this configurable. I remember that there was a common gRPC environment variable for enabling logs. We could piggyback on that.
Or, we could have it so that you can adjust the severity of gRPC independent of Flipts log-level (I suspect).
Food for thought.

I also tried out passing the option to adjust log-level based on gRPC response codes.
The default implementation treats OK as DEBUG. Which, I can see the case for.
To avoid cluttering your logs with just business as usual, successful responses:

grpc_zap.UnaryServerInterceptor(logger, grpc_zap.WithLevels(grpc_zap.DefaultClientCodeToLevel)),

// ...

2022-09-11T08:49:28+01:00	DEBUG	finished unary call with code OK	{"server": "grpc", "grpc.start_time": "2022-09-11T08:49:28+01:00", "system": "grpc", "span.kind": "server", "grpc.service": "flipt.Flipt", "grpc.method": "ListFlags", "peer.address": "127.0.0.1:49820", "grpc.code": "OK", "grpc.time_ms": 1.806}

However, it appears that today Flipt treats gRPC responses as INFO and I didn't want to change that for now.

[markphelps]

Yeah I agree that we should change:

grpc_zap.UnaryServerInterceptor(logger, grpc_zap.WithLevels(grpc_zap.DefaultClientCodeToLevel)),

But perhaps in the next release, potentially when we also add the JSON log output option? It makes sense to me that OK responses would be logged as DEBUG instead of INFO (as they are today).

I also agree that the change:

grpc_zap.ReplaceGrpcLoggerV2WithVerbosity(logger, 0) This is all that is needed.

Should perhaps piggyback off the env var used by gRPC, (I remember it having a weird name?). Idk how much extra value it would be to add another config for Flipt to control this value, it seems to me that using the decided upon env var by the gRPC community would be good enough?

[markphelps]

Amazing! Thank you @GeorgeMac for doing this, it was much needed IMO

[GeorgeMac]

🎉 Awesome. Cheers @markphelps

We can do it all again in the next 6 months when the dust settles here golang/go#54763 😂