Confluence 6.12.1 SQL bug on startup

[Minimons]

Hello!

(This bug has been discovered from 6.12.0 --> 6.12.1)

Suddently Confluence was unable to edit pages and I tried to restart the service with no help. I tried to restart with only data (easy in that it was a docker image) still with no luck.

I then tried to upgrade to the newest version. Still not working. According to the logfile the database upgrade went fine but I noticed the problem. It seems like Atlassian codes needs a beginners book on SQL! :-D

----

2018-10-09 13:59:58,904 WARN [localhost-startStop-1] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions:
->[com.atlassian.confluence.schedule.quartz.ManagedScheduledJobTriggerFactory.initialiseTriggers]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #1338070875)
Showing 10 last transactions at this level out of 20 in total:
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.find]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #281486008)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.delete]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #1934103561)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.find]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #1441865617)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.delete]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #2116576696)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.find]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #1100943275)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.delete]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #844496015)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.find]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #989724524)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.delete]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #416323668)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.find]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #456203934)
[com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJobDao.delete]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT (Session #1817754410)
2018-10-09 13:59:59,017 ERROR [localhost-startStop-1] [atlassian.config.lifecycle.LifecycleManager] panicAndShutdown Unable to start up Confluence. Fatal error during startup sequence: confluence.lifecycle.core:mananagedjobs (Start and stop the Managed Scheduled Jobs)
org.springframework.orm.hibernate5.HibernateJdbcException: JDBC exception on Hibernate data access: SQLException for SQL [n/a]; SQL state [HY000]; error code [50000]; could not extract ResultSet; nested exception is org.hibernate.exception.GenericJDBCException: could not extract ResultSet
at org.springframework.orm.hibernate5.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:248)
at org.springframework.orm.hibernate5.HibernateTemplate.doExecute(HibernateTemplate.java:366)
at org.springframework.orm.hibernate5.HibernateTemplate.execute(HibernateTemplate.java:313)
at com.atlassian.confluence.internal.schedule.persistence.dao.HibernateInternalRunDetailsDao.getRecentRunDetails(HibernateInternalRunDetailsDao.java:102)
at com.atlassian.confluence.internal.schedule.persistence.dao.HibernateInternalRunDetailsDao.getRecentRunDetails(HibernateInternalRunDetailsDao.java:114)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy132.getRecentRunDetails(Unknown Source)
at com.atlassian.confluence.schedule.managers.DefaultScheduledJobStatusManager.getScheduledJobStatus(DefaultScheduledJobStatusManager.java:69)
at com.atlassian.confluence.schedule.managers.DefaultScheduledJobManager.getScheduledJob(DefaultScheduledJobManager.java:102)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy134.getScheduledJob(Unknown Source)
at com.atlassian.confluence.schedule.quartz.ManagedScheduledJobTriggerFactory.createAndRegisterTrigger(ManagedScheduledJobTriggerFactory.java:218)
at com.atlassian.confluence.schedule.quartz.ManagedScheduledJobTriggerFactory.initialiseTriggers(ManagedScheduledJobTriggerFactory.java:152)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy159.initialiseTriggers(Unknown Source)
at com.atlassian.confluence.schedule.listeners.ManagedScheduledJobsLifecycle.startup(ManagedScheduledJobsLifecycle.java:24)
at com.atlassian.confluence.impl.setup.DefaultLifecycleManager.startUp(DefaultLifecycleManager.java:49)
at com.atlassian.config.lifecycle.LifecycleServletContextListener.contextInitialized(LifecycleServletContextListener.java:17)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4643)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5109)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1429)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1419)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.exception.GenericJDBCException: could not extract ResultSet
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2123)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1911)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1887)
at org.hibernate.loader.Loader.doQuery(Loader.java:932)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:349)
at org.hibernate.loader.Loader.doList(Loader.java:2615)
at org.hibernate.loader.Loader.doList(Loader.java:2598)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2430)
at org.hibernate.loader.Loader.list(Loader.java:2425)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:370)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1481)
at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1441)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1410)
at com.atlassian.confluence.internal.schedule.persistence.dao.HibernateInternalRunDetailsDao.lambda$getRecentRunDetails$0(HibernateInternalRunDetailsDao.java:108)
at org.springframework.orm.hibernate5.HibernateTemplate.doExecute(HibernateTemplate.java:359)
... 58 more
Caused by: org.h2.jdbc.JdbcSQLException: General error: "java.lang.IllegalArgumentException: timeNanos out of range 86400466000000"; SQL statement:
select schedulerr0_.id as id1_51_, schedulerr0_.job_id as job_id2_51_, schedulerr0_.start_time as start_ti3_51_, schedulerr0_.duration as duration4_51_, schedulerr0_.outcome as outcome5_51_, schedulerr0_.message as message6_51_ from scheduler_run_details schedulerr0_ where schedulerr0_.job_id=? order by schedulerr0_.start_time desc limit ? [50000-196]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.message.DbException.convert(DbException.java:295)
at org.h2.command.Command.executeQuery(Command.java:215)
at org.h2.server.TcpServerThread.process(TcpServerThread.java:329)
at org.h2.server.TcpServerThread.run(TcpServerThread.java:158)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalArgumentException: timeNanos out of range 86400466000000
at org.h2.value.ValueTimestamp.<init>(ValueTimestamp.java:54)
at org.h2.value.ValueTimestamp.fromDateValueAndNanos(ValueTimestamp.java:68)
at org.h2.value.ValueTimestamp.fromMillisNanos(ValueTimestamp.java:95)
at org.h2.store.Data.readValue(Data.java:780)
at org.h2.index.PageDataLeaf.readRow(PageDataLeaf.java:623)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:333)
at org.h2.index.PageDataLeaf.getRowWithKey(PageDataLeaf.java:453)
at org.h2.index.PageDataNode.getRowWithKey(PageDataNode.java:280)
at org.h2.index.PageDataNode.getRowWithKey(PageDataNode.java:280)
at org.h2.index.PageDataNode.getRowWithKey(PageDataNode.java:280)
at org.h2.index.PageDataIndex.getRowWithKey(PageDataIndex.java:426)
at org.h2.index.PageDataIndex.getRow(PageDataIndex.java:415)
at org.h2.table.RegularTable.getRow(RegularTable.java:106)
at org.h2.index.PageBtreeIndex.getRow(PageBtreeIndex.java:303)
at org.h2.index.PageBtreeCursor.get(PageBtreeCursor.java:45)
at org.h2.index.MultiVersionCursor.get(MultiVersionCursor.java:82)
at org.h2.index.IndexCursor.get(IndexCursor.java:288)
at org.h2.table.TableFilter.getValue(TableFilter.java:1087)
at org.h2.expression.ExpressionColumn.getValue(ExpressionColumn.java:186)
at org.h2.expression.Alias.getValue(Alias.java:36)
at org.h2.command.dml.Select$LazyResultQueryFlat.fetchNextRow(Select.java:1459)
at org.h2.result.LazyResult.hasNext(LazyResult.java:79)
at org.h2.result.LazyResult.next(LazyResult.java:59)
at org.h2.command.dml.Select.queryFlat(Select.java:519)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:625)
at org.h2.command.dml.Query.queryWithoutCacheLazyCheck(Query.java:114)
at org.h2.command.dml.Query.query(Query.java:371)
at org.h2.command.dml.Query.query(Query.java:333)
at org.h2.command.CommandContainer.query(CommandContainer.java:113)
at org.h2.command.Command.executeQuery(Command.java:201)
... 3 more

