I have noticed that my OCS Import process using the basic connector has gotten very slow lately. When I look in the connector log I see stack traces for almost every host like:
[PC.Code: action-2013-05-23-16-01-01] New Video to insert
Interceptor
for
{http://soap.services.cmdbuild.org}PrivateService#{http://soap.services.cmdbuild.org}updateWorkflow
has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
at
org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:64)
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:255)
at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:544)
at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:341)
at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:294)
at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:73)
at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:124)
at com.sun.proxy.$Proxy48.updateWorkflow(Unknown Source)
at org.cmdbuild.externalconnector.inventory.action.Action.executeAction(Action.java:79)
at org.cmdbuild.externalconnector.xml.XMLDiff.compare(XMLDiff.java:83)
at org.cmdbuild.externalconnector.update.InventoryConnector.connect(InventoryConnector.java:172)
at org.cmdbuild.externalconnector.update.UpdateCMDBuild.main(UpdateCMDBuild.java:39)
Caused
by: java.net.SocketTimeoutException: SocketTimeoutException invoking
http://127.0.0.1:8080/cmdbuild/services/soap/Private: Read timed out
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:534)
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:2153)
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:2138)
at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:730)
at
org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)
... 11 more
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:146)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:688)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:633)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1162)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:397)
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:2270)
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:2239)
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:2082)
... 14 more
The related section in the cmdbuild.log appears to be:
INFO 2016-02-01 13:05:38 [workflow] getting process class with name 'ImportAsset'
INFO 2016-02-01 13:05:38 [workflow] getting process class with name 'ImportAsset'
INFO 2016-02-01 13:05:38 [workflow] starting process for class 'ImportAsset' with variables '{}'
INFO 2016-02-01 13:05:38 [cmdbuild] trying to login user workflow with group null
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#FlowStatus#Description'
INFO 2016-02-01 13:05:40 [workflow] synchronizing process state, activities and (maybe) variables
INFO 2016-02-01 13:05:40 [workflow] synchronizing variables
INFO 2016-02-01 13:05:40 [workflow] process is completed, delete if from workflow service
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#FlowStatus#Description'
INFO
2016-02-01 13:05:40 [workflow] pushing event
'WorkflowEvent[type=START,processDefinitionId=Process_importasset,processInstanceId=4006307_Package_importasset_Process_importasset]'
for session '55'
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#FlowStatus#Description'
INFO 2016-02-01 13:05:40 [cmdbuild] trying to login user workflow with group null
INFO
2016-02-01 13:05:40 [workflow] pushing event
'WorkflowEvent[type=UPDATE,processDefinitionId=Process_importasset,processInstanceId=4006307_Package_importasset_Process_importasset]'
for session '55'
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#F
lowStatus#Description'
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#FlowStatus#Description'
INFO
2016-02-01 13:05:40 [workflow] updating activity instance
'15948126_4006307_Package_importasset_Process_importasset_InsertModification'
for process 'ImportAsset'
WARN 2016-02-01 13:05:40 [sql ] cannot get content of column 'ImportAsset#FlowStatus#Description'
INFO
2016-02-01 13:05:40 [workflow] advancing activity instance
'15948126_4006307_Package_importasset_Process_importasset_InsertModification'
for process 'ImportAsset'
INFO 2016-02-01 13:05:40 [cmdbuild] trying to login user workflow with group null
INFO
2016-02-01 13:05:40 [workflow] pushing event
'WorkflowEvent[type=UPDATE,processDefinitionId=Process_importasset,processInstanceId=4006307_Package_importasset_Process_importasset]'
for session '62'
INFO 2016-02-01 13:05:40 [cmdbuild] trying to login user workflow with group null
INFO 2016-02-01 13:05:40 [cmdbuild] getting all-in-one 'interface org.cmdbuild.services.event.Observer'
INFO 2016-02-01 13:05:40 [cmdbuild] getting all-in-one 'interface org.cmdbuild.services.event.Observer'
INFO 2016-02-01 13:05:40 [cmdbuild] getting all-in-one 'interface org.cmdbuild.services.event.Observer'
ERROR 2016-02-01 13:05:40 [cmdbuild] card should be locked
org.cmdbuild.logic.data.access.lock.LockManager$ExpectedLocked: should be locked
at org.cmdbuild.logic.data.access.lock.DefaultLockManager.checkLockedByUser(DefaultLockManager.java:119)
at org.cmdbuild.logic.data.access.lock.ForwardingLockManager.checkLockedByUser(ForwardingLockManager.java:39)
at org.cmdbuild.logic.data.DefaultLockLogic.checkCardLockedbyUser(DefaultLockLogic.java:66)
at org.cmdbuild.logic.data.ForwardingLockLogic.checkCardLockedbyUser(ForwardingLockLogic.java:33)
at org.cmdbuild.logic.data.access.DefaultDataAccessLogic.updateCard(DefaultDataAccessLogic.java:703)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.updateCard(ConnectorJob.java:386)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.update(ConnectorJob.java:199)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.run(ConnectorJob.java:115)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
ERROR 2016-02-01 13:05:40 [soap ] ExternalSync - exception raised while updating card [id:27391830 classname: PC]
org.cmdbuild.exception.ConsistencyException: LOCKED_MISSING
at org.cmdbuild.exception.ConsistencyException$ConsistencyExceptionType.createException(ConsistencyException.java:31)
at org.cmdbuild.logic.data.DefaultLockLogic.forward(DefaultLockLogic.java:131)
at org.cmdbuild.logic.data.DefaultLockLogic.checkCardLockedbyUser(DefaultLockLogic.java:69)
at org.cmdbuild.logic.data.ForwardingLockLogic.checkCardLockedbyUser(ForwardingLockLogic.java:33)
at org.cmdbuild.logic.data.access.DefaultDataAccessLogic.updateCard(DefaultDataAccessLogic.java:703)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.updateCard(ConnectorJob.java:386)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.update(ConnectorJob.java:199)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.run(ConnectorJob.java:115)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
ERROR 2016-02-01 13:05:40 [soap ] ExternalSync - exception raised while updating card [id:27391830 classname: PC]
org.cmdbuild.exception.ConsistencyException: LOCKED_MISSING
at org.cmdbuild.exception.ConsistencyException$ConsistencyExceptionType.createException(ConsistencyException.java:31)
at org.cmdbuild.logic.data.DefaultLockLogic.forward(DefaultLockLogic.java:131)
at org.cmdbuild.logic.data.DefaultLockLogic.checkCardLockedbyUser(DefaultLockLogic.java:69)
at org.cmdbuild.logic.data.ForwardingLockLogic.checkCardLockedbyUser(ForwardingLockLogic.java:33)
at org.cmdbuild.logic.data.access.DefaultDataAccessLogic.updateCard(DefaultDataAccessLogic.java:703)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.updateCard(ConnectorJob.java:386)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.update(ConnectorJob.java:199)
at org.cmdbuild.services.soap.syncscheduler.ConnectorJob.run(ConnectorJob.java:115)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Any idea what lock it is looking for and why it wouldn't be occurring? This was working fine at one point, now my sync appears to be not updating existing devices. For example, I added an attribute for the OCS Inventory DB ID (so we can use the SOAP interface to get information out of OCS), but that has yet to show up for single device in the CMDB. I see the "card should be locked" for every device and it is taking over a minute for each device while tailing cmdbuild.log sits at "processing events for session".