Posted on by | Posted in Developer Blog | Tagged , , , ,

Recently we had a problem related Springs auto-proxy feature that I think is worth writing about.

The Problem

We use Spring as our framework of choice because it provides us with a nice set of convenience features when bootstrapping and plugging together our application.
One of these features is caching: We cache our users' roles because their definitions are stored in a pretty slow external system and change rarely.

@Component
public class RoleRepository {

  @Cacheable(CacheConfig.ROLES_NAME)
  public Set<Role> loadRoles() {
    // .. slow call to external system
  }
}

Since our RoleRepository is a component managed by Spring it gets picked up automatically during boot and loadRoles() gets backed by a cache. Spring implements this by proxying our repository. See Spring Reference Documentation for details. As a result the "real" loadRoles() method gets triggered only once in 10 minutes and all the other calls are served from the cache.

After several sprints we noticed a problem with the caching. While in caching worked for other beans it stopped working for the shown RoleRepository.
We noticed this because our health-check which (indirectly) triggers the loadRoles() and runs every 5 seconds did not hit the cache and therefore produced a log-entry every 5 seconds. The cache for roles was empty, regardless of how often loadRoles() was called.

While debugging the issue we found out that the proxy that should do the caching was not generated for RoleRepository. During bootstrap of the application Spring gave us a corresponding hint:

INFO 7189 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'RoleRepository' of type [class ...RoleRepository] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

What is a BeanPostProcessor

A BeanPostProcessor is a special component that allows to manipulate other beans after they are created.
These postprocessors can manipulate beans or even replace them completely. Spring ships with several implementations that do all kinds of stuff. For example there is one that checks if a bean implements ApplicationContextAware and sets the ApplicationContext if so. Also many of the "proxy-stuff" for @Async, @Transactional, @Caching and so on is done using a BeanPostProcessor. You can also implement your own postprocessors.

To be able to postprocess all beans with all BeanPostProcessors Spring has to create them before it creates the "regular" beans.

The Chicken and the Egg

But you can also inject Spring beans into postprocessors. If you inject a bean into a postprocessor Spring has to create this bean even before it creates the corresponding postprocessor you inject it to. In this case it no longer guarantees that all postprocessors are able to process the injected bean but instead logs the message shown above.

In our example the log-message means that there is one postprocessor that (directly or indirectly) leads to creation of our RoleRepository and there are more postprocessors to be created later (probaly the one that handles @Cachable) that will not be able to post-process our RoleRepository.

Debugging the Problem

Unfortunately the log-entry does not help very much in finding out what exactly is the problem.
The statement is produced by BeanPostProcessorChecker which is an inner class in PostProcessorRegistrationDelegate. To find out what exactly happens here I set a breakpoint right at the log-statement and booted our application in debug-mode. Since there are several beans created I waited for the statement in question (in our case the one with beanName = roleRepository).

To find out what caused the creation of our roleRepository I simply followed the call-stack down the getObject methods. In our case the chain was:
roleRepository -> authorityService -> customerPermissionEvaluator -> delegatingPermissionEvaluator -> customMethodSecurityConfiguration -> methodSecurityMetadataSource -> (... more Spring setup code ...)

debugging_getobject

So the RoleRepository is created because it is needed by our custom implementation of Spring Securities PermissionEvaluator-Interface that is used to evaluate security related expressions like the ones that can be used with @PreAuthorize:

@PreAuthorize("hasPermission(#customer, AUTHORITY_BILLING)")
public Optional<BillingDoc> findById(Customer customer, String documentId) {
  // boring business logic here
}

So when Spring Security is bootstrapped (which seems to be done before caching is) it also initializes a part of our "business-beans" which then cannot be postprocessed with caching.

The Fix

To fix the problem I cut the eager dependency from our security-code and replaced it by a lazy one.

@Autowired
public CustomerPermissionEvaluator(AuthorityService authorityService) {
  this.authorityService = authorityService;
}

was changed to

@Autowired
public CustomerPermissionEvaluator(ObjectFactory<AuthorityService> authorityServiceObjectFactory) {
  this.authorityServiceObjectFactory = authorityServiceObjectFactory;
}

@Override
public boolean hasPermission(Authentication authentication, Object targetDomainObject, Object permission) {
  AuthorityService service = this.authorityServiceObjectFactory.getObject();
  // ... do stuff with service
}

By using Springs ObjectFactory and calling its getObject() later (not during construction of the CustomerPermissionEvaluator) we delay the creation of AuthorityService (and of beans it needs such as the RoleRepository).
By doing so they can later be processed by all BeanPostProcessors and the log message in question disappeares & caching works again \o/.

Note that there are other ways to solve the problem. One other thing I can think of is to change the order the PostProcessors are created.

Final Thougths

In conclusion you might want to actively watch the statements Spring logs at INFO and above during your applications bootstrap.

Especially the mentioned statement about beans being not eligible for auto-proxying should not contain any of your non-infrastructure beans.

Also make sure there is no eager dependency between your infrastructure-related code and your business-logic. At least double-check and challenge these decisions. This is especially true because dependency-graphs get pretty big pretty fast. In our example there were 20 other "business" beans not eligable for auto-proxying because of the same eager dependency.


About Marc Kannegiesser

Senior Java Developer / Architect


Schreibe einen Kommentar

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert.