@Cacheevict 有时会在上下文中丢失一个对象 (EL1011E)答案

【问题标题】：@Cacheevict sometimes missing an object in the context (EL1011E)@Cacheevict 有时会在上下文中丢失一个对象 (EL1011E)
【发布时间】：2015-05-11 16:49:42
【问题描述】：

我正在与错误作斗争大约一个星期，但没有任何结果。我有一个旧版 Spring 应用程序，它已升级到 Spring 3.2.11.RELEASE 和 Hibernate 4.2.15.Final。有一个类包含 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 类的实例。当我在日志文件中看到 logger.debug 输出时，肯定会调用 flush 方法（见下文，时间为 19:39:01,149），但是从缓存中逐出一个必须在从该方法返回后发生的项目由于错误而失败： “org.springframework.expression.spel.SpelEvaluationException: EL1011E:(pos 30): Method call: Attempted to call method getPlainId() on null context object”。这会导致回滚数据库事务。以下是日志文件的摘录（我缩短了休眠跟踪消息）：

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 方法，则不会发生错误。

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

【问题讨论】：

标签： java spring caching spring-el

【解决方案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 注释方法一起执行。所以现在它可以工作了，但错误来源仍然不清楚。

【讨论】：

【解决方案2】：

“在版本 8 之前的 Java 运行时上，由于 JLS 中定义抽象类型的限制，在组合过程中不保留参数名称，这实际上无法按预期工作。这就是参数名称查找在此处失败的原因。

你基本上有两种选择：

使用 Java 8 并在编译时启用 -parameters 标志。如 Spring 参考文档中所述，在 SpEL 表达式中使用位置参数绑定。"

来源：https://jira.spring.io/browse/DATAJPA-598

【讨论】：