AnsweredAssumed Answered

CmisStorageException on cmis checkin

Question asked by marcolf on Nov 11, 2016
Latest reply on Nov 22, 2016 by marcolf

Hi,

i have a big problem with cmis checkin.

I use Alfresco 5.0.d with Apache OpenCmis 1.0.0 (previous 0.13.0) and AtomPub implementation.

My client side code is:

 

Document doc = null;
Document pwc = null;
ContentStream contentStream = null;
try {
// refresh object
//document.refresh();

// document checkout
log.info("try to check-out document..");
ObjectId idOfCheckedOutDocument = document.checkOut();
log.info("successfully check-out document!");
// get private working copy of document
pwc = (Document) session.getObject(idOfCheckedOutDocument);

// create the content stream
contentStream = getContentStream(session, fileName, content);

log.info(String.format("Content Stream value -> %s", contentStream.getStream()));
log.info(String.format("Content Stream value -> %s", contentStream.getLength()));

// document checkin
log.info("try to check-in document");
//pwc.refresh(); // refresh the pwc object
ObjectId objectId = pwc.checkIn(majorFlag, additionalProperties, contentStream, null);
log.info("successfully check-in document");

// get & refresh object
doc = (Document) session.getObject(objectId);
doc.refresh();
log.info("Document Version label is now:" + doc.getVersionLabel());

}catch(CmisBaseException cbe) {
log.error(cbe.getMessage(), cbe);
if(pwc!=null){
log.info("try to cancel the checkout on private working copy");
pwc.cancelCheckOut();
log.info("cancel checkout successfully completed");
}
throw cbe;

}finally {
if (contentStream != null) {
IOUtils.closeQuietly(contentStream);
}
}

I'm sure the stream is properly loaded.

I randomly get this exception on client side:

 

org.apache.chemistry.opencmis.commons.exceptions.CmisStorageException: Expected 2780 bytes but retrieved 0 bytes!
at org.apache.chemistry.opencmis.client.bindings.spi.atompub.AbstractAtomPubService.convertStatusCode(AbstractAtomPubService.java:521) ~[chemistry-opencmis-client-bindings-1.0.0.jar:1.0.0]
at org.apache.chemistry.opencmis.client.bindings.spi.atompub.AbstractAtomPubService.put(AbstractAtomPubService.java:750) ~[chemistry-opencmis-client-bindings-1.0.0.jar:1.0.0]
at org.apache.chemistry.opencmis.client.bindings.spi.atompub.AbstractAtomPubService.put(AbstractAtomPubService.java:737) ~[chemistry-opencmis-client-bindings-1.0.0.jar:1.0.0]
at org.apache.chemistry.opencmis.client.bindings.spi.atompub.VersioningServiceImpl.checkIn(VersioningServiceImpl.java:215) ~[chemistry-opencmis-client-bindings-1.0.0.jar:1.0.0]
at org.apache.chemistry.opencmis.client.runtime.DocumentImpl.checkIn(DocumentImpl.java:322) ~[chemistry-opencmis-client-impl-1.0.0.jar:1.0.0]
at org.apache.chemistry.opencmis.client.runtime.DocumentImpl.checkIn(DocumentImpl.java:624) ~[chemistry-opencmis-client-impl-1.0.0.jar:1.0.0]

 

While Server side exception, on Alfresco (debug level) log, is:

