[RTFACT-15508] Database conversion during update fails Created: 21/Dec/17  Updated: 13/Apr/20

Status: Open
Project: Artifactory Binary Repository
Component/s: Artifact Storage, Database
Affects Version/s: 5.7.0, 5.8.0, 5.8.1
Fix Version/s: None

Type: Bug Priority: Minor
Reporter: Volker Fuessler Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: artifactory
Environment:
java -version
java version "1.8.0_152"
Java(TM) SE Runtime Environment (build 1.8.0_152-b16)
Java HotSpot(TM) 64-Bit Server VM (build 25.152-b16, mixed mode)

MySQL 5.5.58-0+deb8u1
Debian Jessie

Machine has 16 cores and 32GB RAM


 Description   

After updating Artifactory Pro (Debian Version) from 5.6.3 to 5.7.0, it is not able to start due to an error with the database conversion.

I get the following error in artifactory.log:

2017-12-21 08:42:34,131 [art-init] [INFO ] (o.a.s.ArtifactorySchedulerFactoryBean:647) - Starting Quartz Scheduler now
2017-12-21 08:42:34,222 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:231) - Artifactory context starting up 49 Spring Beans...
2017-12-21 08:42:34,237 [art-init] [INFO ] (o.a.s.d.v.ArtifactoryDBVersion:98) - Starting database conversion from v563 to v570
2017-12-21 08:42:34,238 [art-init] [INFO ] (o.a.s.d.v.c.DbSqlConverterUtil:30) - Starting schema conversion: /conversion/mysql/mysql_v570.sql
2017-12-21 08:42:47,936 [art-init] [INFO ] (o.a.w.s.ArtifactoryContextConfigListener:282) -
                _   _  __           _                     _____
     /\        | | (_)/ _|         | |                   |  __ \
    /  \   _ __| |_ _| |_ __ _  ___| |_ ___  _ __ _   _  | |__) | __ ___
   / /\ \ | '__| __| |  _/ _` |/ __| __/ _ \| '__| | | | |  ___/ '__/ _ \
  / ____ \| |  | |_| | || (_| | (__| || (_) | |  | |_| | | |   | | | (_) |
 /_/    \_\_|   \__|_|_| \__,_|\___|\__\___/|_|   \__, | |_|   |_|  \___/
 Version:  5.7.0                                   __/ |
 Revision: 50700900                               |___/
 Artifactory Home: '/var/opt/jfrog/artifactory'

