Stephen Todd opened SPR-10430 and commented

In org.springframework.aop.framework.autoproxy.BeanFactoryAdvisorRetrievalHelper, if an advisor is currently in creation and should be a candidate for a bean being created, it is silently dropped. From the source, it appears that this isn't intended to happen silently. What I experienced was that the advisor is not applied and there is no log out (or an exception). Below is the offending code (BeanFactoryAdvisorRetrievalHelper:83-104 in current master):

for (String name : advisorNames) {
    if (isEligibleBean(name) && !this.beanFactory.isCurrentlyInCreation(name)) {
        try {
            advisors.add(this.beanFactory.getBean(name, Advisor.class));
        }
        catch (BeanCreationException ex) {
            Throwable rootCause = ex.getMostSpecificCause();
            if (rootCause instanceof BeanCurrentlyInCreationException) {
                BeanCreationException bce = (BeanCreationException) rootCause;
                if (this.beanFactory.isCurrentlyInCreation(bce.getBeanName())) {
                    if (logger.isDebugEnabled()) {
                        logger.debug("Ignoring currently created advisor '" + name + "': " + ex.getMessage());
                    }
                    // Ignore: indicates a reference back to the bean we're trying to advise.
                    // We want to find advisors other than the currently created bean itself.
                    continue;
                }
            }
            throw ex;
        }
    }
}

As can be seen in the code, we check if the advisor bean (with name "name") is currently being created in the bean factory. If it is, then there is no else and the advisor is silently dropped. If we look further into the code, it appears that we have an entire catch block setup to catch the same condition. If the check (&& !this.beanFactory.isCurrentlyInCreation(name)) is removed, then we will correctly execute the catch logic, which includes logging the issue (which maybe ought to be logged at warning level rather than debug).

Hopefully, we can save others from hours in the debugger like me. I spent a couple days in the debugger trying to figure out why my @Transaction annotation wasn't getting applied to my UserService. Turned out I had a dependency like this: create @Transactional advisor -> postprocess bean -> create MethodSecurity advisor -> create dependency UserService (which is @Transactional). As a result, the user service would not execute code in a transaction and my queries were failing. After finally discovering the issue, I had to late bind my custom MethodSecurity advisor.

Thanks!

Affects: 3.2.2

2 votes, 6 watchers

Comment From: spring-projects-issues

Drew Mazurek commented

I was able to capture log messages of this in action:

Creating instance of bean 'org.springframework.aop.config.internalAutoProxyCreator' Finished creating instance of bean 'org.springframework.aop.config.internalAutoProxyCreator' Creating instance of bean 'org.springframework.transaction.config.internalTransactionAdvisor' Creating instance of bean 'com.googlecode.ehcache.annotations.config.internalEhCacheCachingAdvisor' Creating instance of bean 'myBean1' Finished creating instance of bean 'myBean1' Finished creating instance of bean 'com.googlecode.ehcache.annotations.config.internalEhCacheCachingAdvisor' Finished creating instance of bean 'org.springframework.transaction.config.internalTransactionAdvisor' Creating instance of bean 'myBean2' Creating implicit proxy for bean 'myBean2' with 0 common interceptors and 2 specific interceptors Finished creating instance of bean 'myBean2'

In this case, myBean1 doesn't get proxied since the two advisors aren't finished being created yet. myBean2 works fine.

Is there a fix or workaround in sight?

Comment From: spring-projects-issues

Kirill Kadyrko commented

Confirm the issue. Looking for a workaround.

Comment From: spring-projects-issues

Juergen Hoeller commented

Good catch. I've added logging for the case where the framework is skipping an advisor bean because it is currently in creation itself.

Note that the currently-in-creation check in the catch block is for a different case: There we're skipping an advisor because one of the beans that it depends on is currently in creation - for example, because the advisor is pointing back to the bean that we're currently trying to advise, or to a bean that in turn depends on that current bean. I've refined the log message accordingly.

As for the log level, those checks do work out fine in scenarios where an advisor is obviously only meant to apply to beans other than the ones that it depends on itself. This is then just the framework trying to figure out intended applicability of each advisor by reacting to its dependency structure. In such a scenario, warn or even info level logging wouldn't be appropriate.

Juergen

Comment From: johnfreier

I also ran into this issue and was able to fix it by lazy loading my beans inside the advisor.

Example:

@Component
public class CustomPermissionEvaluator implements PermissionEvaluator {

    @Lazy
    @Autowired
    private UserService userService;

    ...
}

I hope this helps someone and saves them a few days of debugging.

Comment From: darioseidl

Could this issue be reopened and reconsidered?

Just like OP, I just spent a long time debugging why some @Transactional annotations were ignored. Transactional issues are notoriously hard to debug to begin with. For me, it typically goes like this, first thinking it's a simple mistake like a forgotten annotation, then looking for other pitfalls, like self invocation within a class, or passing detached entities across transaction borders, or a problem with (async/scheduled) threads.

The last thing I would expect is that @Transactional annotations are just silently not detected for a bean at all, as can be the case when ~~the org.springframework.transaction.config.internalTransactionAdvisor is being skipped during bean creation.~~ your bean is created before the org.springframework.transaction.config.internalTransactionAdvisor.

You need to turn on the trace log level for logging.level.org.springframework.transaction.annotation.AnnotationTransactionAttributeSource to see which classes/methods are detected as transactional (here I see that some are missing).

And then turn on the trace log level for org.springframework.aop.framework.autoproxy.BeanFactoryAdvisorRetrievalHelper to see messages like

Skipping currently created advisor 'org.springframework.transaction.config.internalTransactionAdvisor'

hinting at the root of the problem. Sadly, here we don't see for which bean the advisor is skipped, but I can find that out with the debugger.

I see that the message "Skipping currently created advisor " has been added since the OP created this issue (before that it was completely silent)~~, but shouldn't that message be at least an info or a warning? Or is there some other way to detect when the internalTransactionAdvisor is being skipped?~~

Edit: Oh, I realize now, the presense of that message by itself doesn't indicate a problem. It seems it's only a problem when a bean with transactional annotations is created before the internalTransactionAdvisor. The better logger to see that is org.springframework.beans.factory.support.DefaultListableBeanFactory (on debug).

The question then is, is there some way to detect / ensure that a bean with @Transactional annotation is not created too early?

Comment From: socia1cast

I had the same problem that the @Cacheable and @CachePut annotations can not work, because the internalCacheAdvisor being created can not be added to the list of advisors.

More details in https://stackoverflow.com/questions/76350019/the-cglib-enhancement-can-not-work-after-i-introduce-the-spring-boot-starter-dat

Johnfreier previously mentioned a solution utilizing @Lazy, but I believe there is room for improvement at the framework level.

Comment From: linuxmin

@socia1cast We solved the problem by first debugging which beans are in creation when the needed advisor is also in creation. For the transactional advisor, there were a few beans in creation at the same time. We have an authentication manager for database access wired and configured within our spring xml configuration and added a depends-on="org.springframework.transaction.config.internalTransactionAdvisor" within the bean definition of our database authentication manager. This led to the initialization of the transactional advisore before any beans that needed database acesss and therefore transactional annotations to be processed by the advisor.

Maybe this works for you too!