LoggingHandler is re-entrant when logging FINE #1386
Assignees
Labels
api: logging
Issues related to the Cloud Logging API.
Comments
|
How are you registering the logging handler? We are aware of this and documented this behavior in our javadoc. To overcome this issue you should register the handler either using
|
|
@mziccard The first of those example did incorrectly use addHandler. When I modify to use the static addHandler, that fixes the NPE in initialization, but I still get a stack overflow when actually logging at FINE. I setup with a combination of logging.properties: and then code that creates a LoggingHandler with specific JSON auth file: public class StackDriverLogging {
static void init() throws Exception {
final LoggingOptions options;
String credentials = System.getenv("GOOGLE_OAUTH2_JSON_CREDENTIALS");
if (credentials == null) {
options = LoggingOptions.getDefaultInstance();
} else {
AuthCredentials authCredentials =
AuthCredentials.createForJson(new FileInputStream(credentials));
options = LoggingOptions.newBuilder().setAuthCredentials(authCredentials).build();
}
LoggingHandler handler = new LoggingHandler("test.log", options);
handler.setLevel(Level.FINE);
LoggingHandler.addHandler(Logger.getLogger(""), handler);
Logger log = Logger.getLogger(StackDriverLogging.class.getName());
log.info("test info");
log.fine("test fine");
//handler.flush();
}This code results in a stack overflow exception, with the following repeated part: and the console log issue the repeated log: My second example above is initialized entirely in a logging.properties file, but it uses a cut/paste/extended version of LoggingHandler that does the JSON auth initialization in the constructor and has some extra code in |
|
I am not able to reproduce. I tried the following code: public class AddLoggingHandler {
public static void main(String... args) throws Exception {
LoggingOptions options = LoggingOptions.getDefaultInstance();
LoggingHandler handler = new LoggingHandler("test.log", options);
handler.setLevel(Level.FINE);
LoggingHandler.addHandler(Logger.getLogger(""), handler);
Logger log = Logger.getLogger(AddLoggingHandler.class.getName());
log.info("test info");
log.fine("test fine");
}
}With the following I have the |
|
@mziccard I switched to your exact version of the code and moved my credentials to GOOGLE_APPLICATION_CREDENTIALS. I still get the infinite recursion?!?! I also tried passing in null for the options, to allow the internals to get the default instance and I get the same result. I'm using the 0.5.1 release. could it be something about my credentials? I can send them to you privately (they are just for a google test project) if you think it worth trying them? |
|
@mbrukman I've simplified my test even more. I now just setup logging in logging.properties: and my test code is just: package com.google.cloud.runtimes.jetty9;
import java.util.logging.Logger;
public class StackDriverLogging {
static void init() throws Exception {
Logger log = Logger.getLogger(StackDriverLogging.class.getName());
log.info("test info");
log.fine("test fine");
}
public static void main(String... args) throws Exception {
init();
}
}which gets the following stack overflow (added in full just in case the top or the bottom has something meaningful to you I just edited to take out most of the repeats]): |
|
I modified the code to printout the state of the loggers: static void init() throws Exception {
Logger log = Logger.getLogger(StackDriverLogging.class.getName());
for (Logger l : new Logger[]{ log,Logger.getLogger("sun.net.www.protocol.http.HttpURLConnection")}) {
while (l!=null) {
System.err.printf("Log '%s' upl=%b %s%n",l.getName(),l.getUseParentHandlers(),Arrays.asList(l.getHandlers()));
l = l.getParent();
}
}
log.info("test info");
log.fine("test fine");
}which produced: So the masking of the loggers looks to have worked as |
|
@gregw great, this is what I was about to suggest you to do. You are right, it seems that the masking is working just fine. In fact, if I run an analogous example I get the same output (set aside class names) and no recursion: Log 'com.google.cloud.examples.logging.snippets.AddLoggingHandler' upl=true []
Log '' upl=true [com.google.cloud.logging.LoggingHandler@48eff760]
Log 'sun.net.www.protocol.http.HttpURLConnection' upl=true []
Log 'sun.net.www.protocol.http' upl=false []
Log '' upl=true [com.google.cloud.logging.LoggingHandler@48eff760]This is really confusing. How are you running the app? Play java? Which version? |
|
I'm currently running from within eclipse IDE using java 1.8.0_40. There is definitely something fishy as if I modify the test to do: The first log line is correctly masked and does not go infinite, but the second one does??? Let me try running from command line.... |
|
Command line gives me same problem: |
|
I upgraded to java 1.8.0_77 and if fails running from command line on the some.random.log: my complete classpath is: with my classes in |
|
@gregw I'm unable to reproduce this either. Are you using OpenJDK? Can you create a minimal maven project that reproduces this problem and share it on your GitHub account? |
|
I'm using openJDK build 1.8.0_77-b03. I'll build a mvn project to reproduce shortly. |
|
@meltsufin I've created a reproduction in a small project. Because it includes credentials, I have not attached it here but posted it a private channel. You can build it with: And run it from the command line with: The recursive logs appear in n the jetty9-work log console |
|
Note also that I just deployed a LoggingHandler in the gcloud flex environment, with logging only at INFO and observed a similar loop on start up: Note this is using my copy/paste/modify of |
|
Has any consideration been given to using a threadlocal rather than masking to avoid such looping? Essentially any thread inside flush would set a threadlocal that would cause all log records generated by that thread to be ignored. I will give that approach a trial in my copy. |
|
I tried the thread local approach. It does stop the looping, but the netty service itself is so verbose outside of any write call that turning on FINE logging is not practicable anyway. But if you explicitly dial down the netty service this approach at least works for me. |
|
Just wondering, are you on the latest 0.6.0 version of logging. There was a change recently that put in the correct google auth, so it should no longer require a JSON or setting GOOGLE_APPLICATION_CREDENTIALS for deployed apps. For local apps, you should be setting |
|
@lesv - No, I'm on 0.5.1, Will try 0.6.0 now... |
|
Using 0.6.0 and the gcloud auth command, I still get infinite loop: |
|
Since with 0.6.0, credentials are no longer needed, I have zipped up the reproduction project here: |
|
@garrettjonesgoogle Is this something you can look at? Greg is working on a workaround that uses a thread-local flag instead of masking, but we would like to get to the bottom of this. Thanks! |
|
I will take a look. |
|
Just tested 0.7.0 and got the same stack overflow. |
|
The root cause is this:
My current plan is to add a thread-local in the GAX layer for all service calls, and throw an exception if the same service call occurs multiple times in the stack frame. The logging handler will catch this exception and defer the flush until later (which will happen anyway at the top-level flush invocation). This ends up preserving all FINE logs in the end. I have gotten this working on my machine - I will clean it up and get it pushed later. |
|
@garrettjonesgoogle FYI You can see the work around we have currently used in the flex jetty-runtime here. We use a thread local that simply discards all the logs generated by a thread during a flush. I would be a bit concerned that the exception thrown would consume additional memory and CPU to log something that is just an artefact of logging. While it would be nice to get the logs from the logging, I don't think it is essential, plus I'm concerned that once FINE logging is turned on, then we will essentially be in an infinite loop of logging, flushing, flushings the logs from the flush, flushing the logs from the flush of the logs of the flush.... ie will the server ever return to idle? Finally, is this threadlocal to be a replacement for the current approach that removes handlers from loggers? Or will it be in addition? |
|
You won't be in an infinite loop of logging, because the secondary flush becomes a no-op. Do you want http and grpc logs not related to logging when you turn on FINE logging? I don't intend on implementing an approach that removes handlers from loggers, so in that sense it's a "replacement". |
|
@garrettjonesgoogle I think we do want the clients to be able to see grpc logs, especially when they're using grpc for their own purposes. Even our own use of grpc for logging could generate logs, if users select that level of logging. We just want to make sure that there isn't an infinite loop or a serious performance impact for supporting it. |
|
I did a test, and it does turn out that when the logging call generates a log, it causes an infinite logging chain. It's not an infinite loop per se; it just means that each flush will queue up another log for the next flush, ad infinitum. I will change my approach so that logs generated as part of a logging call are not sent in the next logging call. It probably makes sense for them to still be logged locally though. |
|
This has taken a gnarly turn. It turns out that gRPC executes its remote calls within worker threads, which means that a ThreadLocal won't stop the worker thread from logging when it isn't supposed to. |
|
That is indeed gnarly. I'm struggling to think of a suggestion other than implementing a extremely simple client just for logging that itself does not log. |
|
Can't we start with a standard logging properties that doesn't use the google appender for JUL for grpc and only logs to console ?? |
|
@lesv the current LoggingHandler essentially does that already (it tries to ignore io.grpc, io.netty, com.google.api.client.http, and sun.net.www.protocol.http), but as @meltsufin says, they would like to be capable of getting grpc logs through the Logging service, as long as they're not for Logging grpc calls. Incidentally I don't know why HttpURLConnection is still logging despite attempts to turn it off. It might be because it goes through sun.util.logging.PlatformLogger, and consequently ignores the logging levels in JUL. If it could be turned off, the recursive trace posted by @gregw wouldn't have happened. |
|
I filed issue grpc/grpc-java#2515 to get help from the gRPC team. |
|
Note also that we have tried to avoid the issue with a logging.properties like: But the global FINE configuration appears to take effect instead of the specific INFO configurations, at least for some log events like: Not yet investigated why this is so, but we have tried just the don't turn it on approach. |
|
gRPC has noted that we can set a Context in one thread which will be accessible in the gRPC thread that handles the service call. I will try out this approach. |
|
The approach didn't work. Filed another issue to gRPC: grpc/grpc-java#2535 |
|
I sent out a PR to fix this. |
github-actions bot
pushed a commit
that referenced
this issue
Jun 21, 2022
…datatransfer to v2.2.3 (#1386) [](https://renovatebot.com) This PR contains the following updates: | Package | Change | Age | Adoption | Passing | Confidence | |---|---|---|---|---|---| | [com.google.cloud:google-cloud-bigquerydatatransfer](https://togithub.com/googleapis/java-bigquerydatatransfer) | `2.2.2` -> `2.2.3` | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | --- ### Configuration 📅 **Schedule**: Branch creation - At any time (no schedule defined), Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Renovate will not automatically rebase this PR, because other commits have been found. 🔕 **Ignore**: Close this PR and you won't be reminded about this update again. --- - [ ] <!-- rebase-check -->If you want to rebase/retry this PR, click this checkbox. ⚠ **Warning**: custom changes will be lost. --- This PR has been generated by [Mend Renovate](https://www.mend.io/free-developer-tools/renovate/). View repository job log [here](https://app.renovatebot.com/dashboard#github/googleapis/java-bigquerydatatransfer).
github-actions bot
pushed a commit
to yoshi-code-bot/google-cloud-java
that referenced
this issue
Oct 6, 2022
…17.0 (googleapis#1386) [](https://renovatebot.com) This PR contains the following updates: | Package | Change | Age | Adoption | Passing | Confidence | |---|---|---|---|---|---| | [com.google.cloud:google-cloud-bigquery](https://togithub.com/googleapis/java-bigquery) | `2.16.1` -> `2.17.0` | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | [](https://docs.renovatebot.com/merge-confidence/) | --- ### Release Notes <details> <summary>googleapis/java-bigquery</summary> ### [`v2.17.0`](https://togithub.com/googleapis/java-bigquery/blob/HEAD/CHANGELOG.md#​2170-httpsgithubcomgoogleapisjava-bigquerycomparev2161v2170-2022-10-03) [Compare Source](https://togithub.com/googleapis/java-bigquery/compare/v2.16.1...v2.17.0) ##### Features - Add remote function options to routine metadata ([#&googleapis#8203;2291](https://togithub.com/googleapis/java-bigquery/issues/2291)) ([d30670e](https://togithub.com/googleapis/java-bigquery/commit/d30670ee2edf498b0335f3dfdec3487f5627a9f3)) ##### Dependencies - Update dependency com.google.api.grpc:proto-google-cloud-bigqueryconnection-v1 to v2.5.5 ([#&googleapis#8203;2328](https://togithub.com/googleapis/java-bigquery/issues/2328)) ([6e48ec2](https://togithub.com/googleapis/java-bigquery/commit/6e48ec22f98f95cc93a6a0e2a068d8a4d8c822ca)) - Update dependency com.google.apis:google-api-services-bigquery to v2-rev20220913-2.0.0 ([#&googleapis#8203;2287](https://togithub.com/googleapis/java-bigquery/issues/2287)) ([fa33184](https://togithub.com/googleapis/java-bigquery/commit/fa331844dc1862120867d73ad87d87587a388576)) - Update dependency com.google.apis:google-api-services-bigquery to v2-rev20220924-2.0.0 ([#&googleapis#8203;2325](https://togithub.com/googleapis/java-bigquery/issues/2325)) ([82c2097](https://togithub.com/googleapis/java-bigquery/commit/82c2097a866804ffb95a871087438fc163e8b77c)) - Update dependency com.google.cloud:google-cloud-shared-dependencies to v3.0.4 ([#&googleapis#8203;2327](https://togithub.com/googleapis/java-bigquery/issues/2327)) ([188c779](https://togithub.com/googleapis/java-bigquery/commit/188c77995cad31b328cfbf745df164f4ac70b692)) - Update dependency gcp-releasetool to v1.8.9 ([#&googleapis#8203;2326](https://togithub.com/googleapis/java-bigquery/issues/2326)) ([52dfd13](https://togithub.com/googleapis/java-bigquery/commit/52dfd13a4d311526c784397f50ca5cf45b60f2a5)) - Update dependency importlib-metadata to v4.13.0 ([#&googleapis#8203;2323](https://togithub.com/googleapis/java-bigquery/issues/2323)) ([4c7e089](https://togithub.com/googleapis/java-bigquery/commit/4c7e089f281c7147cd468fbdbd19cd7238b49be3)) - Update dependency importlib-metadata to v5 ([#&googleapis#8203;2324](https://togithub.com/googleapis/java-bigquery/issues/2324)) ([bd43cf4](https://togithub.com/googleapis/java-bigquery/commit/bd43cf42443feba02d7970d3dd17c11d1b64872c)) - Update dependency org.graalvm.buildtools:junit-platform-native to v0.9.14 ([#&googleapis#8203;2288](https://togithub.com/googleapis/java-bigquery/issues/2288)) ([959519c](https://togithub.com/googleapis/java-bigquery/commit/959519cd9e5910ba7d93cce00c318ed322dcaf23)) - Update dependency org.graalvm.buildtools:native-maven-plugin to v0.9.14 ([#&googleapis#8203;2289](https://togithub.com/googleapis/java-bigquery/issues/2289)) ([3cf7ef8](https://togithub.com/googleapis/java-bigquery/commit/3cf7ef83d891480bf80fcb1879ca86e9e053304e)) - Update dependency org.junit.vintage:junit-vintage-engine to v5.9.1 ([#&googleapis#8203;2285](https://togithub.com/googleapis/java-bigquery/issues/2285)) ([65fac18](https://togithub.com/googleapis/java-bigquery/commit/65fac188db2514ae620fb5146055591cfe6ac995)) </details> --- ### Configuration 📅 **Schedule**: Branch creation - At any time (no schedule defined), Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the rebase/retry checkbox. 🔕 **Ignore**: Close this PR and you won't be reminded about this update again. --- - [ ] <!-- rebase-check -->If you want to rebase/retry this PR, click this checkbox. --- This PR has been generated by [Mend Renovate](https://www.mend.io/free-developer-tools/renovate/). View repository job log [here](https://app.renovatebot.com/dashboard#github/googleapis/java-asset). <!--renovate-debug:eyJjcmVhdGVkSW5WZXIiOiIzMi4yMTQuMCIsInVwZGF0ZWRJblZlciI6IjMyLjIxNy4wIn0=-->
github-actions bot
pushed a commit
to renovate-bot/google-cloud-java
that referenced
this issue
Oct 8, 2022
](https://renovatebot.com){kind=link}
🤖 I have created a release *beep* *boop* --- ## [3.7.1](https://togithub.com/googleapis/java-asset/compare/v3.7.0...v3.7.1) (2022-10-07) ### Dependencies * Update dependency com.google.api.grpc:proto-google-cloud-orgpolicy-v1 to v2.3.6 ([googleapis#1390](https://togithub.com/googleapis/java-asset/issues/1390)) ([4219b66](https://togithub.com/googleapis/java-asset/commit/4219b66da58325f5a133caa84243dc0958d90149)) * Update dependency com.google.api.grpc:proto-google-cloud-os-config-v1 to v2.5.6 ([googleapis#1382](https://togithub.com/googleapis/java-asset/issues/1382)) ([3abde9e](https://togithub.com/googleapis/java-asset/commit/3abde9e4130d62d9e6857dd3b016be88691bd7f4)) * Update dependency com.google.api.grpc:proto-google-cloud-pubsub-v1 to v1.102.20 ([googleapis#1384](https://togithub.com/googleapis/java-asset/issues/1384)) ([5904111](https://togithub.com/googleapis/java-asset/commit/5904111205fc7c698703eb8db805b159a6513389)) * Update dependency com.google.api.grpc:proto-google-identity-accesscontextmanager-v1 to v1.4.5 ([googleapis#1383](https://togithub.com/googleapis/java-asset/issues/1383)) ([48f2dd8](https://togithub.com/googleapis/java-asset/commit/48f2dd863c23ec3fffb24970046cab6795a64045)) * Update dependency com.google.cloud:google-cloud-bigquery to v2.17.0 ([googleapis#1386](https://togithub.com/googleapis/java-asset/issues/1386)) ([d3cf534](https://togithub.com/googleapis/java-asset/commit/d3cf534180a8b0c4a421ff52a998b43edd502e6c)) * Update dependency com.google.cloud:google-cloud-core to v2.8.20 ([googleapis#1380](https://togithub.com/googleapis/java-asset/issues/1380)) ([113b74e](https://togithub.com/googleapis/java-asset/commit/113b74e29f05047ba3eb22cee370b2b35b133991)) * Update dependency com.google.cloud:google-cloud-pubsub to v1.120.20 ([googleapis#1385](https://togithub.com/googleapis/java-asset/issues/1385)) ([792d9a2](https://togithub.com/googleapis/java-asset/commit/792d9a2aa2253e4cb6541c587810aab936aa9d81)) * Update dependency com.google.cloud:google-cloud-resourcemanager to v1.5.6 ([googleapis#1391](https://togithub.com/googleapis/java-asset/issues/1391)) ([9afc924](https://togithub.com/googleapis/java-asset/commit/9afc924fbe87b481dc3b731935d3dc021e1bae00)) * Update dependency com.google.cloud:google-cloud-storage to v2.13.0 ([googleapis#1392](https://togithub.com/googleapis/java-asset/issues/1392)) ([9660ee4](https://togithub.com/googleapis/java-asset/commit/9660ee42c68e7cb88e0d6867ac46f2cd6056ca17)) --- This PR was generated with [Release Please](https://togithub.com/googleapis/release-please). See [documentation](https://togithub.com/googleapis/release-please#release-please).
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
When using the LoggingHandler with logging turned up to FINE, it becomes re-entrant causing either an error or a stack overflow.
This appears due to the fact that classes used to implement LoggingHandler are themselves instrumented with Java Util Logging! Examples I have found are
io.netty(first stack trace below)and
HttpURLConnection(second stack trace using a cut/paste of LoggingHandler to com.google.cloud.runtimes.jetty9.LoggingHandler as I'm working on Issue #1329The text was updated successfully, but these errors were encountered: