upgrade problem with ms2-15.30-16.10.sql

Installation Forum (Inactive)
upgrade problem with ms2-15.30-16.10.sql toan nguyen  2017-10-26 11:43
Status: Closed
Hi all,

  We have problem during the upgrade to 17.2. Please see below for the error.
  Please help.


INFO SqlScriptManager 2017-10-25 16:05:03,879 Module Upgrade : start running script : ms2-15.30-16.10.sql
ERROR Table 2017-10-25 20:39:19,149 Module Upgrade : SQL Exception
org.postgresql.util.PSQLException: ERROR: column "mascotfile" of relation "runs" already exists
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2476)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2189)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:301)
        at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:287)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:264)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:260)
        at org.apache.tomcat.dbcp.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:290)
        at org.apache.tomcat.dbcp.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:290)
        at org.labkey.api.data.dialect.StatementWrapper.execute(StatementWrapper.java:1908)
        at org.labkey.api.data.SqlExecutor$NormalStatementExecutor.execute(SqlExecutor.java:156)
        at org.labkey.api.data.SqlExecutor$NormalStatementExecutor.execute(SqlExecutor.java:144)
        at org.labkey.api.data.SqlExecutor.execute(SqlExecutor.java:122)
        at org.labkey.api.data.SqlExecutor.execute(SqlExecutor.java:75)
        at org.labkey.api.data.SqlExecutor.execute(SqlExecutor.java:70)
        at org.labkey.api.data.SqlScriptExecutor$Block.execute(SqlScriptExecutor.java:208)
        at org.labkey.api.data.SqlScriptExecutor.lambda$execute$0(SqlScriptExecutor.java:101)
        at java.util.ArrayList.forEach(ArrayList.java:1249)
        at org.labkey.api.data.SqlScriptExecutor.execute(SqlScriptExecutor.java:98)
        at org.labkey.api.data.dialect.SqlDialect.runSql(SqlDialect.java:588)
        at org.labkey.api.data.SqlScriptManager.runScript(SqlScriptManager.java:215)
        at org.labkey.api.data.SqlScriptRunner.runScripts(SqlScriptRunner.java:82)
        at org.labkey.api.module.DefaultModule.versionUpdate(DefaultModule.java:333)
        at org.labkey.api.module.ModuleUpgrader.upgrade(ModuleUpgrader.java:83)
        at org.labkey.api.module.ModuleUpgrader.lambda$upgrade$0(ModuleUpgrader.java:95)
        at java.lang.Thread.run(Thread.java:748)
ERROR Table 2017-10-25 20:39:19,158 Module Upgrade : SQL [22230]
toan nguyen responded:  2017-10-26 12:33
Sorry forgot to mention.
I am upgrading to 17.2 on Ubuntu 16.04.

The postgres log shows :

2017-10-25 20:39:15 PDT 21895 postgres labkey LOG: duration: 943967.640 ms execute <unnamed>:
        CREATE UNIQUE INDEX UQ_MS2PeptidesData_FractionScanCharge ON ms2.PeptidesData(Fraction, Scan, EndScan, Charge, HitRank, Decoy, QueryNumber)
2017-10-25 20:39:19 PDT 22230 postgres labkey ERROR: column "mascotfile" of relation "runs" already exists
toan nguyen responded:  2017-10-26 15:12
this upgrade sql give problem when run in psql

ERROR: column "mascotfile" of relation "runs" already exists

look like I already have mascotfile...

 mascotfile | character varying(300) | | extended |

and other columns in that ADD sql already there too. I guess I can comment it out, but how to resume the upgrade ?
jeckels responded:  2017-10-26 15:38

What version were you starting with prior to the upgrade?

Also, since it sounds like you have a direct database connection set up already, can you send the output from this query:

select * from core.sqlscripts where filename like 'ms2%' order by filename

Jon (LabKey DevOps) responded:  2017-10-26 15:54
Also, by any chance did you start the upgrade and then had to shut it down and start it up again before it finished?


toan nguyen responded:  2017-10-26 16:16
well this is a mystery.
I am guessing the SQL script failed , then restart itself. Then it causes problem.
the fastaid column already drop out the table on that script. I do see new data , run, fastaid on the new table;
I comments sql lines out and restart tomcat. It appears the upgrade finish the rest and the app is up.

INFO ModuleLoader 2017-10-26 15:58:31,128 Module Upgrade : Running startup listener: DataIntegration
INFO ModuleLoader 2017-10-26 15:58:31,353 Module Upgrade : Module startup complete

Well , I am not sure what data is missing.

Also, whenever I restart tomcat, the module upgrade will need to run again ?
I thought it only run once .

INFO ModuleLoader 2017-10-26 16:11:49,197 localhost-startStop-1 : LabKey Server startup is complete; modules are being upgraded and initialized in the background
INFO ModuleLoader 2017-10-26 16:11:49,205 Module Upgrade : Starting up modules
INFO ModuleLoader 2017-10-26 16:11:49,213 Module Upgrade : Starting module 'Core'
Jon (LabKey DevOps) responded:  2017-10-26 23:58
Hi Toan,

If the upgrade had failed midway through, specifically after it already did an ALTER to the table to add more columns, it would make sense then to get the error you're seeing again. Since you commented those SQL lines out when you did the restart, that definitely would have bypassed the rest of the script's actions.

Thankfully, once the server has finished updating, the core.modules table will actually list the scripts it ran last successfully, so those scripts will not re-trigger again on the DB.

Also, don't worry about the message talking about the modules "upgrading and initializing in the background". The message is a bit generic, but upgrading and initializing are one in the same. We check to see if the DB needs to be upgraded and based on what the core.modules table tells us, we then either proceed or just move onto the next module until all the modules are initialized (i.e. unzipped from their .module archive).


toan nguyen responded:  2017-10-27 11:03

when I visit the labkey URL (tomcat up) after manual script upgrade, the web site said , upgrade in process..
I did not restart tomcat at that time. However the sql scripts took like 4 hours to run and it failed with that column exists error.

I think, I may have refresh the browser when I am waiting for the sql upgrade.
Can that cause the sql script to run twice ?

I will test again. This time I will close the browser when waiting for the sql script upgrade to complete.

Thanks a lot for your inputs.