Create
cancel
Showing results for 
Search instead for 
Did you mean: 
Sign up Log in

Database migration from HSQLDB to PostgreSQL failing

Mircea Vutcovici November 28, 2014

I am trying to migrate a Stash instance from the internal database (HSQLDB) to PostgreSQL 9.3.5.

The migration is failing with the following error in browser:

Stash could not be migrated to the new database. Some data may have already been written to the new database leaving it in an inconsistent state. You will need to empty or recreate the new database before trying again.
	com.atlassian.stash.internal.maintenance.migration.DatabaseMigrationTask.run(DatabaseMigrationTask.java:51)
	com.atlassian.stash.internal.maintenance.DefaultMaintenanceTaskMonitor.run(DefaultMaintenanceTaskMonitor.java:183)
	java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	...
Failed to execute change: Insert Row; nested exception is org.postgresql.util.PSQLException: ERROR: invalid byte sequence for encoding "UTF8": 0x00
	com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseDao.insert(DefaultLiquibaseDao.java:274)
	com.atlassian.stash.internal.backup.liquibase.DatabaseUpdater.endElement(DatabaseUpdater.java:81)
	org.apache.xerces.parsers.AbstractSAXParser.endElement(Unknown Source)
	...
ERROR: invalid byte sequence for encoding "UTF8": 0x00
	org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
	org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
	org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
	...

We are usign an empty PostgreSQL database as required by the Stash migration documentation. https://confluence.atlassian.com/display/STASH/Connecting+Stash+to+PostgreSQL

The schema is populated durring the migration with 71 tables some of them containing data.

In the atlassian-stash.log file the part where the migration is failing is:

