Recurring log entries every 15 seconds!

[ibar78]

Hi All,

Wondering if someone can help explain what the following log entry means and what I can do to stop it:

2017-03-21 14:54:30,009 INFO  [org.alfresco.repo.transaction.RetryingTransactionHelper] [DefaultScheduler_Worker-9] Retrying DefaultScheduler_Worker-9: count  0; wait: 0.0s; msg: "Incorrect number of rows affected for updateLock: LockEntity[ ID=14, sharedResourceId=13, exclusiveResourceId=13]: expected 1, actual 0"; exception: (org.springframework.dao.ConcurrencyFailureException)

We are running Alfresco v4.2.5.2 on Red Hat 6.8 (Santiago) and we're seeing this log entry being generated every 15 seconds in \var\lib\tomcat\alfresco . What does it mean and although it mentions it's informational (INFO) why does it occur with such regularity?

Any help would be greatly appreciated!

[ibar78]

I have set logging to debug mode in the hope it will provide more information to the problem. So I get the following entry every 15 seconds:

2017-03-21 16:35:15,025 DEBUG [org.alfresco.repo.transaction.RetryingTransactionHelper] [DefaultScheduler_Worker-9]
Transaction commit failed:
   Thread: DefaultScheduler_Worker-9
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@52d706d1, status=0]
   Iteration: 0
   Exception follows:
org.alfresco.repo.lock.LockAcquisitionException: 02210019 Failed to get lock '{http://www.alfresco.org/model/system/1.0}activitypostlookup' using token 'ffd181b4-5c34-4738-b8d3-1ba52663cdde'.
    at org.alfresco.repo.domain.locks.AbstractLockDAOImpl.getLock(AbstractLockDAOImpl.java:137)
    at org.alfresco.repo.lock.JobLockServiceImpl$5.execute(JobLockServiceImpl.java:466)
    at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:457)
    at org.alfresco.repo.lock.JobLockServiceImpl.doWithRetry(JobLockServiceImpl.java:518)
    at org.alfresco.repo.lock.JobLockServiceImpl.getLockImpl(JobLockServiceImpl.java:472)
    at org.alfresco.repo.lock.JobLockServiceImpl.getLock(JobLockServiceImpl.java:222)
    at org.alfresco.repo.lock.JobLockServiceImpl.getLock(JobLockServiceImpl.java:212)
    at org.alfresco.repo.activities.post.lookup.PostLookup.acquireLock(PostLookup.java:789)
    at org.alfresco.repo.activities.post.lookup.PostLookup.execute(PostLookup.java:203)
    at org.alfresco.repo.activities.post.lookup.PostLookupJob.execute(PostLookupJob.java:50)
    at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:563)
Caused by: org.springframework.dao.ConcurrencyFailureException: Incorrect number of rows affected for updateLock: LockEntity[ ID=15, sharedResourceId=14, exclusiveResourceId=14]: expected 1, actual 0
    at org.alfresco.repo.domain.locks.ibatis.LockDAOImpl.updateLock(LockDAOImpl.java:150)
    at org.alfresco.repo.domain.locks.AbstractLockDAOImpl.getLock(AbstractLockDAOImpl.java:133)
    ... 11 more

Can anyone help me explain what this means please?

[afaust]

That is a message from a scheduled job that is triggered in regular intervals. Since you are referring to an Alfresco Enterprise version you may be running Alfresco in a cluster / on multiple machines against the same database. In that case there can be instances where both servers try to run the job at the same time and only one can get the lock to ensure only one runs at the same time.

[ibar78]

That's correct we have 2 Alfresco servers running in a cluster against a Postgres database server so that makes sense. Is this normal behaviour? How do i determine what these jobs are and is it possible to change the schedule or is this something that is fixed within Alfresco and cannot be changed?

Many thanks for your help!

[afaust · Accepted solution]

Since this is a DEBUG message it is something that Alfresco already expects can happen. If you don't set the log level to DEBUG you won't even notice it is happening underneath the covers in the first place.