Make logging traceable #1685

sawadashota · 2020-01-09T05:50:58Z

Related issue

Proposed changes

Add Tracing logging option.

log:
  tracing:
    public: false
    admin: true

Then, hydra logs like this.

$ curl -k https://localhost:4445/health/alive -H 'Traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01'

{"level":"info","method":"GET","msg":"started handling request","remote":"[::1]:56308","request":"/health/alive","time":"2020-01-11T11:09:46+09:00","trace_id":"00f067aa0ba902b7"}
{"level":"info","measure#hydra/admin: https://localhost:4444/.latency":218780,"method":"GET","msg":"completed handling request","remote":"[::1]:56308","request":"/health/alive","status":200,"text_status":"OK","time":"2020-01-11T11:09:46+09:00","took":218780,"trace_id":"00f067aa0ba902b7"}

If request doesn't have Traceparent header, log doesn't appear trace_id and span_id.

$ curl -k https://localhost:4445/health/alive

{"level":"info","method":"GET","msg":"started handling request","remote":"[::1]:56396","request":"/health/alive","time":"2020-01-11T11:27:45+09:00"}
{"level":"info","measure#hydra/admin: https://localhost:4444/.latency":99643,"method":"GET","msg":"completed handling request","remote":"[::1]:56396","request":"/health/alive","status":200,"text_status":"OK","time":"2020-01-11T11:27:45+09:00","took":9964

Checklist

I have read the contributing guidelines
I have read the security policy
I confirm that this pull request does not address a security vulnerability. If this pull request addresses a security
vulnerability, I confirm that I got green light (please contact security@ory.sh) from the maintainers to push the changes.
I have added tests that prove my fix is effective or that my feature works
I have added necessary documentation within the code base (if appropriate)
I have documented my changes in the developer guide (if appropriate)

aeneasr · 2020-01-09T10:07:33Z

cmd/server/handler.go

+	logger.Before = func(entry *logrus.Entry, r *http.Request, _ string) *logrus.Entry {
+		fields := make(map[string]interface{})
+		for key, headerKey := range headers {
+			fields[key] = r.Header.Get(headerKey)


This does not seem to be compliant with the open tracing specification: https://github.com/opentracing/specification/blob/584c52365fe0700ba25effa79dce5effb845ced8/rfc/trace_identifiers.md

I would expect that this parses the HTTP Header traceparent. I'm pretty sure that opentracing has a library to do that, so maybe we can just use that here?

You're right. And I found library to extract tracing information from header!
https://github.com/open-telemetry/opentelemetry-go

Signed-off-by: Shota Sawada <xiootas@gmail.com>

aeneasr · 2020-01-10T14:45:53Z

cmd/server/handler.go

@@ -154,6 +155,21 @@ func RunServeAll(version, build, date string) func(cmd *cobra.Command, args []st
 	}
 }

+func setTracingLogger(d driver.Driver, logger *negronilogrus.Middleware) {
+	logger.Before = func(entry *logrus.Entry, r *http.Request, remoteAddr string) *logrus.Entry {


This overwrites the existing logger.Before, right? I think we have a custom Before somewhere - Maybe you could check if logger.Before is set and if it is, execute it and then execute this logic here, but only adding the trace_id and span_id?

I see, it appears that we're not actually using that here. Here's the actual function I was referring to: https://github.com/ory/x/blob/master/reqlog/middleware.go

I think it would make sense to use that function and add the trace_id in that middleware. We should also add it to both before, and after!

Here's an example: https://github.com/ory/oathkeeper/blob/master/cmd/server/server.go#L44

I fixed it!
It seemed logger.Before was set default(request, method and remote). I realized it's not safety to consider whether logger.Before or not, I fixed to add field.

We should also add it to both before, and after!

It's seems it's enough to add only before. Actually logs appear span_id and trace_id at both stating and completed handling request.

{"level":"info","method":"GET","msg":"started handling request","remote":"[::1]:56308","request":"/health/alive","time":"2020-01-11T11:09:46+09:00","trace_id":"00f067aa0ba902b7"} {"level":"info","measure#hydra/admin: https://localhost:4444/.latency":218780,"method":"GET","msg":"completed handling request","remote":"[::1]:56308","request":"/health/alive","status":200,"text_status":"OK","time":"2020-01-11T11:09:46+09:00","took":218780,"trace_id":"00f067aa0ba902b7"}

aeneasr · 2020-01-10T14:48:58Z

driver/configuration/provider_viper.go

@@ -413,3 +415,11 @@ func (v *ViperProvider) ShareOAuth2Debug() bool {
 func (v *ViperProvider) PKCEEnforced() bool {
 	return viperx.GetBool(v.l, ViperKeyPKCEEnforced, false, "OAUTH2_PKCE_ENFORCED")
 }
+
+func (v *ViperProvider) LogTracingPublic() bool {


I would be fine with actually having this enabled always no config required

I fixed it!

Signed-off-by: sawadashota <xiootas@gmail.com>

aeneasr · 2020-01-11T12:32:39Z

Thank you! :)

Signed-off-by: Shota Sawada <xiootas@gmail.com>

aeneasr mentioned this pull request Jan 9, 2020

Use consistent field types for logging #1683

Closed

aeneasr reviewed Jan 9, 2020

View reviewed changes

config: Make logging traceable

813d638

Signed-off-by: Shota Sawada <xiootas@gmail.com>

sawadashota force-pushed the feat-1680 branch from f9fefbd to 328ee69 Compare January 10, 2020 12:39

cmd: Get trace parent via opentelemetry lib

6d6a2b7

Signed-off-by: Shota Sawada <xiootas@gmail.com>

sawadashota force-pushed the feat-1680 branch from 328ee69 to 6d6a2b7 Compare January 10, 2020 12:54

aeneasr reviewed Jan 10, 2020

View reviewed changes

sawadashota added 3 commits January 11, 2020 10:40

config: Always enable tracing logging

2a6caa4

Signed-off-by: sawadashota <xiootas@gmail.com>

cmd: Introduce reqllog middleware as logger

4e72b2a

Signed-off-by: sawadashota <xiootas@gmail.com>

cmd: Always don't override before logging function

9e037c4

Signed-off-by: sawadashota <xiootas@gmail.com>

sawadashota changed the title ~~config: Make logging traceable~~ Make logging traceable Jan 11, 2020

aeneasr merged commit 3cee9b1 into ory:master Jan 11, 2020

sawadashota deleted the feat-1680 branch January 11, 2020 15:11

sawadashota mentioned this pull request Jan 16, 2020

cmd: Fix logging Span ID #1695

Merged

6 tasks

aeneasr mentioned this pull request Feb 17, 2020

Log specified http request headers ory/oathkeeper#361

Open

eli-zh pushed a commit to eli-zh/hydra that referenced this pull request Mar 22, 2020

server: Make logging traceable (ory#1685)

c772327

Signed-off-by: Shota Sawada <xiootas@gmail.com>

claudio-benfatto mentioned this pull request May 22, 2020

feat: Decorate request logs with trace_id and span_id fields ory/oathkeeper#445

Closed

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make logging traceable #1685

Make logging traceable #1685

sawadashota commented Jan 9, 2020 •

edited

aeneasr Jan 9, 2020 •

edited

sawadashota Jan 10, 2020

aeneasr Jan 10, 2020

aeneasr Jan 10, 2020

aeneasr Jan 10, 2020

sawadashota Jan 11, 2020

aeneasr Jan 10, 2020

sawadashota Jan 11, 2020

aeneasr commented Jan 11, 2020

Make logging traceable #1685

Make logging traceable #1685

Conversation

sawadashota commented Jan 9, 2020 • edited

Related issue

Proposed changes

Checklist

aeneasr Jan 9, 2020 • edited

Choose a reason for hiding this comment

sawadashota Jan 10, 2020

Choose a reason for hiding this comment

aeneasr Jan 10, 2020

Choose a reason for hiding this comment

aeneasr Jan 10, 2020

Choose a reason for hiding this comment

aeneasr Jan 10, 2020

Choose a reason for hiding this comment

sawadashota Jan 11, 2020

Choose a reason for hiding this comment

aeneasr Jan 10, 2020

Choose a reason for hiding this comment

sawadashota Jan 11, 2020

Choose a reason for hiding this comment

aeneasr commented Jan 11, 2020

sawadashota commented Jan 9, 2020 •

edited

aeneasr Jan 9, 2020 •

edited