2017-12-21 08:42:48,085 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:480) - Artifactory application context set to NOT READY by refresh
2017-12-21 08:42:48,085 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:224) - Refreshing artifactory: startup date [Thu Dec 21 08:42:48 UTC 2017]; root of context hierarchy
2017-12-21 08:42:53,059 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:216) - Database: MySQL 5.5.58-0+deb8u1. Driver: MySQL Connector Java mysql-connector-java-5.1.42 ( Revision: 1f61b0b0270d9844b006572ba4e77f19c0f230d4 ) Pool: mysql
2017-12-21 08:42:53,060 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:219) - Connection URL: jdbc:mysql://localhost:3306/artdb?characterEncoding=UTF-8&elideSetAutoCommits=true
2017-12-21 08:42:53,616 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'blob' from jar:file:/opt/jfrog/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/artifactory-storage-db-5.7.0.jar!/
2017-12-21 08:42:53,662 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'eventual, eventual-cluster, google-storage, hdfs, s3Old, s3, sharding, sharding-cluster, state-aware, azure-blob-storage' from jar:file:/opt/jfrog/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/artifactory-addon-filestore-5.7.0.jar!/
2017-12-21 08:42:53,668 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'empty, external-file, external-wrapper, file-system, cache-fs, retry' from jar:file:/opt/jfrog/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/binary-store-core-2.0.24.jar!/
2017-12-21 08:42:53,671 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'remote' from jar:file:/opt/jfrog/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/binary-store-client-2.0.24.jar!/
2017-12-21 08:42:57,749 [art-init] [INFO ] (o.a.s.ArtifactorySchedulerFactoryBean:647) - Starting Quartz Scheduler now
2017-12-21 08:42:57,848 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:231) - Artifactory context starting up 49 Spring Beans...
2017-12-21 08:42:57,869 [art-init] [INFO ] (o.a.s.d.v.ArtifactoryDBVersion:98) - Starting database conversion from v563 to v570
2017-12-21 08:42:57,870 [art-init] [INFO ] (o.a.s.d.v.c.DbSqlConverterUtil:30) - Starting schema conversion: /conversion/mysql/mysql_v570.sql
2017-12-21 08:42:57,871 [art-init] [ERROR] (o.j.s.u.DbStatementUtils:56) - Failed to execute query: Duplicate key name 'node_props_node_prop_value_idx':
CREATE INDEX node_props_node_prop_value_idx ON node_props(node_id, prop_key, prop_value(255))
2017-12-21 08:42:57,877 [art-init] [ERROR] (o.a.s.d.v.c.DbSqlConverterUtil:35) - Could not convert DB using v570 converter due to Duplicate key name 'node_props_node_prop_value_idx'
com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Duplicate key name 'node_props_node_prop_value_idx'
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.8.0_152]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [na:1.8.0_152]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.8.0_152]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) [na:1.8.0_152]
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:425) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.Util.getInstance(Util.java:408) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:943) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeUpdateInternal(StatementImpl.java:1552) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeLargeUpdate(StatementImpl.java:2607) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1480) ~[mysql-connector-java.jar:5.1.42]
        at org.jfrog.storage.util.DbStatementUtils.executeSqlStream(DbStatementUtils.java:51) ~[jfrog-db-infra-1.3.8.jar:na]
        at org.artifactory.storage.db.version.converter.DbSqlConverterUtil.convert(DbSqlConverterUtil.java:31) ~[artifactory-common-5.7.0.jar:na]
        at org.artifactory.storage.db.version.converter.DBSqlConverter.convert(DBSqlConverter.java:49) [artifactory-storage-db-5.7.0.jar:na]
        at org.artifactory.storage.db.version.ArtifactoryDBVersion.convert(ArtifactoryDBVersion.java:100) [artifactory-storage-db-5.7.0.jar:na]
        at org.artifactory.storage.db.DbServiceImpl.convert(DbServiceImpl.java:287) [artifactory-storage-db-5.7.0.jar:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_152]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_152]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_152]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_152]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) [spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:201) [spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at com.sun.proxy.$Proxy152.convert(Unknown Source) [na:na]
        at org.artifactory.converter.ConvertersManagerImpl.serviceConvert(ConvertersManagerImpl.java:167) [artifactory-common-5.7.0.jar:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.refresh(ArtifactoryApplicationContext.java:237) [artifactory-core-5.7.0.jar:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.<init>(ArtifactoryApplicationContext.java:124) [artifactory-core-5.7.0.jar:na]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.8.0_152]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [na:1.8.0_152]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.8.0_152]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) [na:1.8.0_152]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.configure(ArtifactoryContextConfigListener.java:224) [artifactory-web-application-5.7.0.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.access$2(ArtifactoryContextConfigListener.java:186) [artifactory-web-application-5.7.0.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener$1.run(ArtifactoryContextConfigListener.java:95) [artifactory-web-application-5.7.0.jar:na]
2017-12-21 08:42:57,878 [art-init] [ERROR] (o.a.c.ConvertersManagerImpl:216) - Conversion failed. You should analyze the error and retry launching Artifactory. Error is: Could not convert DB using v570 converter : Duplicate key name 'node_props_node_prop_value_idx'
2017-12-21 08:42:57,881 [art-init] [ERROR] (o.a.w.s.ArtifactoryContextConfigListener:99) - Application could not be initialized: Duplicate key name 'node_props_node_prop_value_idx'
java.lang.reflect.InvocationTargetException: null
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_152]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_152]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_152]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_152]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.configure(ArtifactoryContextConfigListener.java:224) ~[artifactory-web-application-5.7.0.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.access$2(ArtifactoryContextConfigListener.java:186) ~[artifactory-web-application-5.7.0.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener$1.run(ArtifactoryContextConfigListener.java:95) ~[artifactory-web-application-5.7.0.jar:na]
Caused by: java.lang.RuntimeException: Could not convert DB using v570 converter : Duplicate key name 'node_props_node_prop_value_idx'
        at org.artifactory.converter.ConvertersManagerImpl.handleException(ConvertersManagerImpl.java:223) ~[artifactory-common-5.7.0.jar:na]
        at org.artifactory.converter.ConvertersManagerImpl.serviceConvert(ConvertersManagerImpl.java:171) ~[artifactory-common-5.7.0.jar:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.refresh(ArtifactoryApplicationContext.java:237) ~[artifactory-core-5.7.0.jar:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.<init>(ArtifactoryApplicationContext.java:124) ~[artifactory-core-5.7.0.jar:na]
        ... 7 common frames omitted
Caused by: java.lang.RuntimeException: Could not convert DB using v570 converter
        at org.artifactory.storage.db.version.converter.DbSqlConverterUtil.convert(DbSqlConverterUtil.java:36) ~[artifactory-common-5.7.0.jar:na]
        at org.artifactory.storage.db.version.converter.DBSqlConverter.convert(DBSqlConverter.java:49) ~[artifactory-storage-db-5.7.0.jar:na]
        at org.artifactory.storage.db.version.ArtifactoryDBVersion.convert(ArtifactoryDBVersion.java:100) ~[artifactory-storage-db-5.7.0.jar:na]
        at org.artifactory.storage.db.DbServiceImpl.convert(DbServiceImpl.java:287) ~[artifactory-storage-db-5.7.0.jar:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_152]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_152]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_152]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_152]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:201) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at com.sun.proxy.$Proxy152.convert(Unknown Source) ~[na:na]
        at org.artifactory.converter.ConvertersManagerImpl.serviceConvert(ConvertersManagerImpl.java:167) ~[artifactory-common-5.7.0.jar:na]
        ... 9 common frames omitted
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Duplicate key name 'node_props_node_prop_value_idx'
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_152]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_152]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_152]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_152]
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:425) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.Util.getInstance(Util.java:408) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:943) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeUpdateInternal(StatementImpl.java:1552) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeLargeUpdate(StatementImpl.java:2607) ~[mysql-connector-java.jar:5.1.42]
        at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1480) ~[mysql-connector-java.jar:5.1.42]
        at org.jfrog.storage.util.DbStatementUtils.executeSqlStream(DbStatementUtils.java:51) ~[jfrog-db-infra-1.3.8.jar:na]
        at org.artifactory.storage.db.version.converter.DbSqlConverterUtil.convert(DbSqlConverterUtil.java:31) ~[artifactory-common-5.7.0.jar:na]
        ... 20 common frames omitted
2017-12-21 08:43:23,361 [http-nio-8081-exec-6] [ERROR] (o.a.w.s.ArtifactoryFilter:199) - Artifactory failed to initialize: Context is null


 Comments   
Comment by Volker Fuessler [ 05/Jan/18 ]

Doesn't work with 5.8.1. Do you have a solution, that's a real blocker for us (paying customers).

Comment by Volker Fuessler [ 05/Jan/18 ]

Ok, fixed it, by deleting the index before starting. But this worked only on one of two machines. On the other we could not delete the index and we had to set it up from scratch.

So, what worked on one machine was running those mysql commands:

ALTER TABLE node_props DROP INDEX node_props_node_prop_value_idx;
ALTER TABLE node_props DROP INDEX node_props_prop_key_value_idx;
Generated at Tue Sep 29 10:47:18 UTC 2020 using Jira 8.5.3#805003-sha1:b4933e02eaff29a49114274fe59e1f99d9d963d7.