Skip to content

Add LabKit correlation, access logger and global logger settings

João Pereira requested to merge add-correlation-id into add-labkit-logging

Related to #31 (closed).

This MR does the following changes:

  • Add a correlation_id to the context and the logger. This is provided by labkit/correlation and allows us to correlate not only individual log messages but also enables us to correlate requests across GitLab applications. We already have a request.id (UUID) in the logs that allow us to correlate log messages (and we can't get rid of it that easily because it's used in other parts of the applications, such as for the webhook notifications), but correlation_id is standard across GitLab applications, so we need to add it.

  • Stop logging a custom log message (response completed) after each request, unless access logging is disabled. The details provided by this log message are essentially what an access log message provides. Duplicated logs generate a lot of noise and require additional storage/bandwidth. Workhorse logs are a good example of this (sample), there's an access log and then the rest are application-related messages, correlated by correlation_id.

  • Switch over to LabKit for the access logger. We still support the default combined format (but now we do it through LabKit as well).

  • Initialize both access and app loggers through LabKit to make sure we have sane settings.

Before

INFO[0000] listening on [::]:5000                        environment=development go.version=go1.14.4 instance.id=6efdb918-7b5f-436e-9809-9552b50a702f service=registry version=v2.9.1-gitlab-269-gb391ba84
DEBU[0001] authorizing request                           go.version=go1.14.4 http.request.host="198.18.0.1:5000" http.request.id=9fcc5da4-1046-4a2f-a17c-a0c24a0c0b8a http.request.method=GET http.request.remoteaddr="198.18.0.1:60354" http.request.uri=/v2/busybox/tags/list http.request.useragent=HTTPie/2.2.0 vars.name=busybox
DEBU[0001] finding tags in database                      go.version=go1.14.4 http.request.host="198.18.0.1:5000" http.request.id=9fcc5da4-1046-4a2f-a17c-a0c24a0c0b8a http.request.method=GET http.request.remoteaddr="198.18.0.1:60354" http.request.uri=/v2/busybox/tags/list http.request.useragent=HTTPie/2.2.0 limit=100 marker= repository=busybox vars.name=busybox
INFO[0001] response completed                            go.version=go1.14.4 http.request.host="198.18.0.1:5000" http.request.id=9fcc5da4-1046-4a2f-a17c-a0c24a0c0b8a http.request.method=GET http.request.remoteaddr="198.18.0.1:60354" http.request.uri=/v2/busybox/tags/list http.request.useragent=HTTPie/2.2.0 http.response.contenttype="application/json; charset=utf-8" http.response.duration=4.10809ms http.response.status=200 http.response.written=37
198.18.0.1 - - [22/Jul/2020:17:04:35 +0100] "GET /v2/busybox/tags/list HTTP/1.1" 200 37 "" "HTTPie/2.2.0"

After

With combined access logs (default):

INFO[0000] listening on [::]:5000                        environment=development go.version=go1.14.4 instance.id=81cc748e-0caa-4889-8916-363b421df732 service=registry version=v2.9.1-gitlab-274-gc7bb016d
DEBU[0001] authorizing request                           correlation_id=4OfWr7E0ha9 go.version=go1.14.4 vars.name=busybox
DEBU[0001] finding tags in database                      correlation_id=4OfWr7E0ha9 go.version=go1.14.4 limit=100 marker= repository=busybox vars.name=busybox
198.18.0.1:5000 198.18.0.1 - - [2020/07/22:17:56:36 +0100] "GET /v2/busybox/tags/list HTTP/1.1" 200 37 "" "HTTPie/2.2.0" 5

With text access logs:

INFO[0000] listening on [::]:5000                        environment=development go.version=go1.14.4 instance.id=b8fd4a83-fab4-43c6-ac53-66e31414ba7b service=registry version=v2.9.1-gitlab-273-g68872928
DEBU[0001] authorizing request                           correlation_id=APt19aLt139 go.version=go1.14.4 vars.name=busybox
DEBU[0001] finding tags in database                      correlation_id=APt19aLt139 go.version=go1.14.4 limit=100 marker= repository=busybox vars.name=busybox
INFO[0001] access                                        content_type="application/json; charset=utf-8" correlation_id=APt19aLt139 duration_ms=5 host="198.18.0.1:5000" method=GET proto=HTTP/1.1 referrer= remote_addr="198.18.0.1:60320" remote_ip=198.18.0.1 status=200 system=http uri=/v2/busybox/tags/list user_agent=HTTPie/2.2.0 written_bytes=37

With json access logs:

INFO[0000] listening on [::]:5000                        environment=development go.version=go1.14.4 instance.id=4e2bc222-2c0a-4da9-8549-024153361b98 service=registry version=v2.9.1-gitlab-274-gc7bb016d
DEBU[0000] authorizing request                           correlation_id=8c8FCEEhRa9 go.version=go1.14.4 vars.name=busybox
DEBU[0000] finding tags in database                      correlation_id=8c8FCEEhRa9 go.version=go1.14.4 limit=100 marker= repository=busybox vars.name=busybox
{"content_type":"application/json; charset=utf-8","correlation_id":"8c8FCEEhRa9","duration_ms":4,"host":"198.18.0.1:5000","level":"info","method":"GET","msg":"access","proto":"HTTP/1.1","referrer":"","remote_addr":"198.18.0.1:49424","remote_ip":"198.18.0.1","status":200,"system":"http","time":"2020-07-22T17:58:42+01:00","uri":"/v2/busybox/tags/list","user_agent":"HTTPie/2.2.0","written_bytes":37}

With all logs as json:

{"environment":"development","go.version":"go1.14.4","instance.id":"7801d73f-5190-49a2-8616-92d7d2d04f22","level":"info","msg":"listening on [::]:5000","service":"registry","time":"2020-07-22T17:59:47+01:00","version":"v2.9.1-gitlab-274-gc7bb016d"}
{"correlation_id":"FdZpgYfVLp","go.version":"go1.14.4","level":"debug","msg":"authorizing request","time":"2020-07-22T17:59:48+01:00","vars.name":"busybox"}
{"correlation_id":"FdZpgYfVLp","go.version":"go1.14.4","level":"debug","limit":100,"marker":"","msg":"finding tags in database","repository":"busybox","time":"2020-07-22T17:59:48+01:00","vars.name":"busybox"}
{"content_type":"application/json; charset=utf-8","correlation_id":"FdZpgYfVLp","duration_ms":3,"host":"198.18.0.1:5000","level":"info","method":"GET","msg":"access","proto":"HTTP/1.1","referrer":"","remote_addr":"198.18.0.1:49438","remote_ip":"198.18.0.1","status":200,"system":"http","time":"2020-07-22T17:59:48+01:00","uri":"/v2/busybox/tags/list","user_agent":"HTTPie/2.2.0","written_bytes":37}

Next Steps

  • Make logging keys consistent. Most of our app log keys are separated with dots, e.g. "go.version", while LabKit (and at GitLab) always uses underscores as separators.

  • Make error logging values consistent. We have some error values (mostly the detail field) that sometimes are logged as string and others as an object. We must make it always a string as we can't index dynamically nested object values.

  • Some log context is not being propagated. For example, above we can see that instance.id only appears in the first few logs. This is not new, it was already happening and is not related with LabKit at all, so we'll tackle that separately.

Edited by João Pereira

Merge request reports