Send logrus messages back to caller when building #3215

rhatdan · 2021-05-07T17:40:33Z

We want Info, Warning and Debug logrus messages to be writen to the
buildah stderr. this way when podman-remote is using build, it will
get the messages back on the client side.

[NO TESTS NEEDED] Since this will be tested in Podman.

Fixes: #3214

Signed-off-by: Daniel J Walsh dwalsh@redhat.com

openshift-ci-robot · 2021-05-07T17:40:48Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: rhatdan

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [rhatdan]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

jwhonce

fmt.Fprintf(Err, "Warning: missing %q build argument. Try adding %q to the command line\n", argName, fmt.Sprintf("--build-arg %s=<VALUE>", argName))

Please add newline at end of message

jwhonce · 2021-05-07T17:45:27Z

/cc @edsantiago

nalind · 2021-05-07T17:47:48Z

This doesn't cover all of the places in the main buildah package, and the other packages in this repository that it uses, where we can also call logrus during imagebuildah.BuildDockerfiles(), and it doesn't cover any of the libraries that we depend on. I think we need to document that our caller needs to call logrus.SetOutput() and leave it at that.

rhatdan · 2021-05-07T17:49:54Z

So fix this in Podman.

jwhonce · 2021-05-07T17:51:08Z

@nalind The problem with logrus.SetOutput() is we don't want all the debugging information forwarded to the client. We only want expected error messages.

jwhonce · 2021-05-07T17:52:45Z

LGTM

rhatdan · 2021-05-07T18:01:28Z

Is there a way in logrus, to be selective about messages, IE Error and Warn go to buildOpts.Err

nalind · 2021-05-07T18:06:06Z

