Solve logging

[ejona86]

We used to have some INFO logs, but they were considered spam by some users (#1439), so they were reduced to FINE (#1449). In general, open source libraries don't log unless something is going wrong, and these log statements didn't imply something was wrong.

However, in #1538 INFO-level logs were added back (in a different place, but same effective event). These could be a lower level, but it seems difficult for users to enable a higher logging level.

We do know applications can do something like this to squelch what is logged:

// May need to save this reference
Logger log = Logger.getlogger("io.grpc");
log.setLevel(Level.WARNING);

More than one project has been annoyed with the logging-by-default, but the number of Java developers who can handle logging.properties seems limited.

On Android, things are even worse because most phones almost always return false from Log.isLoggable() for lower log levels. Developer phones (like debug builds of Android) will return true, but few develop on such phones. This means that even when you configure java.util.logging to log lower levels, they won't actually be logged. You can run a command like adb shell setprop log.tag.<MAGICTAG> VERBOSE for each class you want to log, where the MAGICTAG can be found from DalvikLogging.loggerNameToTag(), but this is so painful it isn't close to practical.

Note that most Android applications don't notice any problem with Log.isLoggable() because while it may return false, if you call the log anyway (say, via Log.v()) apparently it will be logged.

One developer suggested we use slf4j because it is "java best practices." I think in some part of the Java world it is, but it is unclear whether grpc exists in that part of the world. The number of developers that can configure java.util.logging, log4j, logback, or slf4j is certainly higher than just java.util.logging, but it will also become harder to direct users in how to enable logging when we need it for a report. It also has the deficiency that "If no binding is found on the class path, then SLF4J will default to a no-operation implementation" which is pretty bad for our WARNING statements.

[udoprog]

Hey, coming from spotify/heroic#56 here.

SLF4J has the promise to unify logging implementations under a relatively consistent and stable API. Unfortunately java.util.logging is the one implementation which is very hard to cooperate which. The approach SLF4J has with other frameworks is to provide an alternative compatible implementation of their API. but java.util.logging classes cannot be reliably provided by anyone outside of the JDK.

This leaves the end user with two choices. Either fully embrace java.util.logging, or introduce a SLF4J bridge similar to this at all their entry points:

SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();

As for the no-op. I'm not convinced logging to stderr by default is the best approach here. The messages themselves tend to end up in non-obvious places. SLF4J instead tells that they should configure a logging framework through stderr if none has been configured:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

I realize SLF4J is not the 'easiest' solution. But a decision of sticking with java.util.logging would make 'doing the right thing' quite hard.

Thanks

[carl-mastrangelo]

@udoprog We are currently working with our java core libraries team for a fast logging solution. I expect this bug to be resolved by late Q3.

[udoprog]

@carl-mastrangelo Hey, thanks for the heads up! I'm looking forward to it.

[ejona86]

It is possible for alternative implementations of Formatter and Handler, but I do agree configuring java.util.logging is a pain.

The real problem of SLF4J is requiring our users to configure the logger. That's silly. I don't understand why SLF4J chose that behavior, but in my mind it should silently use java.util.logging or stderr if nothing is configured. This is done sanely in java.util.logging, Log4j, and Commons Logging. So even though SLF4J is pretty popular, it seems toward the bottom of the list of options.

I don't think the new library we are using will be handling configuration, but I'm uncertain what it relies on.

[udoprog]

grpc-java is a library, it should not have a say in how logging is performed at runtime. Integration tests might want it to be completely disabled (slf4j-nop), cli tools probably want stderr-based logging (slf4j-simple), server applications want file-based logging (slf4j-over-log4j). SLF4J chose to print an error message if logging is not configured instead of silently making assumptions about the target environment. It's a rather powerful, and intentional approach that has served many OSS projects well for a long time.

You could in practice provide a default binding to slf4j-simple which would give you the same behavior as today. I'd argue you wouldn't be worse of than what we are today. At least I would have the option of excluding it when I depend on grpc-java. I'd rather just urge you to reconsider your stance on default logger bindings. I don't know how many times I've had to dig deep into third party libraries bindings to figure out how to get them into my log files. I've actually had servers fail because stderr gets logged to some location (e.g. /var/log/upstart/...) that doesn't have a lot of disk space.

[ccleve]

Grpc is very tightly bound to Netty, and that isn't going to change, so you might consider using the same approach as Netty.

https://github.com/netty/netty/tree/4.1/common/src/main/java/io/netty/util/internal/logging

https://github.com/netty/netty/blob/4.1/common/src/main/java/io/netty/util/internal/logging/InternalLoggerFactory.java

As it stands, you would have to configure Grpc logging and Netty logging separately, Would be nice to do it only once.

Note that the Netty classes are strictly internal and they don't want you to use them, but you could certainly do something similar and share the configuration.

Or have Netty use SLF4J and use that in Grpc directly. It's not a bad option.

[jonnyzzz]

What is the current status or understanding about changing the current JUL logger to something? Personally I like the idea of using SLF4J. I'm trying to figure out if it makes sense to provide a pull request for that.

[ejona86]

I don't think it would be useful to send out a pull request to convert to SLF4J. We aren't concerned with the migration cost, but the solution. We have an idea of at least a partial solution, but are blocked temporarily. Let's just be in a holding pattern for the moment.

[craigday]

SLF4J gets a BIG THUMBS DOWN! from me. GRPC is (wonderful) infrastructure code/functionality. It should stick with JUL. It's extremely annoying when library vendors choose a logging framework that you then have to cater for. I don't have to think about JUL. It's just there and it just works, and I can push it through any logging setup I choose!!

[dieselpoint]

SLF4J gets a BIG THUMBS DOWN!

I can't disagree more strongly. Slf4j isn't a logging framework, it's a facade. It's just a set of interfaces. The underlying implementation can be anything. JUL doesn't easily allow other implementations.

GRPC is a library that fits into other apps, and it really should use whatever logging implementation the underlying app uses. The means that GRPC must write to an interface. You can either roll your own interface, or use Slf4j. I think Slf4j is a better choice.

[jonnyzzz]

My main concern is the ability to isolate logging from other parts of JVM. In most cases one develops an application that is likely to coexist in some application server. In particular, a web application that is deployed to, say jetty or tomcat. There can be a number of applications running in such a server. And, it's vital to be able to configure logging in per-application basis.
Since JUL is implemented inside JVM core libraries, it's not possible to have it overridden (via classloaders) for each application. So all JUL logging is hard (at least efficiently) to split between applications. It can easily lead to logs that are erroneous or incorrect at all.

Any external (meaning non-embedded into JRE by default) logging library allows one to isolate logging and to let it be per-application processed. I like slf4j, but any home grown solution (hope not) or other library (e.g. commons logging, or something else) will work for that. I really expect a logging API will be used, not a particular implementation.

I cannot agree fully with a just works statement from craigday. This sounds weird to me. I can hardly assume any production ready application that have no logging setup. Yes, I understand it is, well, hard, messy, painful, but one should finally have properly configured logging for anything that is more-less stable.

Finally, in case slf4j is considered, there are a number of alternatives for end-users as documented here. Is short, log4j-simple can be used as default implementation that is comparable to JUL.

[askoog]

Any updates on this? I would really like to see a logging facade in grpc. SLF4J is not required, but it should be up to the end user to specify how logging should be done. As for now this is a big issue for us since we do not want to configure java util logging configuration for all our apps for this case alone.

Take a look at how hazelcast implements logging for example: https://github.com/hazelcast/hazelcast/blob/master/hazelcast/src/main/java/com/hazelcast/logging/Logger.java
I like this idea very much, make it possible for the end user to configure logging by providing extra libraries at runtime and setting a config property. It would be a fairly simple task to replace all references to JUL with a similar home-made logger facade that forwards to JUL by default.

[danielcompton]

This bit me recently when I was trying to set logging levels to hide log lines from grpc that weren't informative. I was very surprised to find that grpc-java depends on j.u.l. instead of logging to the slf4j facade.

I fully concede that for beginners, getting your head around logging on Java is a bit of a pain. This could be eased by providing instructions to beginners on how to add (say) log4j-simple, and provide a config file that they can start with.

I would argue that most of the server-side JVM audience for grpc-java are somewhat familiar with SLF4J logging and can configure this for themselves in whatever way makes sense for their production application. You can't get too far in the server world without coming across it. I'll confess I have no idea about the situation on the Android side of the fence, it sounds like it's a bit different there.

[ahjohannessen]

Same here, for example io.grpc.Context checks if FINE is enabled and outputs an error when it tries to do a Class.forName("io.grpc.override.ContextStorageOverride"). Our applications do not use JUL, but somehow the following passes through, default in JUL is INFO, when using okhttp client from a Play http application.

if (log.isLoggable(Level.FINE)) {
    // Avoid writing to logger because custom log handlers may try to use Context, which is
    // problemantic (e.g., NullPointerException) because the Context class has not done loading
    // at this point.  The caveat is that in environments stderr may be disabled, thus this
    // message would go nowhere.
    System.err.println("io.grpc.Context: Storage override doesn't exist. Using default.");
    e.printStackTrace();
}

That is not very desirable considering that is an opt-in thing. It should rather log with INFO when it manages to find a custom storage implementation.

[Groostav]

Bump,

I came to this issue because my logs weren't verbose enough. I'm looking for an elegant way to have protoc dump a nicely formatted message strings to standard-error before/while serializing it to the wire --like a poor mans fiddler or a nicely-formatted wireshark. Seems like I need to do a little digging.

one more thought: I'm wondering if JEP 264 (java-9) has impacts on your guys thoughts.

[carl-mastrangelo]

@Groostav That's an interesting JEP, thanks for calling it out. The Flogger API is one we plan on using eventually, (as it is extremely fast), but the implementation isn't open sourced yet.

For your specific question: protoc (the binary) is not involved after the compilation, so I think you are referring to the proto library. For me personally, I use Netty's frame logging since the other HTTP/2 frames are usually of interest too.

[ejona86]

Flogger is open source: https://github.com/google/flogger . But it hadn't been optimized for Android last we checked; it brought in too many methods.

JEP 264 is really interesting, but it isn't "real" until something like SLF4J implements it. There's a few things to double-check with it as well, like how it would behave in "interesting" class loader environments, like a servlet container.

[emaayan]

IMO the ability to integrate grpc's logging with the parent app is no less the mandatory if you features such as waitForReady and retries which just log any failures, and if the app doesn't JUL those logs will be lost, and troubleshooting is very hard.
you should at least allow extensible logging so users would be able to contibute log4j/slf4j extension and default to JUL if none exists.

[ejona86]

@emaayan, waitForReady and retry do not log failures. Also, Log4J/SLF4J has a JUL bridge/adapter which works okay.

Our current approach has been to remove all INFO logs and avoid WARNING logs. There are some WARNING logs, but they are effectively each a special case in some way. (I know of: if a service throws an exception and if there is a weird connection error on server-side.)

you should at least allow extensible logging so users would be able to contibute log4j/slf4j extension and default to JUL if none exists.

No. We are not making yet another pluggable logging API. That is what log4j/slf4j/JUL are; we don't need another. JUL's main issue is it can not be configured well in servlet and application containers. But SLF4J defaults to a null logger instead of JUL, and I can't accept it due to that one behavior craziness. I don't remember how Log4j works out-of-the-box from a library perspective.

[emaayan]

@emaayan, waitForReady and retry do not log failures. Also, Log4J/SLF4J has a JUL bridge/adapter which works okay.

Our current approach has been to remove all INFO logs and avoid WARNING logs. There are some WARNING logs, but they are effectively each a special case in some way. (I know of: if a service throws an exception and if there is a weird connection error on server-side.)

you should at least allow extensible logging so users would be able to contibute log4j/slf4j extension and default to JUL if none exists.

No. We are not making yet another pluggable logging API. That is what log4j/slf4j/JUL are; we don't need another. JUL's main issue is it can not be configured well in servlet and application containers. But SLF4J defaults to a null logger instead of JUL, and I can't accept it due to that one behavior craziness. I don't remember how Log4j works out-of-the-box from a library perspective.

when i'm seeing transient failures in my logs , i call that logging errors, i'ts better then not seeing anything at all. right now, any cases of connection refuses or unavailalbes aren't being logged.
i was offered to use the bridge, however my understanding is that it may incur a performance cost.

[ejona86]

however my understanding is that it may incur a performance cost

Given the fragmentation of the ecosystem, I don't think we can make everyone happy here. Since the logs remaining logs should be relatively rare, a 2x slowdown (I'm making up a number) in performance seems fine and generally undetectable. That is assuming that the bridge doesn't do silly things like log every debug entry.