2016-11-11 13:39:16,778 DEBUG [server.shared.Dispatcher] [http-apr-8080-exec-6] -default- / entry, PUT -> org.apache.chemistry.opencmis.server.impl.atompub.ObjectService$UpdateProperties
2016-11-11 13:39:16,780 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Created system temporary directory: /storage/alfresco-5.0.d/tomcat/temp
2016-11-11 13:39:16,780 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Creating tmp file: /storage/alfresco-5.0.d/tomcat/temp/Alfresco/cmis3549815024799568990content
2016-11-11 13:39:16,970 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Created system temporary directory: /storage/alfresco-5.0.d/tomcat/temp
2016-11-11 13:39:16,970 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Creating tmp file: /storage/alfresco-5.0.d/tomcat/temp/Alfresco/cmis3338959984438601081content
2016-11-11 13:39:16,971 DEBUG [alfresco.opencmis.AlfrescoCmisServiceInterceptor] [http-apr-8080-exec-6]
CMIS invocation:
Method: checkIn
Arguments:
-default-
Holder(67730bc4-fab0-4ad7-bb69-bbeba48baa24;pwc)
true
Properties Data [properties=[Property [id=ara:riservato, display Name=null, local name=null, query name=null, values=[false]][extensions=null], Property [id=ara:codiceAOO-protocollo, display Name=null, local name=null, query name=null, values=[aoo_test_2]][extensions=null], Property [id=ara:tipo-protocollo, display Name=null, local name=null, query name=null, values=[Entrata]][extensions=null], Property [id=ara:stato, display Name=null, local name=null, query name=null, values=[1]][extensions=null], Property [id=ara:utente-creatore, display Name=null, local name=null, query name=null, values=[provarest]][extensions=null], Property [id=ara:urgente, display Name=null, local name=null, query name=null, values=[false]][extensions=null], Property [id=ara:numero-protocollo, display Name=null, local name=null, query name=null, values=[1757]][extensions=null], Property [id=ara:data-ricezione, display Name=null, local name=null, query name=null, values=[java.util.GregorianCalendar[time=?,areFieldsSet=false,areAllFieldsSet=false,lenient=true,zone=sun.util.calendar.ZoneInfo[id="GMT+02:00",offset=7200000,dstSavings=0,useDaylight=false,transitions=0,lastRule=null],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=?,YEAR=2016,MONTH=9,WEEK_OF_YEAR=?,WEEK_OF_MONTH=?,DAY_OF_MONTH=18,DAY_OF_YEAR=?,DAY_OF_WEEK=?,DAY_OF_WEEK_IN_MONTH=?,AM_PM=?,HOUR=?,HOUR_OF_DAY=0,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=?,DST_OFFSET=?]]][extensions=null], Property [id=ara:codiceUfficio-protocollo, display Name=null, local name=null, query name=null, values=[furtrica]][extensions=null], Property [id=ara:barcode, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=cm:description, display Name=null, local name=null, query name=null, values=[sodhiyfy.pdf]][extensions=null], Property [id=ara:utente-modificatore, display Name=null, local name=null, query name=null, values=[provarest]][extensions=null], Property [id=ara:in-risposta-a-numero-protocollo, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=ara:note, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=ara:mittente-esterno, display Name=null, local name=null, query name=null, values=[Giancarlo Prova]][extensions=null], Property [id=ara:info-procedimento, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=cm:title, display Name=null, local name=null, query name=null, values=[sodhiyfy.pdf]][extensions=null], Property [id=ara:numero-protocollo-emergenza, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=ara:codice-registro-protocollo, display Name=null, local name=null, query name=null, values=[aaaa]][extensions=null], Property [id=ara:spedito, display Name=null, local name=null, query name=null, values=[false]][extensions=null], Property [id=ara:anno-protocollo, display Name=null, local name=null, query name=null, values=[2016]][extensions=null], Property [id=ara:codiceEnte-protocollo, display Name=null, local name=null, query name=null, values=[entetest]][extensions=null], Property [id=ara:hash, display Name=null, local name=null, query name=null, values=[]][extensions=null], Property [id=ara:data-protocollo, display Name=null, local name=null, query name=null, values=[java.util.GregorianCalendar[time=?,areFieldsSet=false,areAllFieldsSet=false,lenient=true,zone=sun.util.calendar.ZoneInfo[id="GMT+01:00",offset=3600000,dstSavings=0,useDaylight=false,transitions=0,lastRule=null],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=?,YEAR=2016,MONTH=10,WEEK_OF_YEAR=?,WEEK_OF_MONTH=?,DAY_OF_MONTH=11,DAY_OF_YEAR=?,DAY_OF_WEEK=?,DAY_OF_WEEK_IN_MONTH=?,AM_PM=?,HOUR=?,HOUR_OF_DAY=13,MINUTE=39,SECOND=15,MILLISECOND=542,ZONE_OFFSET=?,DST_OFFSET=?]]][extensions=null]]][extensions=null]
ContentStream [filename=sodhiyfy.pdf, length=2780, MIME type=application/pdf, has stream=true][extensions=null]
null
null
null
null
null
Pre-call authentication:
Full auth: admin
Effective auth: admin
In-call authentication:
Full auth: admin
Effective auth: admin
Post-call authentication:
Full auth: admin
Effective auth: admin
Throwing: Expected 2780 bytes but retrieved 0 bytes!
org.apache.chemistry.opencmis.commons.exceptions.CmisStorageException: Expected 2780 bytes but retrieved 0 bytes!
at org.alfresco.opencmis.AlfrescoCmisServiceImpl.copyToTempFile(AlfrescoCmisServiceImpl.java:2947)
at org.alfresco.opencmis.AlfrescoCmisServiceImpl.checkIn(AlfrescoCmisServiceImpl.java:2158)
at sun.reflect.GeneratedMethodAccessor814.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.alfresco.repo.transaction.RetryingTransactionInterceptor$1.execute(RetryingTransactionInterceptor.java:79)
at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:457)
at org.alfresco.repo.transaction.RetryingTransactionInterceptor.invoke(RetryingTransactionInterceptor.java:69)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.alfresco.opencmis.AlfrescoCmisStreamInterceptor.invoke(AlfrescoCmisStreamInterceptor.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.alfresco.opencmis.AlfrescoCmisServiceInterceptor.invoke(AlfrescoCmisServiceInterceptor.java:101)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.alfresco.opencmis.AlfrescoCmisExceptionInterceptor.invoke(AlfrescoCmisExceptionInterceptor.java:83)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy332.checkIn(Unknown Source)
at org.apache.chemistry.opencmis.server.support.wrapper.ConformanceCmisServiceWrapper.checkIn(ConformanceCmisServiceWrapper.java:1058)
at org.apache.chemistry.opencmis.server.impl.atompub.ObjectService$UpdateProperties.serve(ObjectService.java:579)
at org.apache.chemistry.opencmis.server.shared.Dispatcher.dispatch(Dispatcher.java:91)
at org.apache.chemistry.opencmis.server.impl.atompub.CmisAtomPubServlet.dispatch(CmisAtomPubServlet.java:226)
at org.apache.chemistry.opencmis.server.impl.atompub.CmisAtomPubServlet.service(CmisAtomPubServlet.java:173)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at org.alfresco.opencmis.CMISServletDispatcher.execute(CMISServletDispatcher.java:188)
at org.alfresco.opencmis.CMISWebScript.execute(CMISWebScript.java:51)
at org.alfresco.repo.web.scripts.RepositoryContainer.transactionedExecute(RepositoryContainer.java:437)
at org.alfresco.rest.api.PublicApiRepositoryContainer.transactionedExecute(PublicApiRepositoryContainer.java:45)
at org.alfresco.repo.web.scripts.RepositoryContainer.transactionedExecuteAs(RepositoryContainer.java:619)
at org.alfresco.repo.web.scripts.RepositoryContainer.executeScriptInternal(RepositoryContainer.java:399)
at org.alfresco.repo.web.scripts.RepositoryContainer.executeScript(RepositoryContainer.java:280)
at org.alfresco.rest.api.PublicApiRepositoryContainer.access$001(PublicApiRepositoryContainer.java:26)
at org.alfresco.rest.api.PublicApiRepositoryContainer$1.doWork(PublicApiRepositoryContainer.java:81)
at org.alfresco.repo.tenant.TenantUtil.runAsWork(TenantUtil.java:119)
at org.alfresco.repo.tenant.TenantUtil.runAsTenant(TenantUtil.java:88)
at org.alfresco.rest.api.PublicApiRepositoryContainer.executeScript(PublicApiRepositoryContainer.java:77)
at org.springframework.extensions.webscripts.AbstractRuntime.executeScript(AbstractRuntime.java:378)
at org.springframework.extensions.webscripts.AbstractRuntime.executeScript(AbstractRuntime.java:209)
at org.alfresco.repo.web.scripts.TenantWebScriptServlet.service(TenantWebScriptServlet.java:74)
at org.alfresco.rest.api.PublicApiWebScriptServlet.service(PublicApiWebScriptServlet.java:53)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.alfresco.repo.web.filter.beans.NullFilter.doFilter(NullFilter.java:68)
at sun.reflect.GeneratedMethodAccessor562.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.alfresco.repo.management.subsystems.ChainingSubsystemProxyFactory$1.invoke(ChainingSubsystemProxyFactory.java:125)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy268.doFilter(Unknown Source)
at org.alfresco.repo.web.filter.beans.BeanProxyFilter.doFilter(BeanProxyFilter.java:82)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.alfresco.web.app.servlet.GlobalLocalizationFilter.doFilter(GlobalLocalizationFilter.java:61)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2466)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2455)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

