DefaultAdvisorAutoProxyCreator skipping beans

[youngm]

My application worked just fine with 1.1.5. When I upgraded to 1.2 RC1 my DefaultAdvisorAutoProxyCreator began skipping a large number of my beans.

Here is a chunk of my log:

17:23:50,197 INFO  [XmlWebApplicationContext] Bean factory for application context [org.springframework.web.context.support.XmlWebApplicationContext;hashCode=2201387]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [propertyConfigurer,transactionManager,autoProxyCreator,transactionAttributeSource,transactionInterceptor,
transactionTemplate,transactionAdvisor,attributes,avalonContext,accountManagerDaoTarget,accountManagerDao,
avalonContextFilter,themeSource,localeResolver,themeResolver,themeMessageSource,sendEmail,selector,accountBasedDataManager0
,themeVelocityEngine,authenticationManager,casAuthenticationProvider,casProxyTicketValidator,cacheManager,ticketCacheBackend,
statelessTicketCache,casAuthoritiesPopulator,casProxyDecider,serviceProperties,roleVoter,casProcessingFilter,securityEnforcementFilter,
casProcessingFilterEntryPoint,businessAccessDecisionManager,httpRequestAccessDecisionManager,filterInvocationInterceptor,
accountSessionFactory,accountHibernateTemplate,nonCachedAccountHibernateTemplate,accountHibernateInterceptor,
accountHibernateAdvisor,accountLogicMessageSource,accountLogic,featureLogic,userLogic,announcementLogic,groupLogic,
accountPlanLogic,rateScheduleLogic,billingLogic,accountWebUtils,accountConverter,fieldConverter,accountLogicValidators,
mailTemplateMessageSource,velocityEngine,mailLogic,categorizedWordDataSource,mailDataSource,mailJdbcOperations,
bloodgulchSessionFactory,bloodgulchHibernateInterceptor,bloodgulchEntityInterceptor,bloodgulchHibernateTemplate,
bloodgulchHibernateAdvisor,eventLogic,assetFieldLogic,assetLogic,campaignLogic,fieldLogic,subscriptionSettingLogic,
pointBlankLogic,emailAddressLogic,assetActionLogic,binaryFileActionLogic,contentActionLogic,emailListActionLogic0
,folderActionLogic,imageActionLogic,templateActionLogic,textContentActionLogic]; root of BeanFactory hierarchy
17:23:50,197 INFO  [XmlWebApplicationContext] 81 beans defined in application context [org.springframework.web.context.support.XmlWebApplicationContext;hashCode=2201387]
17:23:50,197 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'propertyConfigurer'
17:23:50,197 INFO  [PropertyPlaceholderConfigurer] Loading properties from class path resource [bg_system.properties]
17:23:50,213 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'autoProxyCreator'
17:23:50,213 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountHibernateAdvisor'
17:23:50,229 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'attributes'
17:23:50,229 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountHibernateInterceptor'
17:23:50,229 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountSessionFactory'
17:23:50,244 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'transactionAdvisor'
17:23:50,244 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'transactionInterceptor'
17:23:50,244 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'transactionAttributeSource'
17:23:50,244 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'transactionManager'
17:23:50,260 INFO  [JtaTransactionManager] Using JTA UserTransaction: org.jboss.tm.usertx.client.ServerVMClientUserTransaction@1882c1a
17:23:50,260 INFO  [JtaTransactionManager] Using JTA TransactionManager: org.jboss.tm.TxManager@1079724
17:23:50,260 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'bloodgulchHibernateAdvisor'
17:23:50,260 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'bloodgulchHibernateInterceptor'
17:23:50,260 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'bloodgulchSessionFactory'
17:23:50,260 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'bloodgulchEntityInterceptor'
17:23:50,260 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountLogic'
17:23:50,291 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountHibernateTemplate'
17:23:50,322 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountLogicMessageSource'
17:23:50,322 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'userLogic'
17:23:50,338 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'featureLogic'
17:23:50,354 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'groupLogic'
17:23:50,369 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountPlanLogic'
17:23:50,385 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'mailLogic'
17:23:50,401 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'mailJdbcOperations'
17:23:50,401 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'mailDataSource'
17:23:50,401 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'velocityEngine'
17:23:50,401 INFO  [VelocityEngine] ************************************************************** 
17:23:50,401 INFO  [VelocityEngine] Starting Jakarta Velocity v@version@
17:23:50,401 INFO  [VelocityEngine] RuntimeInstance initializing.
17:23:50,401 INFO  [VelocityEngine] Default Properties File: org\apache\velocity\runtime\defaults\velocity.properties
17:23:50,401 INFO  [VelocityEngine] Default ResourceManager initializing. (class org.apache.velocity.runtime.resource.ResourceManagerImpl)
17:23:50,401 INFO  [VelocityEngine] Resource Loader Instantiated: org.apache.velocity.runtime.resource.loader.ClasspathResourceLoader
17:23:50,401 INFO  [VelocityEngine] ClasspathResourceLoader : initialization starting.
17:23:50,401 INFO  [VelocityEngine] ClasspathResourceLoader : initialization complete.
17:23:50,401 INFO  [VelocityEngine] ResourceCache : initialized. (class org.apache.velocity.runtime.resource.ResourceCacheImpl)
17:23:50,401 INFO  [VelocityEngine] Default ResourceManager initialization complete.
17:23:50,401 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Literal
17:23:50,401 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Macro
17:23:50,416 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Parse
17:23:50,416 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Include
17:23:50,416 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Foreach
17:23:50,447 INFO  [VelocityEngine] Created '20' parsers.
17:23:50,447 INFO  [VelocityEngine] Velocimacro : initialization starting.
17:23:50,447 INFO  [VelocityEngine] Velocimacro : "velocimacro.library" not set.  trying default library : VM_global_library.vm
17:23:50,463 INFO  [VelocityEngine] Velocimacro : default library not found.
17:23:50,463 INFO  [VelocityEngine] Velocimacro : allowInline = true : VMs can be defined inline in templates
17:23:50,463 INFO  [VelocityEngine] Velocimacro : allowInlineToOverride = false : VMs defined inline may NOT replace previous VM definitions
17:23:50,463 INFO  [VelocityEngine] Velocimacro : allowInlineLocal = false : VMs defined inline will be  global in scope if allowed.
17:23:50,463 INFO  [VelocityEngine] Velocimacro : messages on  : VM system will output logging messages
17:23:50,463 INFO  [VelocityEngine] Velocimacro : autoload off  : VM system will not automatically reload global library macros
17:23:50,463 INFO  [VelocityEngine] Velocimacro : initialization complete.
17:23:50,463 INFO  [VelocityEngine] Velocity successfully started.
17:23:50,463 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'mailTemplateMessageSource'
17:23:50,463 INFO  [XmlWebApplicationContext] Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@9957eb]
17:23:50,463 INFO  [XmlWebApplicationContext] Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@15b4535]
17:23:50,463 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'themeSource'
17:24:18,838 INFO  [DefaultListableBeanFactory] Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [propertyConfigurer,transactionManager,autoProxyCreator,transactionAttributeSource,
transactionInterceptor,transactionTemplate,transactionAdvisor,attributes,avalonContext
,accountManagerDaoTarget,accountManagerDao,avalonContextFilter,themeSource,localeResolver,
themeResolver,themeMessageSource,sendEmail,selector,accountBasedDataManager,themeVelocityEngine,
authenticationManager,casAuthenticationProvider,casProxyTicketValidator,cacheManager,
ticketCacheBackend,statelessTicketCache,casAuthoritiesPopulator,casProxyDecider,
serviceProperties,roleVoter,casProcessingFilter,securityEnforcementFilter,casProcessingFilterEntryPoint,
businessAccessDecisionManager,httpRequestAccessDecisionManager,filterInvocationInterceptor,
accountSessionFactory,accountHibernateTemplate,nonCachedAccountHibernateTemplate,
accountHibernateInterceptor,accountHibernateAdvisor,accountLogicMessageSource,accountLogic,
featureLogic,userLogic,announcementLogic,groupLogic,accountPlanLogic,rateScheduleLogic,
billingLogic,accountWebUtils,accountConverter,fieldConverter,accountLogicValidators,
mailTemplateMessageSource,velocityEngine,mailLogic,categorizedWordDataSource,
mailDataSource,mailJdbcOperations,bloodgulchSessionFactory,bloodgulchHibernateInterceptor,
bloodgulchEntityInterceptor,bloodgulchHibernateTemplate,bloodgulchHibernateAdvisor,eventLogic,
assetFieldLogic,assetLogic,campaignLogic,fieldLogic,subscriptionSettingLogic,pointBlankLogic,
emailAddressLogic,assetActionLogic,binaryFileActionLogic,contentActionLogic,emailListActionLogic,
folderActionLogic,imageActionLogic,templateActionLogic,textContentActionLogic]; root of BeanFactory hierarchy]
17:24:18,838 INFO  [ContextLoader] Using context class [org.springframework.web.context.support.XmlWebApplicationContext] for root WebApplicationContext
17:24:18,838 INFO  [ContextLoader] Root WebApplicationContext: initialization completed in 29484 ms
17:24:18,854 INFO  [OpenSessionInViewWithInitial] Initializing filter 'accountHibernateFilter'
17:24:18,854 INFO  [OpenSessionInViewWithInitial] Initializing filter 'accountHibernateFilter'
17:24:18,869 INFO  [OpenSessionInViewWithInitial] Filter 'accountHibernateFilter' configured successfully
17:24:18,869 INFO  [OpenSessionInViewWithInitial] Filter 'accountHibernateFilter' configured successfully
17:24:18,869 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountManagerDao'
17:24:18,869 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'accountManagerDaoTarget'
17:25:11,776 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'themeMessageSource'
17:25:15,104 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'themeVelocityEngine'
17:25:15,213 INFO  [VelocityEngine] ************************************************************** 
17:25:15,213 INFO  [VelocityEngine] Starting Jakarta Velocity v@version@
17:25:15,213 INFO  [VelocityEngine] RuntimeInstance initializing.
17:25:15,213 INFO  [VelocityEngine] Default Properties File: org\apache\velocity\runtime\defaults\velocity.properties
17:25:15,213 INFO  [VelocityEngine] Default ResourceManager initializing. (class org.apache.velocity.runtime.resource.ResourceManagerImpl)
17:25:15,213 INFO  [VelocityEngine] Resource Loader Instantiated: com.avaloninc.web.theme.ThemeResourceLoader
17:25:15,229 DEBUG [ThemeResourceLoader] Initializing
17:25:15,229 INFO  [VelocityEngine] ResourceCache : initialized. (class org.apache.velocity.runtime.resource.ResourceCacheImpl)
17:25:15,229 INFO  [VelocityEngine] Default ResourceManager initialization complete.
17:25:15,229 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Literal
17:25:15,229 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Macro
17:25:15,229 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Parse
17:25:15,229 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Include
17:25:15,229 INFO  [VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Foreach
17:25:15,229 INFO  [VelocityEngine] Created '20' parsers.
17:25:15,229 INFO  [VelocityEngine] Velocimacro : initialization starting.
17:25:15,229 INFO  [VelocityEngine] Velocimacro : "velocimacro.library" not set.  trying default library : VM_global_library.vm
17:25:15,260 DEBUG [ThemeResourceLoader] Getting input stream for: VM_global_library.vm
17:25:15,260 INFO  [VelocityEngine] Velocimacro : default library not found.
17:25:15,260 INFO  [VelocityEngine] Velocimacro : allowInline = true : VMs can be defined inline in templates
17:25:15,260 INFO  [VelocityEngine] Velocimacro : allowInlineToOverride = false : VMs defined inline may NOT replace previous VM definitions
17:25:15,260 INFO  [VelocityEngine] Velocimacro : allowInlineLocal = false : VMs defined inline will be  global in scope if allowed.
17:25:15,260 INFO  [VelocityEngine] Velocimacro : messages on  : VM system will output logging messages
17:25:15,260 INFO  [VelocityEngine] Velocimacro : autoload off  : VM system will not automatically reload global library macros
17:25:15,260 INFO  [VelocityEngine] Velocimacro : initialization complete.
17:25:15,260 INFO  [VelocityEngine] Velocity successfully started.
17:25:27,572 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'cacheManager'
17:25:27,572 INFO  [EhCacheManagerFactoryBean] Initializing EHCache CacheManager
17:25:30,776 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'ticketCacheBackend'
17:25:30,776 INFO  [EhCacheFactoryBean] Creating new EHCache cache region 'ticketCache'
17:25:32,026 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casProcessingFilter'
17:25:32,026 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'authenticationManager'
17:25:32,041 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casAuthenticationProvider'
17:25:32,041 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casAuthoritiesPopulator'
17:25:37,401 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casProxyDecider'
17:25:39,776 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casProxyTicketValidator'
17:25:39,791 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'serviceProperties'
17:25:42,494 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'statelessTicketCache'
17:25:45,791 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'avalonContextFilter'
17:25:46,479 INFO  [OpenSessionInViewWithInitial] Initializing filter 'bloodgulchHibernateFilter'
17:25:46,479 INFO  [OpenSessionInViewWithInitial] Initializing filter 'bloodgulchHibernateFilter'
17:25:46,479 INFO  [OpenSessionInViewWithInitial] Filter 'bloodgulchHibernateFilter' configured successfully
17:25:46,479 INFO  [OpenSessionInViewWithInitial] Filter 'bloodgulchHibernateFilter' configured successfully
17:25:46,510 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'securityEnforcementFilter'
17:25:46,510 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'filterInvocationInterceptor'
17:25:46,510 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'httpRequestAccessDecisionManager'
17:25:46,510 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'roleVoter'
17:25:48,026 INFO  [AbstractSecurityInterceptor] Validated configuration attributes
17:25:48,729 INFO  [DefaultListableBeanFactory] Creating shared instance of singleton bean 'casProcessingFilterEntryPoint'
17:25:50,213 DEBUG [DispatchTilesServlet] Start Tiles initialization
17:25:50,213 DEBUG [DispatchTilesServlet] Try to load Tiles factory
17:25:50,291 INFO  [PropertyMessageResources] Initializing, config='org.apache.struts.util.LocalStrings', returnNull=true
17:25:50,541 DEBUG [DispatchTilesServlet] Tiles Factory successfully loaded

You'll notice my autoProxyCreator is initialized at timestamp: 17:23:50,213

I set a breakpoint in line 218 of AbstractAutoProxyCreator.

I don't get a hit until it attempts to process bean "themeSource" on timestamp 17:23:50,463 skipping all of the beans created above it. From that point on most (but not all) of the beans being created hit the BeanPostProcessor methods of AbstractAutoProxyCreator. If I switch back to 1.1.5 everything works fine again.

Any ideas?

Mike

[youngm]

Actually nevermind. I forgot about Lazy initialization. Let me continue investigating why it's not working.

Mike

[Ben Alex]

I too found a problem with 1.2RC1 with DefaultAdvisorAutoProxyCreator.

Here's some of my application context:

	<bean id="common.party.partyManager" class="com.acegitech.common.party.domain.PartyManagerSpring">
		<property name="partyDao"><ref local="partyDao"/></property>
		<property name="counterManager"><ref bean="common.counter.counterManager"/></property>
	</bean>

   <bean id="authenticationManager" class="net.sf.acegisecurity.providers.ProviderManager">
      <property name="providers">
         <list>
          <!--   <ref local="daoAuthenticationProvider"/> -->
            <ref local="anonymousAuthenticationProvider"/>
            <ref local="rememberMeAuthenticationProvider"/>
         </list>
      </property>
   </bean>

   <bean id="daoAuthenticationProvider" class="net.sf.acegisecurity.providers.dao.DaoAuthenticationProvider">
      <property name="authenticationDao"><ref local="authenticationDao"/></property>
      <property name="userCache"><ref local="userCache"/></property>
   </bean>

   <bean id="authenticationDao" class="com.acegitech.common.party.domain.AcegiAuthenticationDao">
      <property name="partyManager"><ref bean="common.party.partyManager"/></property>
      <property name="roleMemberManager"><ref bean="common.auth.roleMemberManager"/></property>
   </bean>

Note that I've commented out the daoAuthenticationProvider from the authenticationManager.providers List. When commented out, DEBUG-level logging shows the PartyManager and RoleMemberManager beans are checked by DefaultAdvisorAutoProxyCreator. If I enable the daoAuthenticationProvider, DefaultAdvisorAutoProxyCreator never checks PartyManager or RoleMemberManager.

It was just trial and error that found this relationship between the authenticationManager.providers List and the DefaultAdvisorAutoProxyCreator issue. I also have many other beans not being handled by DefaultAdvisorAutoProxyCreator in 1.2RC1, and the above commenting out has not fixed those other issues.

[youngm]

Ben,

I doubt you're problem is related to mine. It turned out that mine was a circular dependency problem. In a round about way my advisor needed a bean that needed to be advised. I thought it was related to 1.2 but it turns out it was because of a recent checkin from another team member.

Mike

[Ben Alex]

After a bit more research, it seems that my problem is that if an interceptor uses a bean as a collaborator, DefaultAdvisorAutoProxyCreator will no longer include such a bean in its list of beans to process.

AFAIK this differs from 1.1.5. Would someone please confirm if this is a deliberate change. If so, how are we meant to advise beans used by interceptors? I need to do this all the time.

[youngm]

Although we used different language I believe you're experiencing the same problem as I. I'm pretty sure 1.1.5 had the same problem. Regardless, my solution was an ugly one. I made the interceptor BeanFactoryAware and lazily retrieved the required bean from the bean factory when it was needed instead of injecting it. This solution may be ugly but if you're in a hurry it works as a quick and dirty fix. That is if I'm understanding you're problem correctly.

Mike

[Juergen Hoeller]

No, there hasn't been a deliberate change in that behavior. I have reworked the auto-proxy creator facility quite a bit for 1.2 RC1, in particular the TargetSourceCreator mechanism, so there might be some side effect. The test suite still passed, though, so I doubt that some general behavior could have changed accidentially.

I'll have a look whether I can find revelant differences between 1.1.5 and 1.2 RC1 in that area. Any input on details is appreciated.

Juergen