[emaayan]

this is why i've opened a FR on being able to insert a listener that would give me a call back on errors while the services is retrying

…

On Thu, Jan 9, 2020 at 9:01 PM Eric Anderson ***@***.***> wrote: however my understanding is that it may incur a performance cost Given the fragmentation of the ecosystem, I don't think we can make everyone happy here. Since the logs remaining logs should be relatively rare, a 2x slowdown (I'm making up a number) in performance seems fine and generally undetectable. That is assuming that the bridge doesn't do silly things like log every debug entry. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1577?email_source=notifications&email_token=ADGP5MBDJSBJD23U27PKMC3Q45X6XA5CNFSM4B62UKX2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIRMVIY#issuecomment-572705443>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADGP5MDHKV65D4HNEXVROGDQ45X6XANCNFSM4B62UKXQ> .

[jeffalder]

We are a little late to the game, but New Relic's Java Agent is going to start using gRPC for some communication. We shade our dependencies so as not to conflict with the user's. We can't shade JUL, and it's not safe to modify JUL configuration in a user's application. We can shade SLF4J. I want to reiterate support for dropping JUL in favor of SLF4J.

If it becomes an issue, we plan to rewrite the classes during shading to use our logging implementation instead of JUL. This is the most horrid of horrid solutions, but we can actually make that work.

