3

I’m fighting with the error about a week without any result. I have a legacy Spring application which was upgraded to Spring 3.2.11.RELEASE and Hibernate 4.2.15.Final. There is a class containing Spring cache annotated methods:

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() + "]");
    }
}

At some moment an application event is generated which causes listeners to invoke flush() method declared in several classes including the instance of GroovyFormulaScriptCompilerImpl class. The flush method is definitely called as I see the logger.debug output in the log file (see below, at time 19:39:01,149) but evicting an item from the cache which must occur after returning from the method fails due to error: "org.springframework.expression.spel.SpelEvaluationException: EL1011E:(pos 30): Method call: Attempted to call method getPlainId() on null context object". This results in rolling back a database transaction. Below is an extraction from the log file (I shortened hibernate trace messages):

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)
...

What I cannot understand is why an argument arg0 is available inside the flush method but become unavailable in the SpEL context a moment later.

Below is the declaration of getPlainId() method inside the ClassifyObjectAttributePlain class (it contains some Hibernate caching annotations but the 2nd level cache is globally turned off):

@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;
}
...
}

An important note: the error is stable but it does not occur if the flush method of the GroovyFormulaScriptCompilerImpl class is called alone, without calling the flush methods in other classes I mentioned above.

Any advice or assumption will be appreciated.

GodVic
  • 73
  • 1
  • 8

2 Answers2

4

Finally I've solved my problem. In case somebody faces it, the solution was to change argument names with positional ones:

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

Log with trace messages confirms that @CacheEvict works:

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

It resembles this post ...spel find null for valid object, but in my case debugging information was presented, and the error occurs depending on whether this method was executed alone or accompanied with other @CacheEvict annotated methods. So now it works but the error origin is still not clear.

Community
  • 1
  • 1
GodVic
  • 73
  • 1
  • 8
0

"On Java runtimes before version 8, that effectively cannot work as you expect it due to a limitation in the JLS that defines that for abstract types, parameter names are not retained during combination. That's why the parameter name lookup fails here.

You basically have two options:

Use Java 8 and enable the -parameters flag when compiling. Use positional parameter bindings in your SpEL-expression as documented in the Spring reference documentation."

source: https://jira.spring.io/browse/DATAJPA-598

Nikolay Kozlov
  • 1
  • 1