java - @Cacheevict 有时会在上下文中丢失对象 (EL1011E)

Question

我与错误抗争了大约一个星期，但没有任何结果。我有一个升级到 Spring 3.2.11.RELEASE 和 Hibernate 4.2.15.Final 的遗留 Spring 应用程序。有一个包含 Spring 缓存注释方法的类:

public class GroovyFormulaScriptCompilerImpl implements FormulaScriptCompiler, CacheFlusher<ClassifyObjectAttributePlain>, InitializingBean {
   …
    @Override
    @Cacheable(value="compile_cache", key="'formulaforAttribute' + #classifyObjectAttribute.getPlainId()")
    public FormulaScript compile(ClassifyObjectAttributePlain classifyObjectAttribute) {
       ...
    }

    @Override
    @CacheEvict(value="compile_cache", key="'formulaforAttribute' + #arg0.getPlainId()")
    public void flush(ClassifyObjectAttributePlain arg0) {
      if(logger.isDebugEnabled())
        logger.debug("Flushing formula script for attribute id=" + arg0.getPlainId() + "[" + arg0.getPlainData().getName() + "]");
    }
} 

在某个时刻，会生成一个应用程序事件，它会导致监听器调用在多个类中声明的 flush() 方法，包括 GroovyFormulaScriptCompilerImpl 类的实例。肯定会调用 flush 方法，因为我在日志文件中看到了 logger.debug 输出(见下文，时间为 19:39:01,149)，但从方法返回后必须从缓存中逐出一个项目因错误而失败: “org.springframework.expression.spel.SpelEvaluationException: EL1011E:(pos 30): 方法调用:尝试在空上下文对象上调用方法 getPlainId()”。这会导致回滚数据库事务。下面是日志文件的摘录(我缩短了 hibernate 跟踪消息):

