AnsweredAssumed Answered

Database upgrade from 4.1.10 to 5.1.1 fails

Question asked by pcharsle on Aug 21, 2016
Latest reply on Sep 23, 2016 by darkredd
We are following the instructions at http://docs.alfresco.com/5.1/tasks/upgrade-process.html to upgrade from 4.1.10 to 5.1.1. We are using AWS RDS MySQL 5.6 with tomcat7 as supported by Alfresco. We successfully install and run Alfresco 5.1.1 with all our extensions. We then do the following:

1) Stop Alfresco
2) Copy across our production contentstore
3) Copy across our 4.1.10 database
4) Tailing the logs, we can see that the database is recognised and the first upgrade patches are successfully applied

However the upgrade stops and "hangs" at the patch activiti-upgrade-5-11.sql and eventually times out. See the snippet from catalina.out below
<!–break–>

Normalized schema dumped to file /tmp/tomcat7-tmp/Alfresco/Alfresco-schema-MySQLInnoDBDialect-pre-upgrade-alf_-498310534441415069.xml.
2016-08-01 04:18:00,631  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Normalized schema dumped to file /tmp/tomcat7-tmp/Alfresco/Alfresco-schema-MySQLInnoDBDialect-pre-upgrade-jbpm_-6566384843334377561.xml.
2016-08-01 04:18:00,632  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Normalized schema dumped to file /tmp/tomcat7-tmp/Alfresco/Alfresco-schema-MySQLInnoDBDialect-pre-upgrade-act_-6400341803565615802.xml.
2016-08-01 04:18:00,696  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-1125795265852298082.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/remove-index-acl_id.sql).
2016-08-01 04:18:00,755  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-2914601116970840258.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/restructure-idx_alf_nprop_s-MSSQL.sql).
2016-08-01 04:18:00,794  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-7084032070803741293.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/migrate-locale-multilingual.sql).
2016-08-01 04:18:00,928  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-2945145454516771820.sql (Copied from classpath:alfresco/dbscripts/create/org.hibernate.dialect.MySQLInnoDBDialect/AlfrescoCreate-AuthorizationTables.sql).
2016-08-01 04:18:00,999  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-8014122370050000922.sql (Copied from classpath:alfresco/dbscripts/create/org.hibernate.dialect.MySQLInnoDBDialect/AlfrescoCreate-ContentUrlEncryptionTables.sql).
2016-08-01 04:18:01,111  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-6503919872556366086.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/activiti-upgrade-5-10.sql).
2016-08-01 04:18:06,358  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-742574778828474973.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/add-activti-index-historic-activity.sql).
2016-08-01 04:18:06,383  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-2297210573458188263.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/activiti-upgrade-5-11.sql).
2016-08-01 04:18:13,592  INFO  [domain.schema.SchemaBootstrap] [localhost-startStop-1] Executing database script /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-6241599408556461012.sql (Copied from classpath:alfresco/dbscripts/upgrade/4.2/org.hibernate.dialect.MySQLInnoDBDialect/migrate-activiti-workflows.sql).
java.net.SocketTimeoutException: Read timed out
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
   at java.net.SocketInputStream.read(SocketInputStream.java:170)
   at java.net.SocketInputStream.read(SocketInputStream.java:141)
   at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
   at sun.security.ssl.InputRecord.read


We checked the script that is failing, /tmp/tomcat7-tmp/Alfresco/AlfrescoSchema-MySQLInnoDBDialect-Update-6241599408556461012.sql. While the upgrade was "hanging" we ran the following commands in our database to find out what was causing the problem:

show open tables;

/* snippet shows that there are 2 locks on tables act_hi_detail and act_hi_varinst */
| alfresco_test | act_hi_detail | 2 | 0 |
| alfresco_test | act_hi_varinst | 2 | 0 |


show engine innodb status;

—TRANSACTION 115281, ACTIVE 2451 sec
mysql tables in use 4, locked 1
MySQL thread id 18, OS thread handle 0x2acf7ab59700, query id 2906 10.0.30.159 alfresco_test Sending data
INSERT INTO ACT_HI_VARINST(
ID_,
PROC_INST_ID_,
EXECUTION_ID_,
TASK_ID_,
NAME_,
VAR_TYPE_,
REV_,
BYTEARRAY_ID_,
DOUBLE_,
LONG_,
TEXT_,
TEXT2_
)
SELECT
(@cnt := @cnt + 1),
PROC_INST_ID_,
EXECUTION_ID_,
TASK_ID_,
NAME_,
VAR_TYPE_,
REV_,
BYTEARRAY_ID_,
DOUBLE_,
LONG_,
TEXT_,
TEXT2_
FROM ACT_HI_DETAIL AHD
CROSS JOIN (SELECT @cnt := 134601 + 1) AS dummy
WHERE AHD.PROC_INST_ID_ not in (select PROC_INST_ID_ from ACT_HI_VARINST)
AND
(AHD.PROC_INST_ID_ , AHD.NAME_, AHD.REV_, AHD.time_) IN
(SELECT
Trx read view will not see trx with id >= 115282, sees < 115282


We have configured our AWS RDS MySQL database with all MySQL settings as recommended by Alfresco. Has anyone else encountered this problem which seems to be caused by the table insert being locked because it has a select from the same table in which it is trying to insert.

Note that after the application times out, we have rebooted our database and are successfully able to run the same insert on the MySQL command line.
Note that the previous patch creates the new table ACT_HI_VARINST

Any help or ideas would be very much appreciated.

Outcomes