log should with traceID and spanID #2235

morlay · 2021-07-09T03:57:16Z

Set log.G with a GetLogger with Fields traceID and spanID when tracing exists.

example image docker.io/morlay/buildkit:log-with-tracing

logs in buidlkit will be

tonistiigi · 2021-07-09T04:25:28Z

But this will always logs the same ID that called GetLogger not the actual context of the call. If that is useful then better just print it once when the tracer is initialized.

edit: or am I wrong? Noticed this is actually containerd logs, not used by buildkit code itself

morlay · 2021-07-09T04:29:37Z

@tonistiigi

Different traceID for different job.

each log with traceID,
we could easy to group logs by the traceID for each jobs, when the buildkit as shared one for multi jobs.

Signed-off-by: Morlay <[email protected]>

morlay · 2021-07-09T05:15:39Z

Here a example
show using loki + tempo, we could link all job logs && tracing by a tracingID

morlay · 2021-07-09T05:25:13Z

@tonistiigi

I'm not know well about full process, from job start to ends,
could you help to replace all logrus. in job procesing by log.G(ctx) ?

I found some logs without traceID, but i think it should related to some job.

like:

ime="2021-07-09T05:13:41Z" level=debug msg="session started"
time="2021-07-09T05:13:41Z" level=debug msg="new ref for local: qgray83c8xqxgo96r87hnaeao"
time="2021-07-09T05:13:41Z" level=debug msg="diffcopy took: 8.060715ms"
time="2021-07-09T05:13:41Z" level=debug msg="saved qgray83c8xqxgo96r87hnaeao as local.sharedKey:dockerfile:dockerfile:"
time="2021-07-09T05:13:41Z" level=debug msg="new ref for local: 17jlrretgw0qvcvrhjs2h0wfb"
time="2021-07-09T05:13:41Z" level=debug msg="diffcopy took: 6.482385ms"
time="2021-07-09T05:13:41Z" level=debug msg="saved 17jlrretgw0qvcvrhjs2h0wfb as local.sharedKey:context:context-.dockerignore:"

time="2021-07-09T05:13:46Z" level=debug msg="new ref for local: ocqwjgbo909txpj7v571y9ggu"
time="2021-07-09T05:13:46Z" level=debug msg="diffcopy took: 22.892484ms"
time="2021-07-09T05:13:46Z" level=debug msg="saved ocqwjgbo909txpj7v571y9ggu as local.sharedKey:context:context:"

time="2021-07-09T05:14:52Z" level=debug msg="session finished: <nil>"

tonistiigi · 2021-07-09T05:33:00Z

Your screenshot looks cool but you are missing the traces from the client. Tracing should be cross-process.

could you help to replace all logrus. in job procesing by log.G(ctx) ?

Generally ok, but I don't want packages that currently depend only on logrus to depend on containerd/log. For library packages should avoid logrus as well and define something smaller & less opinionated that can be connected with logrus from the caller side, but that is out of scope for this.

Also, the trace starts from the client side that sends a parent span with the grpc requests. For logs in code that is outside gprc handlers there is no trace context in buildkitd.

morlay · 2021-07-09T05:48:37Z

Your screenshot looks cool but you are missing the traces from the client. Tracing should be cross-process.

Yes, buildx still use the old version. so haven't collect that part.
when buildx upgrade, the traceID should created from buildx, and multi buildkit node should got both.

Generally ok, but I don't want packages that currently depend only on logrus to depend on containerd/log. For library packages should avoid logrus as well and define something smaller & less opinionated that can be connected with logrus from the caller side, but that is out of scope for this.

We could do this in future.

maybe we could use some simplier interface instead of logrus, like https://github.com/go-logr/logr
so library could be more simpler, and the log always get from context.

Also, the trace starts from the client side that sends a parent span with the grpc requests. For logs in code that is outside gprc handlers there is no trace context in buildkitd.

It doesn't matter. When trace context not exists, we can ignore it.

tonistiigi · 2021-07-09T05:51:48Z

util/log/log.go

