Normal logs should not go to stderr

[chanzxxx]

Summary

Normal logs should not go to stderr.

Motivation

Some people including me detect critical issues on k8s by watching pods' stderr logs. But argocd applications are printing their all logs to stderr, and I think this is confused.

Proposal

Basically we should respect the purpose of each stream. Errors go stderr, and normal activity logs go stdout.

[alexmt]

This is not intended behavior. If some CLI commands are using stderr it is a bug.

[chanzxxx]

@alexmt
I think this is related to logrus package. Its default output stream is stderr.

[l15k4]

Some of argo-events components also logs to stderr. This should be revisited across the whole argoproj. argoproj/argo-events#884

[mrfelton]

Would love to see this resolved. My stackdriver logs are cluttered with inordinate amounts of error messages coming from argocd, which aren't actually errors - just that info level messages are being output to stderr. And since the messages themselves don't include the severity in a format that stackdriver recognises they default to being logged as errors since they went to stderr. If they go to stdout as they should they would have been logged as info rather than error.

[iam-veeramalla]

@jannfis , I am happy to contribute to this. Can you assign this to me ?

[jannfis]

Thanks @iam-veeramalla, much appreciated! I have assigned issue to you :)

[iam-veeramalla]

If I am understanding this issue correctly, It can be fairly easy fix by changing the default log from stderr to stdout. The default logging standard of logrus is stderr and can be modified to stdout by setting log.SetOutput(os.Stdout)

The real difficulty may be in testing this. Identify the different places where it outputs to stderr and change it to stdout.

[edgarkz]

same issue here with argocd: v2.0.0+f5119c0
BuildDate: 2021-04-07T06:00:33Z

Running with the following params "app patch-resource --kind Deployment --patch" logs to sdterr instead of stdout

[phelinor]

Same issue

[olvesh]

Also just ran into this, been open a while... Any known simple workarounds?

[iam-veeramalla]

Also just ran into this, been open a while... Any known simple workarounds?

@olvesh not yet, we are exploring options for a different logging package as the current project logrus is no longer active. It would continue as a maintenance project.

[olvesh]

Ok. I will try to upgrade to 2.1 tomorrow. As I understand I can set the log-format to json in that version. Perhaps that will remedy some of the logging issues in GKE (the other ones being that GKE fluentbit does not ingest the key=values as separate fields)🤞

On the other hand - why not then log structured logging to stdout and unstructured errors unhandled exeptions to stderr?
Surely that can be done even if not continuing to use logrus, as most apps I have come across logs all structured logging to stdout? And I know that logrus can be configured to use either stdout or stderr. (log.SetOutput(os.Stdout))

Guess that this surely has been discussed somewhere, I just havent stumbled over it yet. 😄

[chanzxxx]

I'm willing to contribute to addressing this issue.
Replacing logrus to another looks like best solution. What alternative packages do we have?

[iam-veeramalla]

Hi @edoger, Please find the response from the community meeting.

Whether the new application logging subpackage is approved.

Yes. Do we also want to support Sugar logging with Zap ? Do you see any advantages ?

Use the new Logger interface to decouple the log driver library and the application.

Yes. There is already a log package, if possible we can leverage that.

Wraps zap into existing logging styles to reduce refactoring costs.

Yes

Whether to provide configuration items to split log output to standard error and standard output.

Yes

Whether the log format and log level need to be modified while the application is running.

No opinion, You can take this decision.

[edoger]

@iam-veeramalla thank you very much!
I have seen the feedback and understand it. I'll make all the changes this weekend and can do a code review next Monday.
If you have any other questions or comments, feel free to email me at any time.

[edoger]

@iam-veeramalla
There are some frustrating issues in this project.

The internal grpc interceptor seems to have to rely on the logrus implementation. Many functions utilize logrus' global logger for log output capture (which is almost impossible to dynamically modify the output of the global logger in zap). Some test cases rely on logrus' log detection and test modules.

I can't quite understand why some source code needs to be designed this way.
These modules may need to be rewritten and replaced by dependent third-party library implementations.

argo-cd/util/grpc/logging.go

Lines 73 to 93 in 309654c

	func PayloadStreamServerInterceptor(entry *logrus.Entry, logClaims bool, decider grpc_logging.ServerPayloadLoggingDecider) grpc.StreamServerInterceptor {
	return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
	if !decider(stream.Context(), info.FullMethod, srv) {
	return handler(srv, stream)
	}
	logEntry := entry.WithFields(ctx_logrus.Extract(stream.Context()).Data)
	newStream := &loggingServerStream{ServerStream: stream, entry: logEntry, logClaims: logClaims, info: fmt.Sprintf("received streaming call %s", info.FullMethod)}
	return handler(srv, newStream)
	}
	}
	func PayloadUnaryServerInterceptor(entry *logrus.Entry, logClaims bool, decider grpc_logging.ServerPayloadLoggingDecider) grpc.UnaryServerInterceptor {
	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
	if !decider(ctx, info.FullMethod, info.Server) {
	return handler(ctx, req)
	}
	logEntry := entry.WithFields(ctx_logrus.Extract(ctx).Data)
	logRequest(logEntry, fmt.Sprintf("received unary call %s", info.FullMethod), req, ctx, logClaims)
	resp, err := handler(ctx, req)
	return resp, err
	}

