Add structured logging

[jsoriano]

Add structured logging using JSON ECS format. This includes much more information in logs for http requests. As it uses JSON ECS, it doesn't need special parsing.

-log-level can be used to select log level.

Logger is a global singleton in the util package. Not ideal, but was not trivial to pass the logger to all the components. We can iterate on this though.

Why am I using zap for structured logging? It is one of the two Go loggers currently supported by Elastic for ECS logging. The other one is Logrus. I chose zap because it is supposed to be faster, but I don't have a strong opinion.

Example lines now:

{"log.level":"info","@timestamp":"2022-03-02T20:46:29.747+0100","log.logger":"http","message":"GET /search HTTP/1.1","source.address":"127.0.0.1","http.request.method":"GET","http.response.code":200,"http.response.body.bytes":7912,"source.ip":"127.0.0.1","user_agent.original":"curl/7.58.0","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-03-02T20:46:37.282+0100","log.logger":"http","message":"GET / HTTP/1.1","source.address":"127.0.0.1","http.request.method":"GET","http.response.code":200,"http.response.body.bytes":71,"source.ip":"127.0.0.1","user_agent.original":"curl/7.58.0","ecs.version":"1.6.0"}

With -log-type dev a "developer mode" can be enabled, that logs like this:

2022-03-02T20:30:19.402+0100	INFO	http	GET / HTTP/1.1	{"source.address": "127.0.0.1", "http.request.method": "GET", "http.response.code": 200, "http.response.body.bytes": 71, "source.ip": "127.0.0.1", "user_agent.original": "curl/7.58.0"}
2022-03-02T20:30:21.323+0100	INFO	http	GET /search HTTP/1.1	{"source.address": "127.0.0.1", "http.request.method": "GET", "http.response.code": 200, "http.response.body.bytes": 7912, "source.ip": "127.0.0.1", "user_agent.original": "curl/7.58.0"}

Follow up of #795.

[elasticmachine]

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Start Time: 2022-03-04T09:47:32.369+0000

• Duration: 4 min 8 sec

Test stats 🧪

Test	Results
Failed	0
Passed	148
Skipped	0
Total	148

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

• /test : Re-trigger the build.

[ruflin]

Changing the log structure shloud be considered a breaking change.

[ruflin]

In the context of changing the log format I've been thinking about how we could make it less breaking for users that collect the logs, especially if it is collected with elastic-agent. The package-registry is its own service which I think also deserves its own package. If we have a package, we could ensure that both log formats can be processed. Also it means we can make sure that we have dashboards versioned and link the apm visualizations.

[mtojek]

LGTM

Is there any other benefit coming from this PR apart from cleanup and a nice console logger for development purposes? I mean, do we log more data or include error context?

[jsoriano]

Is there any other benefit coming from this PR apart from cleanup and a nice console logger for development purposes? I mean, do we log more data or include error context?

For most of requests it is the same data, plus timestamps with timezone and caller file and line. This is one of the lines printed on startup when reading the packages:

{"log.level":"info","@timestamp":"2022-03-03T11:02:35.070+0100","log.origin":{"file.name":"packages/packages.go","file.line":208},"message":"found package","package.name":"foo","package.version":"1.0.0","package.path":"testdata/package/foo/1.0.0","ecs.version":"1.6.0"}

For requests we log more data:

Before:

2022/03/01 10:12:38 source.ip: 127.0.0.1:42342, url.original: /search

After:

{"log.level":"info","@timestamp":"2022-03-03T11:02:38.059+0100","log.logger":"http","message":"GET /search HTTP/1.1","source.address":"127.0.0.1","http.request.method":"GET","http.response.code":200,"http.response.body.bytes":7912,"source.ip":"127.0.0.1","user_agent.original":"curl/7.58.0","ecs.version":"1.6.0"}

We also have log levels now.

[jsoriano]

Btw, I wonder if we should log "access" and "error" logs to different streams, as is usual in web servers. We could log "access" logs to stdout, and everything else to stderr. @mtojek wdyt?

[mtojek]

Btw, I wonder if we should log "access" and "error" logs to different streams, as is usual in web servers. We could log "access" logs to stdout, and everything else to stderr. @mtojek wdyt?

I'm fine with such a change if the docker logs command still works so that we will miss neither access nor error logs.

[jsoriano]

@mtojek I found that I was not capturing valuable fields from the url, as the path and the query. I have added this and a couple of fields more. And a test for the captured fields. Could you please take another look?

[jsoriano]

Btw, I wonder if we should log "access" and "error" logs to different streams, as is usual in web servers. We could log "access" logs to stdout, and everything else to stderr. @mtojek wdyt?

I'm fine with such a change if the docker logs command still works so that we will miss neither access nor error logs.

Umm, yes, let's leave this for a separate change, it can have unexpected implications.

[mtojek]

Hm, we don't expect any users here, right?

[jsoriano]

Correct, let's remove this.