As you can see, after the dispatcher calling, the "Creating tmp file" is called twice:

2016-11-11 13:39:16,778 DEBUG [server.shared.Dispatcher] [http-apr-8080-exec-6] -default- / entry, PUT -> org.apache.chemistry.opencmis.server.impl.atompub.ObjectService$UpdateProperties
2016-11-11 13:39:16,780 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Created system temporary directory: /storage/alfresco-5.0.d/tomcat/temp
2016-11-11 13:39:16,780 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Creating tmp file: /storage/alfresco-5.0.d/tomcat/temp/Alfresco/cmis3549815024799568990content
2016-11-11 13:39:16,970 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Created system temporary directory: /storage/alfresco-5.0.d/tomcat/temp
2016-11-11 13:39:16,970 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-6] Creating tmp file: /storage/alfresco-5.0.d/tomcat/temp/Alfresco/cmis3338959984438601081content

the first time the file is created correctly, however the second time its size is 0 bytes!!!

I guess because the stream has already been read and consumed..

 

This happens randomly. 

When the checkin works, I see only one call for creation of temporary file:

2016-11-11 13:35:33,398 DEBUG [server.shared.Dispatcher] [http-apr-8080-exec-2] -default- / entry, PUT -> org.apache.chemistry.opencmis.server.impl.atompub.ObjectService$UpdateProperties
2016-11-11 13:35:33,399 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-2] Created system temporary directory: /storage/alfresco-5.0.d/tomcat/temp
2016-11-11 13:35:33,400 DEBUG [alfresco.util.TempFileProvider] [http-apr-8080-exec-2] Creating tmp file: /storage/alfresco-5.0.d/tomcat/temp/Alfresco/cmis3970331843228445713content
2016-11-11 13:35:33,470 DEBUG [alfresco.opencmis.AlfrescoCmisServiceInterceptor] [http-apr-8080-exec-2]
CMIS invocation:
Method: checkIn
Arguments:
-default-
Holder(b8728a2d-020d-4d41-882d-17d4044260f8;pwc)
true
Properties Data [properties=[]][extensions=null]
ContentStream [filename=Segnatura.xml, length=3853, MIME type=application/xml, has stream=true][extensions=null]
null
null
null
null
null
Pre-call authentication:
Full auth: admin
Effective auth: admin
In-call authentication:
Full auth: admin
Effective auth: admin
Post-call authentication:
Full auth: admin
Effective auth: admin
Returning: null

 

Can you help me? 

Is a bug?

Thank you very much.

Outcomes