Improve logging and forward correlation ID (!516) · Merge requests · GitLab.org / gitlab-pages

Jaime Martinez requested to merge use-labkit-log into master Jul 07, 2021
What does this MR do?

Ensures correlation_id is present in more log lines as well as forwarding it to outbound requests.
Sample log with "correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2"
{"host":"gdk.test:3000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":5171,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":true,"time":"2021-07-07T17:06:34+10:00","was_idle":true}
{"client_name":"gitlab_internal_api","correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","host":"gdk.test:3000","level":"trace","msg":"response from client","path":"/api/v4/internal/pages","req_url":"http://gdk.test:3000/api/v4/internal/pages?host=root.pages.test","res_headers":{"Cache-Control":["max-age=0, private, must-revalidate"],"Content-Type":["application/json"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["W/\"57c8c3ae5432451956286ae2d3691947\""],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["SAMEORIGIN"],"X-Request-Id":["01F9ZWMBDM83QZGZY8VE8Z4CEJ"],"X-Runtime":["0.308789"]},"res_status_code":200,"time":"2021-07-07T17:06:34+10:00"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","level":"debug","lookup_error":null,"lookup_name":"root.pages.test","lookup_paths":{"lookup_paths":[{"project_id":31,"prefix":"/root.pages.test/","source":{"type":"zip","path":"http://127.0.0.1:9000/pages/eb/1e/eb1e33e8a81b697b75855af6bfcdbcbf7cbbde9f94962ceaec1ed8af21f5a50f/pages_deployments/19/artifacts.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=88523eec8ba153c4b13d74d0806c3cdc2020e0a2bced37a777ab263b6b9e9dae"}},{"project_id":21,"prefix":"/redirects-public/","source":{"type":"zip","path":"http://127.0.0.1:9000/pages/6f/4b/6f4b6612125fb3a0daecd2799dfd6c9c299424fd920f9b308110a2c1fbd8f443/pages_deployments/18/artifacts.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0d0a3ff8ea3686771fd79c6d7957a77713415feccbbfb97f528dce121992fddb"}},{"project_id":22,"access_control":true,"prefix":"/redirects-private/","source":{"type":"zip","path":"http://127.0.0.1:9000/pages/78/5f/785f3ec7eb32f30b90cd0fcf3657d388b5ff4297f2f9716ff66e9b69c05ddd09/pages_deployments/13/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=991c6165b9ead7e1ee1db187f0b1cbc1cbd6002105bb79bd68eb065670cf52b3"}},{"project_id":20,"prefix":"/public-blog/","source":{"type":"zip","path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d"}},{"project_id":19,"access_control":true,"prefix":"/private-blog/","source":{"type":"zip","path":"http://127.0.0.1:9000/pages/94/00/9400f1b21cb527d7fa3d3eabba93557a18ebe7a2ca4e471cfe5e4c5b4ca7f767/pages_deployments/11/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=b1022fb2d0c71a06005bf24d5437bc264a3c29dd64cd6b7bd63337d322b27bae"}},{"project_id":27,"prefix":"/local-file/","source":{"type":"zip","path":"file:///Users/jaime/dev/gitlab/ee/gitlab/shared/pages/@hashed/67/06/670671cd97404156226e507973f2ab8330d3022ca96e0c93bdbdb320c41adcaf/pages_deployments/14/artifacts.zip"}}]},"msg":"retrieval response sent","requested_domain":"root.pages.test","time":"2021-07-07T17:06:34+10:00"}
{"host":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"address":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.ConnectStart","network":"tcp","time":"2021-07-07T17:06:34+10:00"}
{"address":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.ConnectDone","network":"tcp","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":0,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":false,"time":"2021-07-07T17:06:34+10:00","was_idle":false}
{"client_name":"zip_vfs","correlation_id":"","host":"127.0.0.1:9000","level":"trace","msg":"response from client","path":"/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip","req_url":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","res_headers":{"Accept-Ranges":["bytes"],"Content-Length":["1"],"Content-Range":["bytes 0-0/372"],"Content-Security-Policy":["block-all-mixed-content"],"Content-Type":["application/zip"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["\"427721243201da6c69777a2e24b905d2\""],"Last-Modified":["Tue, 05 Jan 2021 06:18:17 GMT"],"Server":["MinIO"],"Vary":["Origin"],"X-Amz-Bucket-Region":["gdk"],"X-Amz-Request-Id":["168F706AD5E373C0"],"X-Xss-Protection":["1; mode=block"]},"res_status_code":206,"time":"2021-07-07T17:06:34+10:00"}
{"host":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":0,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":true,"time":"2021-07-07T17:06:34+10:00","was_idle":true}
{"client_name":"zip_vfs","correlation_id":"","host":"127.0.0.1:9000","level":"trace","msg":"response from client","path":"/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip","req_url":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","res_headers":{"Accept-Ranges":["bytes"],"Content-Length":["372"],"Content-Range":["bytes 0-371/372"],"Content-Security-Policy":["block-all-mixed-content"],"Content-Type":["application/zip"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["\"427721243201da6c69777a2e24b905d2\""],"Last-Modified":["Tue, 05 Jan 2021 06:18:17 GMT"],"Server":["MinIO"],"Vary":["Origin"],"X-Amz-Bucket-Region":["gdk"],"X-Amz-Request-Id":["168F706AD60F8500"],"X-Xss-Protection":["1; mode=block"]},"res_status_code":206,"time":"2021-07-07T17:06:34+10:00"}
{"host":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":0,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":true,"time":"2021-07-07T17:06:34+10:00","was_idle":true}
{"client_name":"zip_vfs","correlation_id":"","host":"127.0.0.1:9000","level":"trace","msg":"response from client","path":"/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip","req_url":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","res_headers":{"Accept-Ranges":["bytes"],"Content-Length":["199"],"Content-Range":["bytes 173-371/372"],"Content-Security-Policy":["block-all-mixed-content"],"Content-Type":["application/zip"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["\"427721243201da6c69777a2e24b905d2\""],"Last-Modified":["Tue, 05 Jan 2021 06:18:17 GMT"],"Server":["MinIO"],"Vary":["Origin"],"X-Amz-Bucket-Region":["gdk"],"X-Amz-Request-Id":["168F706AD6291BC8"],"X-Xss-Protection":["1; mode=block"]},"res_status_code":206,"time":"2021-07-07T17:06:34+10:00"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Root call","path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Lstat call","name":".","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Lstat call","name":"/index.html","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Lstat call","name":"/index.html","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":"file does not exist","level":"trace","msg":"Lstat call","name":"/index.html.br","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":"file does not exist","level":"trace","msg":"Lstat call","name":"/index.html.gz","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"host":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":0,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":true,"time":"2021-07-07T17:06:34+10:00","was_idle":true}
{"client_name":"zip_vfs","correlation_id":"","host":"127.0.0.1:9000","level":"trace","msg":"response from client","path":"/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip","req_url":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","res_headers":{"Accept-Ranges":["bytes"],"Content-Length":["30"],"Content-Range":["bytes 37-66/372"],"Content-Security-Policy":["block-all-mixed-content"],"Content-Type":["application/zip"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["\"427721243201da6c69777a2e24b905d2\""],"Last-Modified":["Tue, 05 Jan 2021 06:18:17 GMT"],"Server":["MinIO"],"Vary":["Origin"],"X-Amz-Bucket-Region":["gdk"],"X-Amz-Request-Id":["168F706AD6449308"],"X-Xss-Protection":["1; mode=block"]},"res_status_code":206,"time":"2021-07-07T17:06:34+10:00"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Open call","name":"/index.html","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","error":null,"level":"trace","msg":"Lstat call","name":"/index.html","root-path":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","time":"2021-07-07T17:06:34+10:00","vfs":"zip"}
{"host":"127.0.0.1:9000","level":"trace","msg":"httptrace.ClientTrace.GetConn","time":"2021-07-07T17:06:34+10:00"}
{"idle_time_ms":0,"level":"trace","msg":"httptrace.ClientTrace.GotConn","reused":true,"time":"2021-07-07T17:06:34+10:00","was_idle":true}
{"client_name":"zip_vfs","correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","host":"127.0.0.1:9000","level":"trace","msg":"response from client","path":"/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip","req_url":"http://127.0.0.1:9000/pages/f5/ca/f5ca38f748a1d6eaf726b8a42fb575c3c71f1864a8143301782de13da2d9202b/pages_deployments/12/_migrated.zip?X-Amz-Expires=86400\u0026X-Amz-Date=20210707T070634Z\u0026X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=minio%2F20210707%2Fgdk%2Fs3%2Faws4_request\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=0701430722ad19e70f38d2f66aad5c659189801a85c43bfbeaf14ae990b4d52d","res_headers":{"Accept-Ranges":["bytes"],"Content-Length":["20"],"Content-Range":["bytes 84-103/372"],"Content-Security-Policy":["block-all-mixed-content"],"Content-Type":["application/zip"],"Date":["Wed, 07 Jul 2021 07:06:34 GMT"],"Etag":["\"427721243201da6c69777a2e24b905d2\""],"Last-Modified":["Tue, 05 Jan 2021 06:18:17 GMT"],"Server":["MinIO"],"Vary":["Origin"],"X-Amz-Bucket-Region":["gdk"],"X-Amz-Request-Id":["168F706AD65C3DA0"],"X-Xss-Protection":["1; mode=block"]},"res_status_code":206,"time":"2021-07-07T17:06:34+10:00"}
{"content_type":"text/html; charset=utf-8","correlation_id":"01F9ZWMBDMQS9PPBH9F0FSDHY2","duration_ms":10,"host":"root.pages.test:3010","level":"info","method":"GET","msg":"access","pages_host":"root.pages.test","pages_https":false,"pages_project_id":20,"pages_project_prefix":"/public-blog/","pages_project_serving_type":"zip","proto":"HTTP/1.1","referrer":"","remote_addr":"172.16.123.1:56558","remote_ip":"172.16.123.1","status":200,"system":"http","time":"2021-07-07T17:06:34+10:00","ttfb_ms":10,"uri":"/public-blog/","user_agent":"curl/7.64.1","written_bytes":18}
Seems like the correlation ID is not used in /internal API endpoints yet gitlab#324836 (closed)
Related to #590 (closed)
Edited Jul 08, 2021 by Jaime Martinez
Improve logging and forward correlation ID

What does this MR do?

Merge request reports