[leoluz]

The internal grpc interceptor seems to have to rely on the logrus implementation. Many functions utilize logrus' global logger for log output capture (which is almost impossible to dynamically modify the output of the global logger in zap). Some test cases rely on logrus' log detection and test modules.

@edoger We are aware and discussed this in the contributors when @iam-veeramalla presented this issue. This will require a huge refactor in Argo CD. We will need help coordinating all this work. I believe that it is better to map every package that needs to be migrated and provide smaller PRs. This way we will be able to gradually migrate to the new log approach and refactor everything.

@iam-veeramalla would you be willing to take this governance task to map and track all work that needs to be done in order to get this 100% implemented?

[iam-veeramalla]

The internal grpc interceptor seems to have to rely on the logrus implementation. Many functions utilize logrus' global logger for log output capture (which is almost impossible to dynamically modify the output of the global logger in zap). Some test cases rely on logrus' log detection and test modules.

@edoger We are aware and discussed this in the contributors when @iam-veeramalla presented this issue. This will require a huge refactor in Argo CD. We will need help coordinating all this work. I believe that it is better to map every package that needs to be migrated and provide smaller PRs. This way we will be able to gradually migrate to the new log approach and refactor everything.

@iam-veeramalla would you be willing to take this governance task to map and track all work that needs to be done in order to get this 100% implemented?

I can do that but I will need to get on a call to understand the actual efforts and how we can get it done together 🙂.

[Kerwood]

How did it go with this issue ? Did you get started on it?
I currently get 450k log lines an hour on stderr which is a bit problematic.

[nicl-dev]

Any update on this? We are looking at hundreds of thousands of log entries per hour in GCP. This costs us and our customers more and more resources and money.

[vermin1]

Any update on this,please. We are in the same boat.

[griseau]

Did anybody found a workaround ?
We can exclude them from cloud logging, but this is quite annoying

[crenshaw-dev]

Quick note that the proposed go-native structured, leveled logging library is available as an experimental package: https://pkg.go.dev/golang.org/x/exp/slog

[edoger]

The change of complete refactoring is very huge, (╯﹏╰)b, I suggest forking logrus and adding LevelOutput function (I once submitted a function patch, but the author seems not very interested in new functions), and then in go mod replace the package.

[Kerwood]

The change of complete refactoring is very huge, (╯﹏╰)b, I suggest forking logrus and adding LevelOutput function (I once submitted a function patch, but the author seems not very interested in new functions), and then in go mod replace the package.

Apparently not...

[markcheret]

Is there any chance this logging issue could be resolved?

[crenshaw-dev]

@edoger I'm not completely opposed to the idea of a fork. Fully replacing the logger is a huge undertaking, and I don't think anyone is currently doing it. If logrus isn't accepting new features, then maintaining a fork should be relatively low-effort.

Unless someone wants to take on the full-replacement task. :-)

[jannfis]

Just wanted to point out that in Argo CD Image Updater, we use vanilla logrus with being able to log anything with a level less severe than error to stdout, and error and fatal severities to stderr: https://github.com/argoproj-labs/argocd-image-updater/blob/master/pkg/log/log.go

So, it's possible, even if there is some slight overhead through a wrapper.

[crenshaw-dev]

Seems like a reasonable opt-in approach, for folks who aren't worried about a little CPU overhead. Maybe even fine as a default, idk how expensive the wrapper is.

[jannfis]

I haven't done any performance tests, but the major part of the overhead would be calling two functions instead of one. There's not much compute involved in that, I guess.

[jannfis]

If it would be acceptable to just log everything (including levels error and fatal) to stdout, it's just a matter of calling logrus' SetOutput() function before starting to log.

[alvarogonzalez-packlink]

If it would be acceptable to just log everything (including levels error and fatal) to stdout, it's just a matter of calling logrus' SetOutput() function before starting to log.

I think this is OK for JSON logging. Theoretically , if you're doing structured logging, you can just filter by the value of the level key.

[crenshaw-dev]

Should definitely be fine as an opt-in.

[jannfis]

We still have some external dependencies doing their own logging, such as argoproj/pkg and potentially others.

[smaftoul]

The go standard library package log/slog has been released as part of go 1.21. Is this the way to go to fix this issue ?

[griseau]

If anyone is interested in a workaround in the meantime (thanks to @smaftoul 🎉 ), we configured argocd to log as json with the following config :

  - applicationsetcontroller.log.format=json
  - controller.log.format=json
  - notificationscontroller.log.format=json
  - reposerver.log.format=json
  - server.log.format=json

That way logs are correctly parsed by GCP even if going to stderr.

[leoluz]

Getting back here to point out that logs should indeed keep going to stderr. There are many log libraries that do that by default (zap, logrus, etc) for a reason. The reason is because stdout must only contain the output from the executed command. For example, if we run a command like argocd app list we should only get the list of applications and not getting it mixed with logs. Doing so, would break scripts that depend on Argo CD CLI with no easy path to fix.

Even if it is a bit counter intuitive, diagnostics output like logs do belong to stderr.
See: https://www.gnu.org/software/libc/manual/html_node/Standard-Streams.html