19:39:01,131 DEBUG RecWasModifiedPublicationInterceptor:23 - Generating modification event for ClassifyObjectAttributePlain id=142...
19:39:01,131 DEBUG DefaultListableBeanFactory:243 - Returning cached instance of singleton bean 'trigger.attributeWasModifiedObserver.observable'
19:39:01,131 DEBUG DefaultListableBeanFactory:243 - Returning cached instance of singleton bean 'com.ps.service.event.RecWasModifiedFlushingListener#0'
19:39:01,132 DEBUG DefaultListableBeanFactory:243 - Returning cached instance of singleton bean 'com.ps.service.event.RecWasModifiedFlushingListener#1'
19:39:01,132 DEBUG DefaultListableBeanFactory:243 - Returning cached instance of singleton bean 'com.ps.service.event.RecWasModifiedFlushingListener#2'
19:39:01,132 DEBUG DefaultListableBeanFactory:243 - Returning cached instance of singleton bean 'com.ps.service.event.RecWasModifiedFlushingListener#3'
19:39:01,132 DEBUG CTAttributeWasModifiedObservingTrigger:79 - Generating RecWasModifiedEvent for classify type = 42 due to change of attribute packDownGrade
19:39:01,133 DEBUG CTAttributeWasModifiedObservingTrigger:99 - Removed observing for classify type 42
19:39:01,133 DEBUG ClassifyDataCompilerImpl:76 - Flushing classify type id=42 [Subs]
19:39:01,148 DEBUG JpaDcsDao:948 - Flushing classify type id=42
19:39:01,149 DEBUG GroovyFormulaScriptCompilerImpl:111 - Flushing formula script for attribute id=142[packDownGrade]
19:39:01,155 DEBUG HibernateTransactionManager:844 - Initiating transaction rollback
19:39:01,156 DEBUG HibernateTransactionManager:571 - Rolling back Hibernate transaction on Session [...]
19:39:01,156 DEBUG AbstractTransactionImpl:203 - rolling back
19:39:01,169 DEBUG JdbcTransaction:164 - rolled JDBC Connection
19:39:01,169 DEBUG JdbcTransaction:126 - re-enabling autocommit
19:39:01,169 DEBUG LogicalConnectionImpl:198 - Aggressively releasing JDBC connection
19:39:01,169 DEBUG LogicalConnectionImpl:232 - Releasing JDBC connection
19:39:01,169 DEBUG LogicalConnectionImpl:250 - Released JDBC connection
19:39:01,170 DEBUG HibernateTransactionManager:633 - Closing Hibernate Session [...] after transaction
19:39:01,171 DEBUG JdbcCoordinatorImpl:182 - HHH000420: Closing un-released batch
19:39:01,171  WARN ChangelogEditorController:53 - Error parsing request
org.springframework.expression.spel.SpelEvaluationException: EL1011E:(pos 30): Method call: Attempted to call method getPlainId() on null context object
at org.springframework.expression.spel.ast.MethodReference.throwIfNotNullSafe(MethodReference.java:135)
at org.springframework.expression.spel.ast.MethodReference.getValueRef(MethodReference.java:68)
at org.springframework.expression.spel.ast.CompoundExpression.getValueRef(CompoundExpression.java:63)
at org.springframework.expression.spel.ast.CompoundExpression.getValueInternal(CompoundExpression.java:82)
at org.springframework.expression.spel.ast.OpPlus.getValueInternal(OpPlus.java:70)
at org.springframework.expression.spel.ast.SpelNodeImpl.getValue(SpelNodeImpl.java:93)
at org.springframework.expression.spel.standard.SpelExpression.getValue(SpelExpression.java:89)
at org.springframework.cache.interceptor.ExpressionEvaluator.key(ExpressionEvaluator.java:95)
at org.springframework.cache.interceptor.CacheAspectSupport$CacheOperationContext.generateKey(CacheAspectSupport.java:448)
at org.springframework.cache.interceptor.CacheAspectSupport.inspectCacheEvicts(CacheAspectSupport.java:251)
at org.springframework.cache.interceptor.CacheAspectSupport.inspectAfterCacheEvicts(CacheAspectSupport.java:227)
at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:212)
at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy60.flush(Unknown Source)
at com.ps.service.event.RecWasModifiedFlushingListener$1.update(RecWasModifiedFlushingListener.java:32)
at java.util.Observable.notifyObservers(Observable.java:159)
at com.ps.service.event.RecWasModifiedObservingListener.onApplicationEvent(RecWasModifiedObservingListener.java:40)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:96)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:334)
at com.ps.service.event.RecWasModifiedPublicationInterceptor.invoke(RecWasModifiedPublicationInterceptor.java:24)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:51)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:51)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:51)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:51)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy59.updateClassifyObjectAttribute(Unknown Source)
...

我无法理解的是为什么参数 arg0 在 flush 方法中可用，但稍后在 SpEL 上下文中变得不可用。

下面是 ClassifyObjectAttributePlain 类中 getPlainId() 方法的声明(它包含一些 Hibernate 缓存注释，但二级缓存是全局关闭的):

@Entity(name="object_attribute_plain")
@Table(name="fact_attributes")
@Cache(usage=CacheConcurrencyStrategy.READ_WRITE,region="rules_cache")
@BatchSize(size=5)
@Filter(name="logicalDeletedFilter")
public class ClassifyObjectAttributePlain extends PlainRecordAbstract<ClassifyObjectAttribute> {
private Long plainId;
private static final String seqName="fatr_seq";

@Id
@Column(name="fatr_id")
@SequenceGenerator(name=seqName,sequenceName=seqName,allocationSize=1)
@GeneratedValue(strategy=GenerationType.SEQUENCE,generator=seqName) 
public Long getPlainId() {
    return plainId;
}

public void setPlainId(Long id) {
    this.plainId = id;
}
...
}

重要说明:该错误是稳定的，但如果单独调用 GroovyFormulaScriptCompilerImpl 类的 flush 方法，而没有调用我上面提到的其他类中的 flush 方法，则不会出现该错误。

任何建议或假设将不胜感激。

Answer 1