+)
+
+func init() {
+	log.G = GetLogger


for a simple change to support buildkit's logs move this line out of util to cmd/buildkitd and then you can replace the logrus calls with util/log.GetLogger() without containerd/log dependency.

Can do this in separate PR as well.

And when you do that, don't use log package name as it collides with stdlib in imports. bklogor logger.Get() or smth else that doesn't collide is better.

tonistiigi · 2021-09-02T19:00:16Z

@morlay It seems these show up even if no tracing is enabled. We should find a way to avoid that. PTAL

crazy-max · 2021-09-02T19:09:03Z

Yeah it also seems custom fields are removed. Here host is removed in v0.9.0.

v0.8.3

  time="2021-07-01T10:09:35Z" level=debug msg=resolving host=mirror.gcr.io
  time="2021-07-01T10:09:35Z" level=debug msg="do request" host=mirror.gcr.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent=containerd/1.4.0+unknown request.method=HEAD url="https://mirror.gcr.io/v2/library/alpine/manifests/latest?ns=docker.io"
  time="2021-07-01T10:09:35Z" level=debug msg="fetch response received" host=mirror.gcr.io response.header.alt-svc="h3=\":443\"; ma=2592000,h3-29=\":443\"; ma=2592000,h3-T051=\":443\"; ma=2592000,h3-Q050=\":443\"; ma=2592000,h3-Q046=\":443\"; ma=2592000,h3-Q043=\":443\"; ma=2592000,quic=\":443\"; ma=2592000; v=\"46,43\"" response.header.content-length=1638 response.header.content-type=application/vnd.docker.distribution.manifest.list.v2+json response.header.date="Thu, 01 Jul 2021 10:09:35 GMT" response.header.docker-content-digest="sha256:234cb88d3020898631af0ccbbcca9a66ae7306ecd30c9720690858c1b007d2a0" response.header.docker-distribution-api-version=registry/2.0 response.header.server="Docker Registry" response.header.x-frame-options=SAMEORIGIN response.header.x-xss-protection=0 response.status="200 OK" url="https://mirror.gcr.io/v2/library/alpine/manifests/latest?ns=docker.io"

v0.9.0

time="2021-09-02T10:09:29Z" level=debug msg=resolving spanID=31f00e00807cf7d5 traceID=b828c839daa8ea1bc2058af93478d03e
time="2021-09-02T10:09:29Z" level=debug msg="do request" request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent=containerd/1.5.3+unknown request.method=HEAD spanID=31f00e00807cf7d5 traceID=b828c839daa8ea1bc2058af93478d03e
time="2021-09-02T10:09:29Z" level=debug msg="fetch response received" response.header.alt-svc="h3=\":443\"; ma=2592000,h3-29=\":443\"; ma=2592000,h3-T051=\":443\"; ma=2592000,h3-Q050=\":443\"; ma=2592000,h3-Q046=\":443\"; ma=2592000,h3-Q043=\":443\"; ma=2592000,quic=\":443\"; ma=2592000; v=\"46,43\"" response.header.content-length=1638 response.header.content-type=application/vnd.docker.distribution.manifest.list.v2+json response.header.date="Thu, 02 Sep 2021 10:09:29 GMT" response.header.docker-content-digest="sha256:e1c082e3d3c45cccac829840a25941e679c25d438cc8412c2fa221cf1a824e6a" response.header.docker-distribution-api-version=registry/2.0 response.header.server="Docker Registry" response.header.x-frame-options=SAMEORIGIN response.header.x-xss-protection=0 response.status="200 OK" spanID=31f00e00807cf7d5 traceID=b828c839daa8ea1bc2058af93478d03e

morlay · 2021-09-07T15:05:38Z

sorry. i missed this msg.
i will check it tomorrow

morlay · 2021-09-08T02:33:39Z

@crazy-max could you location where to define custom fields?

i haven't find the configration fields

morlay force-pushed the log-with-tracing branch from 19777f2 to b20bbd6 Compare July 9, 2021 03:57

morlay mentioned this pull request Jul 9, 2021

OpenTelemetry support docker/buildx#635

Merged

tonistiigi approved these changes Jul 9, 2021

View reviewed changes

morlay force-pushed the log-with-tracing branch from b20bbd6 to df153dd Compare July 9, 2021 04:45

log with traceID and spanID

1ed2d45

Signed-off-by: Morlay <[email protected]>

morlay force-pushed the log-with-tracing branch from df153dd to 1ed2d45 Compare July 9, 2021 04:54

tonistiigi reviewed Jul 9, 2021

View reviewed changes

tonistiigi merged commit b93b5b6 into moby:master Jul 9, 2021

morlay mentioned this pull request Sep 8, 2021

bklog: only log tracing ids when span exporter not nil #2351

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log should with traceID and spanID #2235

log should with traceID and spanID #2235

morlay commented Jul 9, 2021 •

edited

Loading

tonistiigi commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

tonistiigi commented Jul 9, 2021

morlay commented Jul 9, 2021

tonistiigi Jul 9, 2021

tonistiigi Jul 9, 2021

tonistiigi commented Sep 2, 2021

crazy-max commented Sep 2, 2021

morlay commented Sep 7, 2021

morlay commented Sep 8, 2021 •

edited

Loading

log should with traceID and spanID #2235

log should with traceID and spanID #2235

Conversation

morlay commented Jul 9, 2021 • edited Loading

tonistiigi commented Jul 9, 2021 • edited Loading

morlay commented Jul 9, 2021 • edited Loading

morlay commented Jul 9, 2021 • edited Loading

morlay commented Jul 9, 2021 • edited Loading

tonistiigi commented Jul 9, 2021

morlay commented Jul 9, 2021

tonistiigi Jul 9, 2021

Choose a reason for hiding this comment

tonistiigi Jul 9, 2021

Choose a reason for hiding this comment

tonistiigi commented Sep 2, 2021

crazy-max commented Sep 2, 2021

v0.8.3

v0.9.0

morlay commented Sep 7, 2021

morlay commented Sep 8, 2021 • edited Loading

morlay commented Jul 9, 2021 •

edited

Loading

tonistiigi commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

morlay commented Jul 9, 2021 •

edited

Loading

morlay commented Sep 8, 2021 •

edited

Loading