[ejona86]

@jeffalder, why would you need to shade java.util.logging?

[jeffalder]

@ejona86 Because users write their own applications and configure their own application logging, adding the Java Agent later. The Java Agent logs independently using Log4j 2 so agent failures are easier to separate and troubleshoot, and to avoid requiring the user to commingle our logs with their logs ... if they have any.

[ejona86]

@jeffalder, okay, so you separate the agent's logs from the application's, which means changing java.util.logging's configuration for your classes. Would you mind sharing the logs that were causing you to even notice how gRPC logged? I'd sort of assume these are from the Netty server, which may have solutions of its own.

[jeffalder]

which means changing java.util.logging's configuration for your classes

I don't think this is what's going on for us. None of our own classes log to java.util.logging, we directly use our shaded log4j 2. Some of Guava (also a shaded dependency) does use java.util.logging, unfortunately, but I'm not sure if we use those classes. At any rate, we've had no desire to surface that logging.

We looked into gRPC's logging for two reasons:

1. We noticed that our shading code that tweaks Guava's dependency on java.util.logging was hitting gRPC's code.
2. We noticed that if we have a retry policy set up for a service, we're not able to get any logging or notification on what the problem actually was. (for example: bad hostname or ALPN not available.)

As a result, we've disabled gRPC's retry because we are unable to surface information to the end user in our agent logs about why the connection is failing.