at org.h2.engine.SessionRemote.done(SessionRemote.java:629)
at org.h2.command.CommandRemote.executeQuery(CommandRemote.java:176)
at org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:111)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:379)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:71)
... 75 more
2018-10-09 14:00:05,104 INFO [localhost-startStop-1] [com.atlassian.confluence.lifecycle] init Confluence is ready to serve

----

I can see from the log that it is not a data problem but rather an parameter to a SQL statement that is out of range:

   "timeNanos out of range 86400466000000"; SQL statement"

Any ideas how to workaround the bug?

Best regards,

- Morten Green Hermansen

[Lava Kumar Dukanam _Appfire_]

Hi @Minimons,

It looks like there's a common problem associated with H2 upgrade.

Take a look at this http://h2-database.66688.n3.nabble.com/TimeNanos-out-of-range-when-using-different-version-of-jar-No-check-when-DB-upgraded-td4033636.html

i'm quoting a fix from the above link "I suggest you revert to an earlier version, do a dump, and restore into the new version, after fixing up the data."

It is recommended to use MYSQL instead of in-memory H2 DB for production purposes.

Regards,

Lava

[Minimons]

But how is that possible? When starting 6.12.0 the database got migrated. So I am pretty sure starting and old version with new database tables will fail!

And the error is also happening in the old versions. That is why I tried to upgrade in the first place.

Does that mean that I have lost all the data I have put into Confluence then?