2014-11-28 21:52:27,137 INFO  [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseMigrationDao Found 61 non-empty change sets to apply to the target database
2014-11-28 21:52:27,137 INFO  [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseMigrationDao Connecting to target database
.............
2014-11-28 21:52:28,936 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.liquibase.DatabaseUpdater Executing changeset 32 of 61, containing 293 changes with id plugin_setting-41
2014-11-28 21:52:28,950 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao Unlocking Liquibase
2014-11-28 21:52:29,059 ERROR [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao Failed to release Liquibase lock
liquibase.exception.LockException: liquibase.exception.UnexpectedLiquibaseException: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
        at liquibase.lockservice.LockService.releaseLock(LockService.java:152) ~[LockService.class:na]
        at com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseDao$2.apply(DefaultLiquibaseDao.java:83) [DefaultLiquibaseDao$2.class:na]
        at com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseDao$2.apply(DefaultLiquibaseDao.java:79) [DefaultLiquibaseDao$2.class:na]
        at com.atlassian.fugue.Option$Some.foreach(Option.java:441) [Option$Some.class:na]
        at com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseDao.unlock(DefaultLiquibaseDao.java:471) [DefaultLiquibaseDao.class:na]
        at com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseDao.withLock(DefaultLiquibaseDao.java:303) [DefaultLiquibaseDao.class:na]
        at com.atlassian.stash.internal.backup.liquibase.DefaultLiquibaseMigrationDao.restore(DefaultLiquibaseMigrationDao.java:168) [DefaultLiquibaseMigrationDao.class:na]
        at com.atlassian.stash.internal.maintenance.restore.DatabaseRestoreStep.run(DatabaseRestoreStep.java:104) [DatabaseRestoreStep.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask$Step.run(CompositeMaintenanceTask.java:130) [CompositeMaintenanceTask$Step.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask.run(CompositeMaintenanceTask.java:69) [CompositeMaintenanceTask.class:na]
        at com.atlassian.stash.internal.maintenance.restore.RestorePhase.run(RestorePhase.java:26) [RestorePhase.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask$Step.run(CompositeMaintenanceTask.java:130) [CompositeMaintenanceTask$Step.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask.run(CompositeMaintenanceTask.java:69) [CompositeMaintenanceTask.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask$Step.run(CompositeMaintenanceTask.java:130) [CompositeMaintenanceTask$Step.class:na]
        at com.atlassian.stash.internal.maintenance.CompositeMaintenanceTask.run(CompositeMaintenanceTask.java:69) [CompositeMaintenanceTask.class:na]
        at com.atlassian.stash.internal.maintenance.MaintenanceModePhase.run(MaintenanceModePhase.java:27) [MaintenanceModePhase.class:na]
        at com.atlassian.stash.internal.maintenance.migration.BaseMigrationTask.run(BaseMigrationTask.java:60) [BaseMigrationTask.class:na]
        at com.atlassian.stash.internal.maintenance.migration.DatabaseMigrationTask.run(DatabaseMigrationTask.java:46) [DatabaseMigrationTask.class:na]
        at com.atlassian.stash.internal.maintenance.DefaultMaintenanceTaskMonitor.run(DefaultMaintenanceTaskMonitor.java:183) [DefaultMaintenanceTaskMonitor.class:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_72]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_72]
        at com.atlassian.stash.internal.concurrent.StateTransferringExecutor$StateTransferringRunnable.run(StateTransferringExecutor.java:69) [StateTransferringExecutor$StateTransferringRunnable.class:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_72]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_72]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_72]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) [na:1.7.0_72]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_72]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_72]
        ... 1 frame trimmed
Caused by: liquibase.exception.UnexpectedLiquibaseException: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
        at liquibase.snapshot.jvm.JdbcDatabaseSnapshotGenerator.hasTable(JdbcDatabaseSnapshotGenerator.java:63) ~[JdbcDatabaseSnapshotGenerator.class:na]
        at liquibase.snapshot.jvm.JdbcDatabaseSnapshotGenerator.hasDatabaseChangeLogLockTable(JdbcDatabaseSnapshotGenerator.java:49) ~[JdbcDatabaseSnapshotGenerator.class:na]
        at liquibase.database.AbstractDatabase.hasDatabaseChangeLogLockTable(AbstractDatabase.java:549) ~[AbstractDatabase.class:na]
        at liquibase.lockservice.LockService.releaseLock(LockService.java:135) ~[LockService.class:na]
        ... 28 common frames omitted
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254) ~[postgresql-9.1-901.jdbc4.jar:na]
        at org.postgresql.jdbc2.AbstractJdbc2DatabaseMetaData.getTables(AbstractJdbc2DatabaseMetaData.java:2069) ~[postgresql-9.1-901.jdbc4.jar:na]
        at liquibase.snapshot.jvm.JdbcDatabaseSnapshotGenerator.hasTable(JdbcDatabaseSnapshotGenerator.java:54) ~[JdbcDatabaseSnapshotGenerator.class:na]
        ... 31 common frames omitted
2014-11-28 21:52:29,110 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao Liquibase unlocked
2014-11-28 21:52:29,110 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseMigrationDao Deleting temporary file
2014-11-28 21:52:29,129 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao Unlocking Liquibase
..........
2014-11-28 21:52:29,155 DEBUG [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.m.restore.RestorePhase Successfully deleted unpacked files from /opt/stash-home/tmp/backup-mvutcovici-20141128-215202-764Z.zip-unpack84449949564272605.backup
2014-11-28 21:52:29,164 ERROR [threadpool:thread-2] mvutcovici @16LK6DXx1311x84x0 16mw1ju 10.128.221.98 "POST /admin/db/edit HTTP/1.1" c.a.s.i.m.m.BaseMigrationTask Reverting database configuration after a failed migration attempt
com.atlassian.stash.internal.backup.liquibase.LiquibaseChangeExecutionException: Failed to execute change: Insert Row; nested exception is org.postgresql.util.PSQLException: ERROR: invalid byte sequence for encoding "UTF8": 0x00

 

There are some temporary zip files generated in the stash.home/export/ and in the last one, in the stash-data.xml file there, the 32 changeset has the id "sta_project_permission-32".

 

I've activated debug loggin in postgresql. Here is the relevant log from the database server:

< 2014-12-01 14:21:17.997 GMT >LOG:  00000: execute S_29: insert into plugin_setting (namespace, key_name, key_value, id) values ($1, $2, $3, $4)
< 2014-12-01 14:21:17.997 GMT >DETAIL:  parameters: $1 = 'stash.global.settings', $2 = 'applinks.local.RDV.stash_project.linked.entities', $3 = '#java.util.List
    ', $4 = '17'
< 2014-12-01 14:21:17.997 GMT >LOCATION:  exec_execute_message, postgres.c:1906
< 2014-12-01 14:21:17.997 GMT >LOG:  00000: execute S_29: insert into plugin_setting (namespace, key_name, key_value, id) values ($1, $2, $3, $4)
< 2014-12-01 14:21:17.997 GMT >DETAIL:  parameters: $1 = 'stash.global.settings', $2 = 'applinks.local.RDVSER.stash_project.linked.entities', $3 = '#java.util.List
    ', $4 = '18'
< 2014-12-01 14:21:17.997 GMT >LOCATION:  exec_execute_message, postgres.c:1906
< 2014-12-01 14:21:17.998 GMT >ERROR:  22021: invalid byte sequence for encoding "UTF8": 0x00
< 2014-12-01 14:21:17.998 GMT >LOCATION:  report_invalid_encoding, wchar.c:2020
< 2014-12-01 14:21:17.998 GMT >STATEMENT:  insert into plugin_setting (namespace, key_name, key_value, id) values ($1, $2, $3, $4)
< 2014-12-01 14:21:18.003 GMT >ERROR:  25P02: current transaction is aborted, commands ignored until end of transaction block
< 2014-12-01 14:21:18.004 GMT >LOCATION:  exec_parse_message, postgres.c:1259
< 2014-12-01 14:21:18.004 GMT >STATEMENT:  SELECT NULL AS TABLE_CAT, n.nspname AS TABLE_SCHEM, c.relname AS TABLE_NAME,  CASE n.nspname ~ '^pg_' OR n.nspname = 'information_schema'  WHEN true THEN CASE  WHEN n.nspname = 'pg_catalog' OR n.nspname = 'information_schema' THEN CASE c.relkind   WHEN 'r' THEN 'SYSTEM TABLE'   WHEN 'v' THEN 'SYSTEM VIEW'   WHEN 'i' THEN 'SYSTEM INDEX'   ELSE NULL   END  WHEN n.nspname = 'pg_toast' THEN CASE c.relkind   WHEN 'r' THEN 'SYSTEM TOAST TABLE'   WHEN 'i' THEN 'SYSTEM TOAST INDEX'   ELSE NULL   END  ELSE CASE c.relkind   WHEN 'r' THEN 'TEMPORARY TABLE'   WHEN 'i' THEN 'TEMPORARY INDEX'   WHEN 'S' THEN 'TEMPORARY SEQUENCE'   WHEN 'v' THEN 'TEMPORARY VIEW'   ELSE NULL   END  END  WHEN false THEN CASE c.relkind  WHEN 'r' THEN 'TABLE'  WHEN 'i' THEN 'INDEX'  WHEN 'S' THEN 'SEQUENCE'  WHEN 'v' THEN 'VIEW'  WHEN 'c' THEN 'TYPE'  ELSE NULL  END  ELSE NULL  END  AS TABLE_TYPE, d.description AS REMARKS  FROM pg_catalog.pg_namespace n, pg_catalog.pg_class c  LEFT JOIN pg_catalog.pg_description d ON (c.oid = d.objoid AND d.objsubid = 0)  LEFT JOIN pg_catalog.pg_class dc ON (d.classoid=dc.oid AND dc.relname='pg_class')  LEFT JOIN pg_catalog.pg_namespace dn ON (dn.oid=dc.relnamespace AND dn.nspname='pg_catalog')  WHERE c.relnamespace = n.oid  AND n.nspname LIKE 'public'  AND c.relname LIKE 'databasechangeloglock'  AND (false  OR ( c.relkind = 'r' AND n.nspname !~ '^pg_' AND n.nspname <> 'information_schema' ) )  ORDER BY TABLE_TYPE,TABLE_SCHEM,TABLE_NAME 
< 2014-12-01 14:21:18.013 GMT >LOG:  00000: execute S_30: ROLLBACK

The XML entries from stash-data.xml file related to the PostgreSQL messages above:

 <changeSet id="plugin_setting-41" author="mvutcovici">
......
        <insert tableName="plugin_setting">
            <column name="namespace" colType="character"><![CDATA[stash.global.settings]]></column>
            <column name="key_name" colType="character"><![CDATA[applinks.local.RDV.stash_project.linked.entities]]></column>
            <column name="key_value" colType="character"><![CDATA[#java.util.List\u000A]]></column>
            <column name="id" colType="numeric"><![CDATA[17]]></column>
        </insert>
        <insert tableName="plugin_setting">
            <column name="namespace" colType="character"><![CDATA[stash.global.settings]]></column>
            <column name="key_name" colType="character"><![CDATA[applinks.local.RDVSER.stash_project.linked.entities]]></column>
            <column name="key_value" colType="character"><![CDATA[#java.util.List\u000A]]></column>
            <column name="id" colType="numeric"><![CDATA[18]]></column>
        </insert>
        <insert tableName="plugin_setting">
            <column name="namespace" colType="character"><![CDATA[stash.global.settings]]></column>
            <column name="key_name" colType="character"><![CDATA[audit.cleanup.last.run]]></column>
            <column name="key_value" colType="character"><![CDATA[\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000]]></column>
            <column name="id" colType="numeric"><![CDATA[19]]></column>
        </insert>
.....

 

The error 'ERROR: 22021: invalid byte sequence for encoding "UTF8": 0x00' is related to: http://stackoverflow.com/a/1348551/290087

How can we populate the "audit.cleanup.last.run" field?

 

OS: CentOS 6.5 64bit

Java: Oracle Server JRE 7u72 64bit

DB Source: internal HSQLDB 2.2.4 (that is part of Stash installation)

DB Destination: postgresql93-server-9.3.5-1PGDG.rhel6.x86_64

Stash: v3.3.0  Installed using the install4j installer from atlassian-stash-3.3.0-x64.bin package.

 

Any help will be appreciated.

2 answers

1 accepted

2 votes
Answer accepted
Ubisoft December 9, 2014

Explanation:

The problem is in the HSQL database, in the PUBLIC.PLUGIN_SETTING table. This table has the attribute KEY_VALUE as a CLOB (character large object), which allows UTF8 nulls.

# java -cp hsqldb-2.2.4/hsqldb/lib/hsqldb.jar -jar hsqldb-2.2.4/hsqldb/lib/sqltool.jar --rcFile sqltool.rc --debug --sql "SELECT key_value FROM PUBLIC.PLUGIN_SETTING where key_name='audit.cleanup.last.run';" stash |hexdump -C
00000000  00 00 00 00 00 00 00 00  00 00 00 00 00 0a        |..............|
0000000e

PostgeSQL is not supporting null characters in UTF8 strings.

Solution:

The solution is to replace the 13 null characters with an empty string.

This can be done in 2 ways:

  • from HSQLDB with sqltool.jar: java -cp hsqldb-2.2.4/hsqldb/lib/hsqldb.jar -jar hsqldb-2.2.4/hsqldb/lib/sqltool.jar --rcFile sqltool.rc --debug --sql "update PUBLIC.PLUGIN_SETTING set key_value='' where key_name='audit.cleanup.last.run';commit;" stash
  • by running a stash backup with the stash-backup-client.jar and unpacking the backup, then the system-new.zip, then replacing all "\u0000" with an empty string in the stash-data.xml file, then re-packing everything and restoring the changed backup. See: https://confluence.atlassian.com/display/STASH/Using+the+Stash+Backup+Client

Both methods involve stopping the Stash application.

urlid stash
url jdbc:hsqldb:file:$STASH_HOME/shared/data/db;shutdown=true
username SA
password
transiso TRANSACTION_READ_COMMITTED
# /opt/jdk1.7/jre/bin/java -cp hsqldb-2.2.4/hsqldb/lib/hsqldb.jar -jar hsqldb-2.2.4/hsqldb/lib/sqltool.jar --rcFile sqltool.rc --debug --sql "update PUBLIC.PLUGIN_SETTING set key_value='' where key_name='audit.cleanup.last.run';commit;" stash
# /opt/jdk1.7/jre/bin/java -cp hsqldb-2.2.4/hsqldb/lib/hsqldb.jar -jar hsqldb-2.2.4/hsqldb/lib/sqltool.jar --rcFile sqltool.rc --debug --sql "SELECT key_value FROM PUBLIC.PLUGIN_SETTING where key_name='audit.cleanup.last.run';" stash |hexdump -C
00000000  0a                                                |.|
00000001
2 votes
ThiagoBomfim
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
December 9, 2014

Hi everyone!

We've raised an issue for it and we're tracking it here: https://jira.atlassian.com/browse/STASH-6839

Thanks for your report.

Best regards,
Thiago Bomfim
Atlassian Support

Mircea Vutcovici December 10, 2014

Awesome! Thank you guys!

Suggest an answer

Log in or Sign up to answer
TAGS
AUG Leaders

Atlassian Community Events