HELP!: Repeated error messages 'Incorrect number of rows affected for updateLock'

[cheeven_tsai]

Hello,

I am setting up a few new Linux-based Alfresco CE servers, and this "Incorrect number of rows affected for updateLock" message pops up every few seconds in the server log (catalina.out).

May 28, 2015 9:56:00 AM org.alfresco.repo.transaction.RetryingTransactionHelper doInTransaction
INFO: Retrying DefaultScheduler_Worker-9: count  0; wait: 0.0s; msg: "Incorrect number of rows affected for updateLock: LockEntity[ ID=21, sharedResourceId=21, exclusiveResourceId=21]: expected 1, actual 0"; exception: (org.springframework.dao.ConcurrencyFailureException)
‍‍‍‍

The server is set up on
* CentOS Linux
* Oracle JDK 8
* Apache Tomcat 7.0.59
* MySQL 5.6
* Alfresco CE 5.0.d

I have the following in /etc/my.cnf

innodb_locks_unsafe_for_binlog = 1
transaction-isolation=READ-COMMITTED
‍‍‍‍

The server seems to work, and I can login to Share and upload files without a problem. However, the repeated error messages are making me mad because I don't know what they are and their impact to my servers.

Is there anything I need to update for Alfresco CE 5.0.d with MySQL?

Many thanks.

Cheeven Tsai

[cheeven_tsai]

Searching the error message in github, the error seems to be spawn from LockDAOImpl: https://github.com/Alfresco/community-edition/blob/master/projects/repository/source/java/org/alfres...

which indicates a link to a SQL template called "alfresco.lock.update_Lock".

Searching that name in github, I found another related file:
https://github.com/Alfresco/community-edition/blob/e0c6c4088320113db82e16ca5e3261aa321ec26d/projects...

with a SQL template such as

<update id="update_Lock" parameterType="Lock">
        update
            alf_lock
        set
            version = #{version},
            lock_token = #{lockToken},
            start_time = #{startTime},
            expiry_time = #{expiryTime}
        where
            id = #{id}
        <if test="version gt 0">
            and version = (#{version} - 1)
        </if>
    </update>
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

While I can found this SQL code appearing in my local MySQL database server, I can't understand why it does not give a reasonable update count.

I check the alf_lock table that it tries to update, it gives a response such as

mysql> select * from alf_lock;
+—-+———+——————–+——————+————+————+————-+
| id | version | shared_resource_id | excl_resource_id | lock_token | start_time | expiry_time |
+—-+———+——————–+——————+————+————+————-+
|  1 |  127331 |                  1 |                1 | not-locked |          0 |           0 |
|  2 |   63705 |                  2 |                2 | not-locked |          0 |           0 |
|  3 |      13 |                  4 |                3 | not-locked |          0 |           0 |
|  4 |      13 |                  5 |                3 | not-locked |          0 |           0 |
|  5 |      13 |                  6 |                3 | not-locked |          0 |           0 |
|  6 |      13 |                  7 |                3 | not-locked |          0 |           0 |
|  7 |      13 |                  3 |                3 | not-locked |          0 |           0 |
|  8 |      23 |                  8 |                8 | not-locked |          0 |           0 |
|  9 |   21161 |                  9 |                9 | not-locked |          0 |           0 |
| 10 |    3185 |                  4 |               10 | not-locked |          0 |           0 |
| 11 |    3185 |                  5 |               10 | not-locked |          0 |           0 |
| 12 |    3185 |                  6 |               10 | not-locked |          0 |           0 |
| 13 |    3185 |                 12 |               10 | not-locked |          0 |           0 |
| 14 |    3185 |                 14 |               10 | not-locked |          0 |           0 |
| 15 |    3185 |                 15 |               10 | not-locked |          0 |           0 |
| 16 |    3185 |                 10 |               10 | not-locked |          0 |           0 |
| 17 |    3185 |                  4 |               18 | not-locked |          0 |           0 |
| 18 |    3185 |                  5 |               18 | not-locked |          0 |           0 |
| 19 |    3185 |                  6 |               18 | not-locked |          0 |           0 |
| 20 |    3185 |                 12 |               18 | not-locked |          0 |           0 |
| 21 |    3185 |                 19 |               18 | not-locked |          0 |           0 |
| 22 |    3185 |                 20 |               18 | not-locked |          0 |           0 |
| 23 |    3185 |                 18 |               18 | not-locked |          0 |           0 |
| 24 |      29 |                 22 |               22 | not-locked |          0 |           0 |
| 25 |      19 |                 23 |               23 | not-locked |          0 |           0 |
| 26 |       9 |                 24 |               24 | not-locked |          0 |           0 |
| 27 |       9 |                 26 |               26 | not-locked |          0 |           0 |
| 28 |      19 |                 25 |               25 | not-locked |          0 |           0 |
+—-+———+——————–+——————+————+————+————-+
28 rows in set (0.00 sec)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

So I tried to check the last update time for this particular table

mysql> show table status in alfresco where name='alf_lock';
+———-+——–+———+————+——+—————-+————-+—————–+————–+———–+—————-+———————+————-+————+———–+———-+—————-+———+
| Name     | Engine | Version | Row_format | Rows | Avg_row_length | Data_length | Max_data_length | Index_length | Data_free | Auto_increment | Create_time         | Update_time | Check_time | Collation | Checksum | Create_options | Comment |
+———-+——–+———+————+——+—————-+————-+—————–+————–+———–+—————-+———————+————-+————+———–+———-+—————-+———+
| alf_lock | InnoDB |      10 | Compact    |   27 |            606 |       16384 |               0 |        32768 |         0 |             29 | 2015-05-26 09:34:32 | NULL        | NULL       | utf8_bin  |     NULL |                |         |
+———-+——–+———+————+——+—————-+————-+—————–+————–+———–+—————-+———————+————-+————+———–+———-+—————-+———+
1 row in set (0.00 sec)
‍‍‍‍‍‍‍‍‍

So this table does not seem to ever be updated before…

Still not sure why I have this error in my Alfresco server!