终于解决了我的问题。万一有人遇到它，解决方案是用位置名称更改参数名称:

@CacheEvict(value="compile_cache", key="'formulaforAttribute' + #p0.getPlainId()")
public void flush(ClassifyObjectAttributePlain arg0) {

带有跟踪消息的日志确认@CacheEvict 有效:

19:39:35,121 DEBUG AnnotationCacheOperationSource:108 - Adding cacheable method 'flush' with attribute: [CacheEvictOperation[public void com.ps.service.JpaDcsDao.flush(com.ps.dmcl.plain.ClassifyTypePlain)] caches=[compile_cache] | key=''classifyType' + #p0.getPlainId()' | condition='',false,false]
19:39:35,122 DEBUG JpaDcsDao:949 - Flushing classify type id=42
19:39:35,363 TRACE CacheInterceptor:254 - Invalidating cache key classifyType42 for operation CacheEvictOperation[public void com.ps.service.JpaDcsDao.flush(com.ps.dmcl.plain.ClassifyTypePlain)] caches=[compile_cache] | key=''classifyType' + #p0.getPlainId()' | condition='',false,false on method public abstract void com.ps.service.CacheFlusher.flush(com.ps.dmcl.PlainRecord)
19:39:35,366 DEBUG AnnotationCacheOperationSource:108 - Adding cacheable method 'flush' with attribute: [CacheEvictOperation[public void com.ps.ClassifyDataCompilerImpl.flush(com.ps.dmcl.plain.ClassifyTypePlain)] caches=[compile_cache] | key=''compiledData' + #p0.getPlainId()' | condition='',false,false]
19:39:35,366 DEBUG ClassifyDataCompilerImpl:77 - Flushing compiled classify type id=42 [Subs]
19:39:35,367 TRACE CacheInterceptor:254 - Invalidating cache key compiledData42 for operation CacheEvictOperation[public void com.ps.ClassifyDataCompilerImpl.flush(com.ps.dmcl.plain.ClassifyTypePlain)] caches=[compile_cache] | key=''compiledData' + #p0.getPlainId()' | condition='',false,false on method public abstract void com.ps.service.CacheFlusher.flush(com.ps.dmcl.PlainRecord)
19:39:35,368 DEBUG AnnotationCacheOperationSource:108 - Adding cacheable method 'flush' with attribute: [CacheEvictOperation[public void com.ps.GroovyFormulaScriptCompilerImpl.flush(com.ps.dmcl.plain.ClassifyObjectAttributePlain)] caches=[compile_cache] | key=''formulaforAttribute' + #p0.getPlainId()' | condition='',false,false]
19:39:35,368 DEBUG GroovyFormulaScriptCompilerImpl:112 - Flushing formula script for attribute id=142[packDownGrade]
19:39:35,369 TRACE CacheInterceptor:254 - Invalidating cache key formulaforAttribute142 for operation CacheEvictOperation[public void com.ps.GroovyFormulaScriptCompilerImpl.flush(com.ps.dmcl.plain.ClassifyObjectAttributePlain)] caches=[compile_cache] | key=''formulaforAttribute' + #p0.getPlainId()' | condition='',false,false on method public abstract void com.ps.service.CacheFlusher.flush(com.ps.dmcl.PlainRecord)
19:39:35,369 TRACE TransactionInterceptor:473 - Completing transaction for [com.ps.controller.RuleEditorServiceImpl.updateDerivedAttribute2]
19:39:35,369 TRACE HibernateTransactionManager:923 - Triggering beforeCommit synchronization
19:39:35,369 TRACE HibernateTransactionManager:936 - Triggering beforeCompletion synchronization
19:39:35,369 DEBUG HibernateTransactionManager:753 - Initiating transaction commit

它类似于这篇文章...spel find null for valid object ，但在我的例子中，出现了调试信息，错误的发生取决于此方法是单独执行还是与其他 @CacheEvict 注释的方法一起执行。所以现在它可以工作了，但错误来源仍然不清楚。