They all go to the same location (logrus.SetOutput() doesn't take a logging level argument). The only discriminator appears to be the logging level.

@nalind The problem with logrus.SetOutput() is we don't want all the debugging information forwarded to the client. We only want expected error messages.

Why doesn't the client want to know about other warnings and errors?

rhatdan · 2021-05-07T18:09:39Z

sirupsen/logrus#403
Has been talking about this for years. @jwhonce Is worried about Debug, Trace and Info.

jwhonce · 2021-05-07T20:59:51Z

@nalind, Client/Server reporting is a matrix. Buildah is a little different because of the Stdout/StdErr/Auxout/Reporting BuildOptions. Then we have messages the developers have asked for that were rendered via logrus. Logrus output has been captured by the service and kept on the server. The handlers are responsible for relaying information to the client loosely following the table below.

Logging levels:

Errors: Always Client and Server
Warnings: Usually Client and Always Server
Info: Maybe Client and Usually not Server
Debug: Never Client and Usually not Server
Trace: Never Client and Usually not Server

nalind · 2021-05-10T14:20:31Z

The standard logger in the logrus package is a globally-shared object, and it is used not only by buildah, but by other dependencies that both buildah and libpod use, and by libpod itself. That is not something your application wants one library in your dependency stack messing with without your full control and knowledge. podman is going to have to manipulate the global standard logger that the logrus library exports to get the results that you're looking for.

jwhonce · 2021-05-10T15:57:45Z

@nalind The global nature of the logger is the issue. If two remote clients are running builds, it is impossible to route any logged message to the client which called imagebuildah.BuildDockerfiles(). Any logrus output has to stay on the server. imagebuildah.BuildDockerfiles() has four writers already associated with it, that is what we are leveraging here.

nalind · 2021-05-10T17:07:32Z

imagebuildah/build.go

@@ -181,7 +181,7 @@ func warnOnUnsetBuildArgs(node *parser.Node, args map[string]string) {
 				argHasValue = argFound[argName]
 			}
 			if _, ok := args[argName]; !argHasValue && !ok {
-				logrus.Warnf("missing %q build argument. Try adding %q to the command line", argName, fmt.Sprintf("--build-arg %s=<VALUE>", argName))
+				fmt.Fprintf(Err, "Warning: missing %q build argument. Try adding %q to the command line\n", argName, fmt.Sprintf("--build-arg %s=<VALUE>", argName))


Something like (untested)

log := logrus.New() log.SetOutput(Err) log.SetLevel(logrus.GetLevel()) log.Warnf(...)

would probably be less disruptive.

If we could do this one per connection, then this would solve our problem.

We can try to wire in a way to pass a logger to some of our functions, but I don't really think we're going to be able to add a "send logrus output here" parameter to every function that logs things in the packages and libraries that we call into, and that's what'd be necessary to be sure we were catching everything. Not that I know how our caller would filter and route things if all it could control was the output io.Writer.

I say we do our best. So that most of these messages get back to the caller.

nalind · 2021-05-10T17:08:40Z

Well, so long as we're all aware that this one change isn't going to fix the general case, I guess I've grumbled enough.

openshift-ci · 2021-05-14T17:25:04Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: rhatdan

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [rhatdan]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

rhatdan · 2021-05-14T17:28:13Z

@jwhonce @nalind I rewrote this to pass around the logger Object. so that podman-remote will get all Info, Warning and Errors out of server side back to client.

nalind · 2021-05-14T18:03:47Z

buildah.go

@@ -89,6 +89,9 @@ const (
 type Builder struct {
 	store storage.Store

+	// Logger is the logrus loger to write log messages with


Suggested change

// Logger is the logrus loger to write log messages with

// Logger is the logrus logger to write log messages with

nalind · 2021-05-14T18:03:55Z

config.go

+		b.Logger = logrus.New()
+		b.Logger.SetOutput(os.Stderr)
+		b.Logger.SetLevel(logrus.GetLevel())
+	}


This snippet belongs somewhere other than in a method called fixupConfig(). It's also redundant for callers who get here from newBuilder().

Where would you want me to put it. fixupConfig is called by both newbuilder and openbuilder. I could make a new function? And call it from both?

OpenBuilder is called from buildah run ...

It's either going to be do-it-everywhere, or a helper function. Builder objects are also constructed by the variations of OpenBuilder, and by ImportBuilder/ImportBuilderFromImage. Basically, anywhere you see a new Builder object being created, we're going to need to set this field.

nalind · 2021-05-14T18:04:27Z

imagebuildah/executor.go

@@ -300,6 +302,7 @@ func (b *Executor) startStage(ctx context.Context, stage *imagebuilder.Stage, st
 		volumeCacheInfo: make(map[string]os.FileInfo),
 		output:          output,
 		stage:           stage,
+		logger:          b.logger,


This field isn't needed, since it's never different from the Executor's logger. Use the StageExecutor's executor.logger in those places instead, similar to how we handle several other fields that we refer to in the Executor.

nalind · 2021-05-14T18:04:42Z

run.go

@@ -70,6 +71,8 @@ const (

 // RunOptions can be used to alter how a command is run in the container.
 type RunOptions struct {
+	// Logger is the logrus loger to write log messages with


Suggested change

// Logger is the logrus loger to write log messages with

// Logger is the logrus logger to write log messages with

nalind · 2021-05-14T18:04:47Z

run_linux.go

@@ -76,7 +76,7 @@ func (b *Builder) Run(command []string, options RunOptions) error {
 	logrus.Debugf("using %q to hold bundle data", path)
 	defer func() {
 		if err2 := os.RemoveAll(path); err2 != nil {
-			logrus.Error(err2)
+			b.Logger.Error(err2)


Suggested change

b.Logger.Error(err2)

options.Logger.Error(err2)

Also needs to create a logger for options.Logger if it isn't set.

nalind · 2021-05-14T18:04:54Z

run_linux.go

@@ -120,7 +120,7 @@ func (b *Builder) Run(command []string, options RunOptions) error {
 	}
 	defer func() {
 		if err := b.Unmount(); err != nil {
-			logrus.Errorf("error unmounting container: %v", err)
+			b.Logger.Errorf("error unmounting container: %v", err)


Suggested change

b.Logger.Errorf("error unmounting container: %v", err)

options.Logger.Errorf("error unmounting container: %v", err)

nalind · 2021-05-14T18:05:00Z

run_linux.go

@@ -253,7 +253,7 @@ rootless=%d

 	defer func() {
 		if err := cleanupRunMounts(runMountTargets, mountPoint); err != nil {
-			logrus.Errorf("unabe to cleanup run mounts %v", err)
+			b.Logger.Errorf("unabe to cleanup run mounts %v", err)


Suggested change

b.Logger.Errorf("unabe to cleanup run mounts %v", err)

options.Logger.Errorf("unabe to cleanup run mounts %v", err)

nalind · 2021-05-14T18:05:05Z

run_linux.go

@@ -704,12 +704,14 @@ func runUsingRuntime(isolation define.Isolation, options RunOptions, configureNe
 	// Lock the caller to a single OS-level thread.
 	runtime.LockOSThread()

+	logger := options.Logger


This never needs to be different from options.Logger, so drop the variable and use the passed-in value.

nalind · 2021-05-14T18:05:20Z

run_linux.go

@@ -1069,6 +1071,7 @@ func setupRootlessNetwork(pid int) (teardown func(), err error) {

 func runConfigureNetwork(isolation define.Isolation, options RunOptions, configureNetworks []string, pid int, containerName string, command []string) (teardown func(), err error) {
 	var netconf, undo []*libcni.NetworkConfigList
+	logger := options.Logger


This doesn't need to ever be different from options.Logger, and it's used once. Remove the variable and reference options.Logger directly.

That is the way I originally had it, and I thought this was cleaner, but I will revert.

nalind · 2021-05-14T18:26:22Z

Embedding another package's API objects in our API means that any stability guarantees we make for our API are also dependent on the stability of their APIs, and this one ties us to a specific implementation rather than an interface. I understand the motivation for this patch, though, so I'm not rejecting it out of hand, but it remains a concern.

nalind · 2021-05-14T20:29:57Z

imagebuildah/build.go

@@ -190,7 +198,7 @@ func warnOnUnsetBuildArgs(node *parser.Node, args map[string]string) {
 				argHasValue = argFound[argName]
 			}
 			if _, ok := args[argName]; !argHasValue && !ok {
-				logrus.Warnf("missing %q build argument. Try adding %q to the command line", argName, fmt.Sprintf("--build-arg %s=<VALUE>", argName))
+				logger.Warnf("missing %q build argument. Try adding %q to the command line\n", argName, fmt.Sprintf("--build-arg %s=<VALUE>", argName))


The \n was for fmt.Fprintf(), which doesn't add one by default, but logrus's formatters always include it, so we don't need that.

We want Info, Warning and Debug logrus messages to be writen to the buildah stderr. this way when podman-remote is using build, it will get the messages back on the client side. [NO TESTS NEEDED] Since this will be tested in Podman. Fixes: containers#3214 Signed-off-by: Daniel J Walsh <dwalsh@redhat.com>

openshift-ci-robot added the approved label May 7, 2021

jwhonce requested changes May 7, 2021

View reviewed changes

openshift-ci-robot requested a review from edsantiago May 7, 2021 17:45

rhatdan force-pushed the bud branch from 18b772f to ada87ec Compare May 7, 2021 17:48

nalind reviewed May 10, 2021

View reviewed changes

rhatdan force-pushed the bud branch from ada87ec to 317b00f Compare May 14, 2021 17:24

rhatdan force-pushed the bud branch from 317b00f to d018143 Compare May 14, 2021 17:26

rhatdan changed the title ~~We should not send warning messages via logrus when building~~ Send logrus messages back to caller when building May 14, 2021

rhatdan force-pushed the bud branch from d018143 to 565bf29 Compare May 14, 2021 17:30

nalind reviewed May 14, 2021

View reviewed changes

rhatdan force-pushed the bud branch 2 times, most recently from d6cb833 to 51757c2 Compare May 14, 2021 19:56

nalind reviewed May 14, 2021

View reviewed changes

rhatdan force-pushed the bud branch from 51757c2 to d7d0785 Compare May 15, 2021 07:55

rhatdan added the lgtm label May 17, 2021

openshift-merge-robot merged commit 2ab877e into containers:master May 17, 2021

github-actions bot added the locked - please file new issue/PR label Sep 20, 2023

github-actions bot locked as resolved and limited conversation to collaborators Sep 20, 2023

	// Logger is the logrus loger to write log messages with
	// Logger is the logrus logger to write log messages with

	b.Logger.Errorf("error unmounting container: %v", err)
	options.Logger.Errorf("error unmounting container: %v", err)

	b.Logger.Errorf("unabe to cleanup run mounts %v", err)
	options.Logger.Errorf("unabe to cleanup run mounts %v", err)

Send logrus messages back to caller when building #3215

Send logrus messages back to caller when building #3215

Conversation

rhatdan commented May 7, 2021 • edited

openshift-ci-robot commented May 7, 2021

jwhonce left a comment • edited

Choose a reason for hiding this comment

jwhonce commented May 7, 2021

nalind commented May 7, 2021

rhatdan commented May 7, 2021

jwhonce commented May 7, 2021

jwhonce commented May 7, 2021

rhatdan commented May 7, 2021

nalind commented May 7, 2021

rhatdan commented May 7, 2021

jwhonce commented May 7, 2021

nalind commented May 10, 2021 • edited

jwhonce commented May 10, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nalind commented May 10, 2021

openshift-ci bot commented May 14, 2021

rhatdan commented May 14, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nalind commented May 14, 2021

Choose a reason for hiding this comment

rhatdan commented May 7, 2021 •

edited

jwhonce left a comment •

edited

nalind commented May 10, 2021 •

edited