log levels and structured logging

[iwpnd]

TLDR:
Let's organize logging in Tegola, revisit log levels and classification and push for json structured logs.

Hi there 👋,

As discussed on Slack I'd love to discuss the issue of logging in Tegola right now. I want to be transparent here and say that I'm pushing for a discussion, because it's a feature that will benefit the company I'm working for. However, I'm trying to make a case why this benefits the Tegola user in general.

I want to briefly cover three issues I see with logging in Tegola right now.

1. chatty logs
2. inability for the user to set log levels
3. text logs vs json logs

In the following I will try to form problem statements for each of the topics and propose action points that I want to put up for discussion.

1. Chatty logs

Problem statement:
Under some circumstances tegola can be very very chatty. While not ideal, I don't think this is too much of an issue for smaller applications. Bigger applications with a lot of users however, in my experience, push logs to providers like datadog/cloudwatch etc to aggregate and analyze them. Noisy applications tend to become a cost factor all of a sudden.

One example is this log line:

2022-02-17 09:30:09 [INFO] handle_map_layer_zxy.go:100: map (mapname) has no layers, at zoom 6

That occurs when the user configures max and min zoom for a layer.
Is this an information you'd expect to be logged on INFO level?

Action points:

1. agree on a categorization for logs

Log Level	Importance
FATAL	One or more key business functionalities are not working and the whole system doesn’t fulfill the business functionalities.
ERROR	One or more functionalities are not working, preventing some functionalities from working correctly.
WARN	Unexpected behavior happened inside the application, but it is continuing its work and the key business features are operating as expected.
INFO	An event happened, the event is purely informative and can be ignored during normal operations.
DEBUG	A log level used for events considered to be useful during software debugging when more granular information is needed.
TRACE	A log level describing events showing step by step execution of your code that can be ignored during the standard operation, but may be useful during extended debugging sessions.

(source)

2. use said categorization to revise log statements across tegola, eg. make example above DEBUG level

2. inability for the user to set log levels

Problem statement:
Allowing the user to set the desired log level allows to address different user groups and usage scenarios. While development DEBUG level is the preferred choice, INFO or WARN is what makes it to production to reduce information noise and/or alert fatige.

@gdey created a central log package with everything that is needed to to set loglevels for the application. The current init sets defaults it to INFO with no way for the user to change it on start-up or in the config.

Action points:
quick win let's expose log.go:SetLogLevel in the CLI as --log-level very-verbose|verbose|quiet|silent and make this part of v0.15.0.

very-verbose = TRACE
verbose = DEBUG
default = INFO
quiet = WARN
silent = ERROR

3. structured json logs

Problem statement:
Text logs have a small footprint and are faster than json logs. The biggest benefit of loggin in JSON however is, that its structured data that can be analyzed and filtered better than text logs. Plus, it's standardized and almost every language or os can parse/work with it.

I suggest we do not build that from scratch but tap into the rich eco-system of packages that already provide us with the basic functionalities. I also suggest that a json logger hooks into @gdey s existing log package, so log levels can be re-used. Defaulting to the current standard logger gives backwards compatibility.

Proposed package: uber/zap

Zap is very mature, well maintained and highly performant while at the same time highly customizable.
Zap comes with sane development and production default settings, but allows to pass your own configuration.
By default timestamps are logged unix timestamps ts

{
  "level": info
  "msg": "hi"
  "ts": 1645099269.395294
}

Passing a config like this:

{
    "level":"debug",
    "encoding":"json",
    "outputPaths":[
        "stdout"
    ],
    "errorOutputPaths":[
        "stderr"
    ],
    "encoderConfig":{
        "messageKey":"message",
        "levelKey":"level",
        "levelEncoder":"lowercase",
        "timeKey":"timestamp",
        "timeEncoder":"ISO8601"
    }
    "initialFields": {
        "meta": {
          "team":"geo"
          "swarm":"whatever"
          }
      }
}

results in:

{
  "level": "info",
  "message": "hi",
  "timestamp": "2022-02-17T12:13:37+00:00",
  "meta": {
    "team": "geo",
    "swarm": "whatever",
  }
}

That gives alot of power to the user, while also providing basic logs for the user that doesn't really care.

Possible action points:

• add cli option to chose between --logs json|text with text as default
• if json, build a zap logger with default config, and hide it behind a feature toggle eg isJSON

func Infof(format string, args ...interface{}) {
	if !IsInfo {
		return
	}

	msg := fmt.Sprintf(format, args...)
        if isJSON {
            jlogger.Info(msg)
            return
        }

	logger.Info(msg)
}

• add a logger section in the config.toml that allows to pass a zap config to the json logger, if config is present assume json logs

WDYT? :)

[gdey]

I think your suggestion of adding the flag to the cli is a great first step!

[ARolek]

@iwpnd thanks for this write-up! I think logging in tegola has been severely lacking and this is something I strongly support improving. I don't really have any issues with your suggestions. I think it's a strong plan, I support the approach and the introduction of the zap logging library as a dependency.

Regarding implementation, I think we should take this package by package. Maybe we start with the core logging package upgrade followed by implementing this in the server package. That will give us an opportunity to assess the trajectory.

[iwpnd]

I think #865 concludes this feature request. Thank you for your reviews and comments @gdey and @ARolek 🙏