ConfigDataLoader logging

[wind57]

I was looking at an issue that a user reported, and while debugging it saw an interesting thing.

In KubernetesConfigDataLoader, if we added some logging, for example:

private final Log log;

	public KubernetesConfigDataLoader(DeferredLogFactory factory) {
		log = factory.getLog(getClass());
	}

	@Override
	public ConfigData load(ConfigDataLoaderContext context, KubernetesConfigDataResource resource)
			throws IOException, ConfigDataResourceNotFoundException {

		log.debug("Kicking off ConfigDataLoader processing");

                ....

DeferredLogFactory is injected and I do see the logs I generate. But then, this method calls:

propertySources.add(bootstrapContext.get(ConfigMapPropertySourceLocator.class).locate(env)); or ConfigMapPropertySourceLocator::locate and the logs there are not present. I've tried to play around with DeferredLog, but with no luck.

I also saw this issue, but again, did not either understand or did not implement correctly.

Any hints into the direction of how to log these would be lovely, if any is possible at all.

Without this, we are kind of blind what is going on

[ryanjbaxter]

@philwebb do you have any insights?

[philwebb]

The DeferredLogFactory instance passed to the KubernetesConfigDataLoader constructor should be transferred to a real logger once all environment processing has occurred.

The exact order should be:

• EnvironmentPostProcessorApplicationListener is created to trigger Environment post-processing. It includes a DeferredLogs instance (which is a DeferredLogFactory) that gets past to post-processors.
• The ConfigDataEnvironmentPostProcessor is one such post-processor. It will create ConfigDataLoader instances and should pass the same DeferredLogs instance along.
• The loader can call DeferredLogFactory.getLog(...) to create a Log instance. Calls on the resulting logger are tracked but not actually logged at this point.
• After all post-processing has finished, the EnvironmentPostProcessorApplicationListener.finish() method should be called.
• This triggers DeferredLogs.switchOverAll() which should finally push the log messages to a correctly configured logger.

Adding a breakpoint to DeferredLogs.switchOverAll() would be a good place to start debugging why you're not actually seeing log messages.

[wind57]

thank you @philwebb , but it seems to me that we are talking about slightly different issues here.

• I do see logs from KubernetesConfigDataLoader - no problem here.
• The problem is that KubernetesConfigDataLoader::load internally calls ConfigMapPropertySourceLocator::locate and that one does some logging also. These logs is what I do not see, and that is the problem.

This is the chain that I was wondering if it's possible to make it work. I hope I make sense.

[wind57]

If I look at this class here, I notice :

@SuppressWarnings("FieldMayBeFinal") // allow setting via reflection.
private static Log logger = LogFactory.getLog(LeaseAwareVaultPropertySource.class);

and in this usage here

I notice that they override the loggers, otherwise no logging is going to work - just like in our case.

Ryan, it seems to me that we will need to do the same thing. A user had a real problem using the app : because there were no logs and he could tell what is wrong.

[wind57]

If you agree with the above, I have a PR here for fixing it.

[philwebb]

I don't know enough about the internals of spring-cloud-kubernetes or spring-cloud-vault, but resetting loggers using reflection seems a bit hacky to me.

[ryanjbaxter]

@wind57 have you tried passing the DeferredLogFactory to ConfigMapPropertySourceLocator? Could we have a setter that if called overrides the default Logger?

[wind57]

we could, absolutely Ryan. But then there are many other classes that are called internally... which makes this setting impossible. We would have to pass this logger everywhere.

I also agree that it's a bit hacky to do it with reflection, but if Vault does it... also, we are in total control here, it's not like we are setting logger from a different library, it's our own.

[wind57]

either way, we need a solution here and fast (imho), because users using config-data are totally without logs, not being able to tell if anything is wrong at all.

[wind57]

although I gave up on this idea, I will expres it still: we can use ThreadLocal and set the logger into it and have a "proxy" that will check if the logger is present in ThreadLocal. The only reason I did not even try to implement something like this, is the fact that vault was using reflection and the be fair, I thought that this is OK and may be we want to be consistent. may be I was wrong.

[ryanjbaxter]

we could, absolutely Ryan. But then there are many other classes that are called internally... which makes this setting impossible. We would have to pass this logger everywhere.

I dont think so, we leave the creation of the logger as is just not making it static then we add a setter and just call the setter in the config data case.

[wind57]

OK, so you are saying that ConfigMapPropertySourceLocator should have a setter where we can pass a different logger and override the existing one. So far, yes, it makes sense.

But ConfigMapPropertySourceLocator::locate calls internally KubernetesClientConfigMapPropertySourceLocator::getMapPropertySource that calls internally KubernetesClientUtils::getApplicationNamespace. How is the logger going to be passed down to KubernetesClientUtils? what am I missing?

[ryanjbaxter]

Yeah, I guess we would end up passing the logger around. But wouldn't that be the same problem with reflections where we would have to be calling all these classes and setting the logger in them?

[wind57]

imho, reflection is easier to manage, and no obscure code in the logic of how things are really done. There would be additions of public methods for those setters.

It's a lot easier to manage too, if u ask me. The code is common, all we need is say which classes to be updated, in case we find more.

[ryanjbaxter]

@philwebb what do you think? I like you don't think reflection is the right approach, but we can't be the only project (in fact Vault also is suffering from this) that would have the pass the Logger around in order to get things working.

[wind57]

We should replace the question label with a bug label

[wind57]

I was also wondering, considering the timelines for the next release (which I don't know what is), what if we have some solution in (even the reflection one), but keep this issue open in case we come up with something smarter? I feel weird for the fact that we made some good work on that config-data functionality and it's kind of useless in case things don't work :(

[ryanjbaxter]

The release will happen either tomorrow or today. I would rather not rush. The feature still works, its just logging that is the problem so this is not a blocker IMO. A service release will certainly be planned shortly after because as always we will have issues that come up.

[philwebb]

I like you don't think reflection is the right approach, but we can't be the only project (in fact Vault also is suffering from this) that would have the pass the Logger around in order to get things working.

No, it's unfortunately a bit of a tricky issue and I don't really have a good suggestion. We have spring-projects/spring-boot#28678 open in Spring Boot to look at it generally, but we're unlikely to get to it anytime soon.

[wind57]

seems to me like we won't have an option

[ryanjbaxter]

Thanks @philwebb.

@wind57 lets tackle this after the new year. I am on vacation beginning next week and wont be back till after the new year. I will spend some time when I get back looking at the options.

[wind57]

of course! happy Holidays in such a case Ryan!

[ryanjbaxter]

you too!

[wind57]

I have two proposals of implementations to may be solve this:

one here that uses the new feature of JDK : hidden classes.

another one here, that just uses reflection.

[ryanjbaxter]

Thanks!

I guess I am a little hesitant to make big changes, to just rip them all out when Boot fixes the issue.

[wind57]

If they fix the issue, as @philwebb says there are no plans for this one in the near future. Personally, I see no problems with either hidden classes nor reflection, as long as we provide logging for the end-users.

To ease the transition in the future, I wanted to:

• create a PR with tests that assert logging, so that we have tests and ensure the build fails if something is not OK
• have a separate PR that drops this implementation (whatever we choose from the two), so that is eases our future Boot integration, when such is available.

I feel somehow awkward having even a band-aid, but then not providing it... just my 0.02$

[ryanjbaxter]

@philwebb does this still seem like its going to happen in the near future?

[wind57]

I sound like a broken record here, still, what is a path forward here? If any. I am not trying to be pushy at all, it's just that this issue stays like a knot in my throat after all the pain I had to go with the user that reported it, nothing else :) thank you upfront.

[ryanjbaxter]

@wind57 please keep bugging me, I need to get with @philwebb to have a quick discussion
I have a couple of other things on my plate at the moment but I will try to get to this soon.

[wind57]

@ryanjbaxter random 2 weeks reminder... :)

[ryanjbaxter]

I have discussed this issue with a number of people on the team, ultimately everyone has come back to the point that the amount of code needed to fix the issue outweighs the issue itself. We would be much more concerned if this caused the application to not work properly, but ultimately the app will work fine, we just might run into some trouble debugging things.

I think at this point we close this issue, as its something Spring Boot needs to address.

I also want to acknowledge your effort in trying to find a viable solution to the problem, that has not gone unnoticed 🙌

[wind57]

oh it was a fun issue digging in! I just feel already bad for whomever is going to triage an issue when it comes (like the one we had) and logs are mute :) but I can't disagree either... Closing.

I am also going to close the two PRs I had with proposals.
In the background I am still going to maintain one of them, in case a future issue comes in and I want to help