CmisStorageException on cmis checkin

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

[jpotts]

I am wary of using a version of OpenCMIS that is newer than what Alfresco ships with. In your case, 5.0.d ships with OpenCMIS 0.11.

Do you see this problem when using 0.11?

Also, can you post the source of your getContentStream method?

[marcolf]

Jeff Potts ha scritto:

I am wary of using a version of OpenCMIS that is newer than what Alfresco ships with. In your case, 5.0.d ships with OpenCMIS 0.11.

Do you see this problem when using 0.11?

Also, can you post the source of your getContentStream method?

Hi Jeff,

thank you for reply.

First I tried with OpenCMIS 0.13 with the same results. I will try with 0.11 and I'll let you know.

The source code of getContentStream method is:

    public static ContentStream getContentStream(Session session, String fileName, byte[] content) {

        // get mime-type
        String mimeType = MimeTypes.getMIMEType(fileName);

        // create content stream
        ByteArrayInputStream stream = new ByteArrayInputStream(content);
        ContentStream contentStream = session.getObjectFactory().createContentStream(fileName, content.length, mimeType, stream);
        return contentStream;

    }

I checked in debug and all parameters of session.getObjectFactory().createContentStream(...) are correctly filled.

If I insert a (little 500ms) waiting time between checkout and checkin the problem does not occur.

If I insert a loop that retry n times the checkin, the second time it works properly.

Thank you very much,

Marco.