LDAP-AD Sync Thread not finishing

[cesarista]

I got this problem when syncing users and groups from AD.
The differential sync is not working cause there exist a running thread (that is not finishing properly) - It appears in fact in 4.2 admin console Sync IN_PROGRESS (but not progressing)

From the catalina.out I can see this:

<pre>
2014-05-30 00:00:00,023  DEBUG [security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-1]
Running a differential sync.
2014-05-30 00:00:00,024  DEBUG [security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-1]
deletions are allowed
2014-05-30 00:00:00,051  WARN  [security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-1]
User registry synchronization already running in another thread. Synchronize aborted
<pre>

Some questions:
- How many time does this type of thread live ?
- Is there any way of killing (safely) the old thread for executing a new differential sync from JMX ? Is it possible from the command line ?
- Does a service restart solve the problem ?
- Any idea ?

I am using Alfresco 4.2.1.

Thanks in advance.

–C.

[mrogers]

It should not be a problem.   Do you actually have a problem here?      I'd concentrate upon the instance of sync that is running and try to determine what's happening.

No there's no way to "kill" a differential sync.  It should not be neccessary.

[cesarista]

Thanks for the feedback mrogers:

Agree, i understand it shouldn't, but the backend sync process is RUNNING (?) from two days ago, and no more syncs are done while running. So new AD users are not being synced.
I checked with jconsole, jvisualvm and jstack the corresponding threads for finding more information.

I read some answers about restarting service (but it is a production env), and to clean locks from alf_locks, alf_locks_resource (it seems unsafe, i am not administering database).

Regards.

–C.

[mrogers]

You don't need to clean locks.   Just bounce the server that the sync is running on.    I realise that's not ideal.   
You should be able to get some information from the jstack.   Are there any errors in the logs?

In addition please contact alfresco support who may help to diagnose what's going wrong.  

[cesarista]

It seems related with JDBC connection:

<blockcode>
"DefaultScheduler_Worker-4" prio=10 tid=0x00007f7e65f81800 nid=0x7991 runnable [0x00007f7e574f3000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:150)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at java.io.DataInputStream.readFully(DataInputStream.java:195)
        at java.io.DataInputStream.readFully(DataInputStream.java:169)
        at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:846)
        at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:727)
        - locked <0x00000007558cf218> (a java.util.ArrayList)
        at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
        at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
        at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
        at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3932)
        at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
        - locked <0x0000000755c484a0> (a net.sourceforge.jtds.jdbc.TdsCore)
        at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(JtdsStatement.java:537)
        at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.execute(JtdsPreparedStatement.java:558)
        - locked <0x00000007558cec50> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
        at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:22)
        at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:51)
        at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:29)
        at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:87)
        at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:46)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:118)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.delete(DefaultSqlSession.java:131)
        at sun.reflect.GeneratedMethodAccessor382.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:338)
        at com.sun.proxy.$Proxy10.delete(Unknown Source)
        at org.mybatis.spring.SqlSessionTemplate.delete(SqlSessionTemplate.java:259)
        at org.alfresco.repo.domain.propval.ibatis.PropertyValueDAOImpl.deletePropertyRoot(PropertyValueDAOImpl.java:526)
        at org.alfresco.repo.domain.propval.AbstractPropertyValueDAOImpl$PropertyCallbackDAO.deleteByKey(AbstractPropertyValueDAOImpl.java:928)
        at org.alfresco.repo.domain.propval.AbstractPropertyValueDAOImpl$PropertyCallbackDAO.deleteByKey(AbstractPropertyValueDAOImpl.java:863)
        at org.alfresco.repo.cache.lookup.EntityLookupCache.deleteByKey(EntityLookupCache.java:641)
        at org.alfresco.repo.domain.propval.AbstractPropertyValueDAOImpl.deleteProperty(AbstractPropertyValueDAOImpl.java:857)
        at org.alfresco.repo.domain.propval.AbstractPropertyValueDAOImpl.updatePropertyUniqueContext(AbstractPropertyValueDAOImpl.java:1411)
        at org.alfresco.repo.attributes.AttributeServiceImpl.setAttribute(AttributeServiceImpl.java:183)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer$12.execute(ChainingUserRegistrySynchronizer.java:2230)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer$12.execute(ChainingUserRegistrySynchronizer.java:2221)
        at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:450)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.notifySyncDirectoryStart(ChainingUserRegistrySynchronizer.java:2220)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.syncWithPlugin(ChainingUserRegistrySynchronizer.java:933)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronizeInternal(ChainingUserRegistrySynchronizer.java:713)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronize(ChainingUserRegistrySynchronizer.java:436)
        at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob$1.doWork(UserRegistrySynchronizerJob.java:51)
        at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
        at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob.execute(UserRegistrySynchronizerJob.java:47)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:563)
<blockcode>

[cesarista]

What it seem to happen, is that during sync we lost connectivity (or "something") with the database.

"DefaultScheduler_Worker-4" prio=10 tid=0x00007f7e65f81800 nid=0x7991 runnable [0x00007f7e574f3000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:150)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at java.io.DataInputStream.readFully(DataInputStream.java:195)
        at java.io.DataInputStream.readFully(DataInputStream.java:169)
…
- locked <0x00000007558cf218> (a java.util.ArrayList)
        at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
        at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
        at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
        at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3932)
        at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
        - locked <0x0000000755c484a0> (a net.sourceforge.jtds.jdbc.TdsCore)
        at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(JtdsStatement.java:537)
        at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.execute(JtdsPreparedStatement.java:558)
        - locked <0x00000007558cec50> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
…
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronizeInternal(ChainingUserRegistrySynchronizer.java:713)
        at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronize(ChainingUserRegistrySynchronizer.java:436)
        at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob$1.doWork(UserRegistrySynchronizerJob.java:51)
        at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
        at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob.execute(UserRegistrySynchronizerJob.java:47)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:563)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I'll try restarting.

–C.

[mpeters]

Hi,

we experience the same situation, sync is IN_PROGRESS, but never ends. With 24/7 availibility this means, that Alfresco never gets any new users or user changes. Restarting the repo tomcat does help once until next restart. We use MS SQL Server 2012 and driver com.microsoft.sqlserver.jdbc.SQLServerDriver.

Could you solve this nasty problem?

Kind regards
Markus

[mrogers]

Please contact Alfresco support who will need some more information.