Because we're client-only, we're using the okhttp gRPC channel implementation.

Thanks for engaging! I know gRPC is very familiar with shading dependencies, so I hope you get our situation. @ejona86

[ejona86]

We noticed that our shading code that tweaks Guava's dependency on java.util.logging was hitting gRPC's code.

It's not completely clear to me what this is about. It seems like it may not be a problem itself, other than the realization "more code is using java.util.logging. Arg!"

We noticed that if we have a retry policy set up for a service, we're not able to get any logging or notification on what the problem actually was. (for example: bad hostname or ALPN not available.)

The retry code doesn't log at all. This seems separate. And not great. Would you mind filing an issue for it (and you can CC me)?

Because we're client-only, we're using the okhttp gRPC channel implementation.

The Netty transport is client-side as well. We generally expect Netty on "things that aren't Android." But since you probably don't care too much about performance and may appreciate small size, I could understand why you may choose the OkHttp transport.

---

Okay, none of this seems like it would be substantially changed if gRPC were using a different logging system. We can discuss the retry issue separately. If there's more things we should split out into other issues, we can.

[jeffalder]

@ejona86 I will absolutely file an issue on retry not logging.

FWIW, I still think using a facade that isn't a singleton like java.util.logging is the best approach for libraries, since users will consume them in all sorts of ways we can't plan for.

[emaayan]

you should think bigger :) because i filed an issue on wanting to configure a callback on retry as well connection failure, to allow me to do either logging or various reporting mechanisms.

…

On Fri, May 1, 2020 at 2:11 AM jeffalder ***@***.***> wrote: @ejona86 <https://github.com/ejona86> I will absolutely file an issue on retry not logging. FWIW, I still think using a facade that *isn't* a singleton like java.util.logging is the best approach for libraries, since users will consume them in all sorts of ways we can't plan for. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1577 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADGP5MCYIFCJ2SKXP2PI5FDRPIASVANCNFSM4B62UKXQ> .

[ejona86]

@emaayan, that conversation has moved to #6994. And yes, callbacks have been discussed.

[weijie0]

u can try flow code:
<dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>${logback.version}</version> </dependency>