Closed coryfoo closed 3 years ago
meltsufin
commented
3 years ago @coryfoo I tried adding Stackdriver Logging to our Secret Manager Sample, but I'm unable to reproduce the error. See: https://github.com/spring-cloud/spring-cloud-gcp/compare/gh-2554?expand=1 Are you able to provide an example of how to reproduce the issue?
coryfoo
commented
3 years ago @meltsufin I made a paired down project that makes it fail. It turns out there are two other things that are needed:
1) It also requires a dependency on pubsub:
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-gcp-starter-pubsub</artifactId>
<version>${gcp.starter.version}</version>
</dependency>2) You must have a logback-spring.xml defined with a stackdriver appender. This file is enough:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<springProperty name="applicationName" source="spring.application.name" defaultValue="UNKNOWN_APPLICATION_NAME"/>
<appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
<log>${STACKDRIVER_LOG_NAME:-${applicationName}.log}</log>
<flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL:-WARN}</flushLevel>
</appender>
</configuration>@coryfoo Indeed, your configuration reproduces the error, and it's not clear to me what exactly causes it. However, the logging configuration you provided is not what we recommend, and if you use our recommended logging configuration, the error doesn't show up. I just tested it in the branch I already shared with you. Is there any reason you cannot use this logging configuration?
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/cloud/gcp/logging/logback-appender.xml" />
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<root level="INFO">
<!-- If running in GCP, remove the CONSOLE appender otherwise logs will be duplicated. -->
<appender-ref ref="CONSOLE"/>
<appender-ref ref="STACKDRIVER" />
</root>
</configuration>@meltsufin for the stackdriver appender config we also have a custom enhancer element that we use to enrich the log message payload. Because of this, I don't think we can use the configuration you posted above.
After playing around with the configuration you posted above, I am still able to get it to throw if I remove <appender-ref ref="STACKDRIVER" /> from the root logger. Our configuration puts the STACKDRIVER appender-ref in a section that is hidden underneath a springProfile tag which is not run locally, like so:
<springProfile name="production">
<root level="INFO">
<appender-ref ref="STACKDRIVER" />
<appender-ref ref="FILE" />
</root>
</springProfile>Perhaps this is the reason that it throws locally, as the appender-ref is not called in the default profile.
dzou
commented
3 years ago I can help take a look at this too.
meltsufin
commented
3 years ago Thanks, @dzou!
@coryfoo I've tried commenting out <appender-ref ref="STACKDRIVER" /> in my repro, and I'm still not getting the exception.
I suspect there might be something with the fact that you import org/springframework/boot/logging/logback/base.xml instead of org/springframework/boot/logging/logback/defaults.xml, or the order in which appenders are defined, but I don't know for sure.
dzou
commented
3 years ago Hey so I took a look and ran this through the debugger. The reason why the error pops up is it seems that Spring will create the logging environment, destroy it, and then create it again. I think Spring does this for various reasons but I don't know why.
You can observe this behavior by putting some breakpoints on the start and stop methods of LoggingAppender (superclass of the spring logging appender).
Try reproducing the error in a debugger with those breakpoints. The error message is printed out when start() is called followed by another start().
Then try observing the behavior with the logback config Mike posted: You see start(), stop(), start() called in that sequence. And the error doesn't get printed out.
So basically my understanding is that somehow the logback configuration affects this startup/cleanup lifecycle that Spring runs. If the stop() is not called, the client object is garbage collected which is why you get that error.
I then tried to edit @coryfoo 's logback configuration so that the correct lifecycle occurs. I can get the correct start/stop/start lifecycle to occur by surrounding the config in the <root level="INFO"> tag:
<root level="INFO">
<appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
<log>${STACKDRIVER_LOG_NAME:-${applicationName}.log}</log>
<flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL:-WARN}</flushLevel>
</appender>
</root>In the config @coryfoo listed its just an appender on its own without a root level. So just add the root level tag around it and I think it should work.
Though it looks like your production logback config does indeed wrap a root level around the appender so i'm not sure why it doesnt work. Maybe you can share another logback config file that breaks the sample but that uses the root level?
But the bottom line is I think error message is OK and everything will still work. The first logger client was garbage collected but the second one that gets created by Spring should still be being used.
coryfoo
commented
3 years ago @dzou Can confirm that embedding the stackdriver appender within a root element does not throw the reported exception anymore. Thanks for your help (and @meltsufin)!
meltsufin
commented
3 years ago Thanks for the update @coryfoo!
coryfoo
commented
3 years ago @dzou @meltsufin update here: Logback does not like appender definitions defined within the root element. Therefore, I think this is still an issue.
dzou
commented
3 years ago Does this work for you:
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<springProperty name="applicationName" source="spring.application.name" defaultValue="UNKNOWN_APPLICATION_NAME"/>
<appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
<log>${STACKDRIVER_LOG_NAME:-${applicationName}.log}</log>
<flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL:-WARN}</flushLevel>
</appender>
<root level="INFO">
<appender-ref ref="STACKDRIVER" />
</root>
</configuration>I think the appender that you define needs to be "referenced" in the root level. However you can define them outside the root element.
coryfoo
commented
3 years ago @dzou I see, this is back to where I was before. Yes, this works, however, I'd much prefer to not have Stackdriver enabled by default as would be the case with this configuration.
dzou
commented
3 years ago @coryfoo - Hmm what if you put the appender declaration in your profile as well?
<springProfile name="production">
<appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
<log>${STACKDRIVER_LOG_NAME:-${applicationName}.log}</log>
<flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL:-WARN}</flushLevel>
</appender>
<root level="INFO">
<appender-ref ref="STACKDRIVER" />
</root>
</springProfile>@dzou That's what I tried, which works great locally, but led to some not fun quick fixes in production (ie the name of the profile) as that configuration in invalid for logback.
dzou
commented
3 years ago Ah I see. I think this is probably the best we can do here, at least within the scope of spring-cloud-gcp. It seems like this might be a deeper issue with Logback/Spring (like when and why it creates/destroys appenders on startup).
When using SecretManager and Stackdriver Logging in the same project (1.2.5.RELEASE), at application startup an exception is thrown and logged to the console:
If you remove Stackdriver Logging from the project then the SecretManager plugin works as expected, and vis-a-versa.
After this message appears, I can still access secrets using SecretManager. It is unclear if the Stackdriver logging integration is still operational.