echo_logrus: use std context for fields #1174

lzap · 2024-05-06T18:27:44Z

This is a followup of https://github.com/osbuild/image-builder/pull/1171/files

I have couple of concerns with the recent changes.

The new fields are only present when echo logger is used. There are many other logs created through logrus interface (e.g. all SQL queries done by the pgx driver) which will miss all those fields.
All path params are added and can possibly override existing fields e.g. msg or level. This could have unwanted effects, this new patch protects the most important fields. (I haven’t tested this chances are logrus would not allow overriding level or msg fields at all.)
There were concerns about memory consumption or performance - logrus.Fields is a map and context is a lightweight object by design. Paths typically contain one or two fields maximum, with path and method this is up to 4 map elements.
Context will carry a copy of information, that is a valid point (see the original PR discussion), but as described above this is very small amount of information.
I noticed context was not added in "Finished request" message, it is now added.

I have to add I do not believe it is a good thing to add path, method and all path params to every single log line, I think it would be better to only log this once at the beginning of the request and devs can use correlation ids to find the line from any logged line. This proposal adds those fields everywhere tho.

lzap · 2024-05-06T18:30:33Z

cmd/image-builder/logging.go

 		})

 		if !SkipPath(c.Path()) {
-			c.Logger().Debugf("Started request")
+			ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request")


This hunk is probably unnecessary, I was experimenting around to find the best solution. Can put it back, should work just fine. It really does not matter if you use echo interface or logrus interface, the result is the same. In fact, the counterpart for this line "Processed request ..." does use logrus interface, so why not to keep this change.

Suggested change

ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request")

ctxLogger.WithContext(ctx).Debugf("Started request")

my WithFields is also not needed here, right?

It is either this, or I can make use of the echo logger created above. Let me use the echo logger instead, looks better.

lzap · 2024-05-06T18:31:00Z

cmd/image-builder/main.go

@@ -154,7 +154,8 @@ func main() {
 			if values.Error != nil {
 				fields["error"] = values.Error
 			}
-			logrus.WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI)
+			logrus.WithContext(c.Request().Context()).
+				WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI)


Here WithContext was missing, somewhat unrelated to the change but I think it is worth fixing.

do you think also adding
"path": c.Path(),
to the fields here would be beneficial as this is better for log entry searches/grouping (in contrast to values.URI) I guess
but no stopper for this PR I guess
(hmm or is this added by the c.Request().Context() anyway? - I'll check)

lzap · 2024-05-06T18:32:05Z

internal/common/echo_logrus.go

 }

 func (l *EchoLogrusLogger) Panicj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Panicln(string(b))
+	l.Logger.WithContext(l.Ctx).Panicln(string(b))
 }


This file is a full revert. No other changes.

Awesome thanks, looks nicer and even covers more use cases!

schuellerf

Very nice, thanks

schuellerf · 2024-05-07T07:45:49Z

cmd/image-builder/logging.go

 		})

 		if !SkipPath(c.Path()) {
-			c.Logger().Debugf("Started request")
+			ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request")


Suggested change

ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request")

ctxLogger.WithContext(ctx).Debugf("Started request")

my WithFields is also not needed here, right?

schuellerf · 2024-05-07T07:48:06Z

internal/common/echo_logrus.go

 }

 func (l *EchoLogrusLogger) Panicj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Panicln(string(b))
+	l.Logger.WithContext(l.Ctx).Panicln(string(b))
 }


Awesome thanks, looks nicer and even covers more use cases!

lzap · 2024-05-10T07:05:00Z

Rebased.

schuellerf

LGTM

schuellerf · 2024-05-13T10:25:05Z

cmd/image-builder/main.go

@@ -154,7 +154,8 @@ func main() {
 			if values.Error != nil {
 				fields["error"] = values.Error
 			}
-			logrus.WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI)
+			logrus.WithContext(c.Request().Context()).
+				WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI)


do you think also adding
"path": c.Path(),
to the fields here would be beneficial as this is better for log entry searches/grouping (in contrast to values.URI) I guess
but no stopper for this PR I guess
(hmm or is this added by the c.Request().Context() anyway? - I'll check)

lzap · 2024-05-14T07:03:03Z

The way I search paths is simply doing normal search across all fields and once I get request-id I search for that to get the full history of a request. This will work because the path is logged at least once on every request. I can add this if you want.

github-actions · 2024-06-14T04:12:32Z

This PR is stale because it has been open 30 days with no activity. Remove "Stale" label or comment or this will be closed in 7 days.

Signed-off-by: Lukas Zapletal <lzap+git@redhat.com>

ezr-ondrej · 2024-06-18T19:53:59Z

/retest

lzap mentioned this pull request May 6, 2024

echo_logrus: implement adding fields #1171

Merged

lzap force-pushed the stdlog-fields branch from 6483f37 to a189401 Compare May 6, 2024 18:29

lzap commented May 6, 2024

View reviewed changes

lzap force-pushed the stdlog-fields branch from a189401 to 8e7e1ba Compare May 6, 2024 18:31

lzap commented May 6, 2024

View reviewed changes

schuellerf requested changes May 7, 2024

View reviewed changes

schuellerf mentioned this pull request May 7, 2024

Fix caller in logs #1176

Closed

lzap force-pushed the stdlog-fields branch from 8e7e1ba to 6aaf83d Compare May 10, 2024 07:04

schuellerf approved these changes May 13, 2024

View reviewed changes

lzap force-pushed the stdlog-fields branch from 6aaf83d to eeb3342 Compare May 14, 2024 07:08

github-actions bot added the Stale label Jun 14, 2024

echo_logrus: use std context for fields

37d7d03

Signed-off-by: Lukas Zapletal <lzap+git@redhat.com>

lzap force-pushed the stdlog-fields branch from eeb3342 to 37d7d03 Compare June 14, 2024 11:30

github-actions bot removed the Stale label Jun 15, 2024

schuellerf merged commit fb712d0 into osbuild:main Jun 19, 2024
12 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

echo_logrus: use std context for fields #1174

echo_logrus: use std context for fields #1174

lzap commented May 6, 2024

lzap May 6, 2024 •

edited

Loading

schuellerf May 7, 2024

lzap May 10, 2024

lzap May 6, 2024

schuellerf May 13, 2024 •

edited

Loading

lzap May 6, 2024

schuellerf May 7, 2024

schuellerf left a comment

schuellerf May 7, 2024

schuellerf May 7, 2024

lzap commented May 10, 2024

schuellerf left a comment

schuellerf May 13, 2024 •

edited

Loading

lzap commented May 14, 2024

github-actions bot commented Jun 14, 2024

ezr-ondrej commented Jun 18, 2024

	ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request")
	ctxLogger.WithContext(ctx).Debugf("Started request")

echo_logrus: use std context for fields #1174

echo_logrus: use std context for fields #1174

Conversation

lzap commented May 6, 2024

lzap May 6, 2024 • edited Loading

Choose a reason for hiding this comment

schuellerf May 7, 2024

Choose a reason for hiding this comment

lzap May 10, 2024

Choose a reason for hiding this comment

lzap May 6, 2024

Choose a reason for hiding this comment

schuellerf May 13, 2024 • edited Loading

Choose a reason for hiding this comment

lzap May 6, 2024

Choose a reason for hiding this comment

schuellerf May 7, 2024

Choose a reason for hiding this comment

schuellerf left a comment

Choose a reason for hiding this comment

schuellerf May 7, 2024

Choose a reason for hiding this comment

schuellerf May 7, 2024

Choose a reason for hiding this comment

lzap commented May 10, 2024

schuellerf left a comment

Choose a reason for hiding this comment

schuellerf May 13, 2024 • edited Loading

Choose a reason for hiding this comment

lzap commented May 14, 2024

github-actions bot commented Jun 14, 2024

ezr-ondrej commented Jun 18, 2024

lzap May 6, 2024 •

edited

Loading

schuellerf May 13, 2024 •

edited

Loading

schuellerf May 13, 2024 •

edited

Loading