Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Fixed
Priority: Highest
Fix Version/s: 8.1.0, 7.19.6
Affects Version/s: 7.19.4, 7.19.5, 7.20.3
Component/s: Search - Indexing
Labels:
- thunder-bird

Support reference count:
32
Symptom Severity:
Severity 2 - Major
UIS:
380
Bug Fix Policy:
View Atlassian Server bug fix policy

Description

Issue Summary

Post upgrade to Confluence 7.19.4, lots of SQL Error can be observed under the logs that are related to index related threads. Also, once rebuild is done, though the reindexing completes in background but the index percentage completion is way less than 100%. Typical reports have been around 80%.

This is reproducible on Data Center: Yes

Steps to Reproduce

Step 1 Disable Collaborative Editing or ensure there are personal drafts already under the database. If personal drafts are available, skip step 2 below.
Step 2 Create a page and a draft under Confluence.
Step 3 Trigger rebuild from UI

Expected Results

No SQL Errors should be reported during normal index processing and 100% completion should be reported under atlassian-confluence-index.log file.

Actual Results

Logs are flooded with SQL related errors. Below is the snippet from atlassian-confluence.log during rebuild-

2023-01-18 16:09:49,810 WARN [Indexer: 7] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions:
  ->[null]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,readOnly (Session #89148160)
2023-01-18 16:09:49,921 ERROR [Indexer: 13] [engine.jdbc.spi.SqlExceptionHelper] logExceptions ERROR: syntax error at or near ")"
  Position: 1433
2023-01-18 16:09:49,921 WARN [Indexer: 13] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions:
  ->[null]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,readOnly (Session #1874739016)
2023-01-18 16:09:50,419 ERROR [Indexer: 12] [engine.jdbc.spi.SqlExceptionHelper] logExceptions ERROR: syntax error at or near ")"
  Position: 1433

The above errors under atlassian-confluence.log may be slightly different where MySQL DB and Oracle DB would be in play. Below is the snippet for quick reference-

MySQL:

2022-12-17 16:32:08,274 ERROR [Indexer: 11] [engine.jdbc.spi.SqlExceptionHelper] logExceptions You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ') or contentent0_.CONTENTID in ()) and contentent0_.CONTENT_STATUS='current'' at line 1

2022-12-17 16:32:08,275 ERROR [Indexer: 10] [engine.jdbc.spi.SqlExceptionHelper] logExceptions You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ') or contentent0_.CONTENTID in ()) and contentent0_.CONTENT_STATUS='current'' at line 1

Oracle:

2023-03-17 16:52:13,177 ERROR [lucene-interactive-reindexing-thread] [confluence.internal.index.ConcurrentBatchIndexer] index Exception processing batch
 -- referer: http://localhost:8090/plugins/servlet/rebuildindex | url: /rest/prototype/latest/index/reindex | traceId: 3bf01d7a84f18541 | userName: admin
java.util.concurrent.ExecutionException: javax.persistence.PersistenceException: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
	at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more
Caused by: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
	at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:63)
Caused by: java.sql.SQLSyntaxErrorException: ORA-00936: missing expression

	at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:509)
...
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
	... 58 more
Caused by: Error : 936, Position : 1510, Sql = select contentent0_.CONTENTID as CONTENTID1_13_0_, confluence1_.user_key as user_key1_71_1_, contentent0_.HIBERNATEVERSION as

Also, under atlassian-confluence-index.log file, we can observe below logs -

2023-01-18 22:49:37,330 INFO [lucene-interactive-reindexing-thread] [confluence.internal.index.ConcurrentBatchIndexer] submitBatches Partitioning indexable entities [8 com.atlassian.confluence.pages.Draft] up to 100 at a time across indexing threads
2023-01-18 22:49:37,585 ERROR [lucene-interactive-reindexing-thread] [confluence.internal.index.ConcurrentBatchIndexer] index Exception processing batch
 -- referer: http://localhost:8090/plugins/servlet/rebuildindex | url: /rest/prototype/latest/index/reindex | traceId: ea678ce9c83c778e | userName: confluence7194
java.util.concurrent.ExecutionException: javax.persistence.PersistenceException: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
        at java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.util.concurrent.FutureTask.get(FutureTask.java:192)
        at com.atlassian.confluence.internal.index.ConcurrentBatchIndexer.index(ConcurrentBatchIndexer.java:77)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.lambda$null$4(LuceneReIndexer.java:214)
        at com.atlassian.confluence.internal.index.lucene.LuceneSearchIndexAccessor.lambda$execute$0(LuceneSearchIndexAccessor.java:142)
        at com.atlassian.bonnie.LuceneConnection.withWriter(LuceneConnection.java:433)
        at com.atlassian.bonnie.LuceneConnection.execute(LuceneConnection.java:643)
        at com.atlassian.confluence.internal.index.lucene.LuceneSearchIndexAccessor.execute(LuceneSearchIndexAccessor.java:140)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.lambda$reIndex$5(LuceneReIndexer.java:198)
        at com.atlassian.confluence.internal.index.lucene.LuceneSearchIndexAccessor.lambda$execute$0(LuceneSearchIndexAccessor.java:142)
        at com.atlassian.bonnie.LuceneConnection.withWriter(LuceneConnection.java:433)
        at com.atlassian.bonnie.LuceneConnection.execute(LuceneConnection.java:643)
        at com.atlassian.confluence.internal.index.lucene.LuceneSearchIndexAccessor.execute(LuceneSearchIndexAccessor.java:140)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.reIndex(LuceneReIndexer.java:197)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.reIndex(LuceneReIndexer.java:152)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.lambda$reIndex$0(LuceneReIndexer.java:94)
        at java.lang.Iterable.forEach(Iterable.java:75)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.reIndex(LuceneReIndexer.java:92)
        at com.atlassian.confluence.internal.index.lucene.LuceneReIndexer.reIndex(LuceneReIndexer.java:84)
        at com.atlassian.confluence.search.ReIndexTask.run(ReIndexTask.java:89)
        at com.atlassian.confluence.cluster.ReIndexingScopeThreadLocal.withScope(ReIndexingScopeThreadLocal.java:26)
        at com.atlassian.confluence.internal.index.lucene.LuceneFullReindexManager.lambda$null$0(LuceneFullReindexManager.java:109)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at com.atlassian.confluence.impl.tenant.ThreadLocalTenantGate.lambda$wrap$0(ThreadLocalTenantGate.java:25)
        at com.atlassian.confluence.internal.index.lucene.LuceneFullReindexManager.lambda$reIndex$1(LuceneFullReindexManager.java:109)
        at java.lang.Thread.run(Thread.java:748)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:149)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157)
        at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1423)
        at com.atlassian.confluence.internal.persistence.hibernate.AbstractContentEntityObjectHibernateDao.getAllModifiers(AbstractContentEntityObjectHibernateDao.java:643)
        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:344)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
        at com.sun.proxy.$Proxy151.getAllModifiers(Unknown Source)
        at com.atlassian.confluence.internal.index.v2.extractors.ContentModifiersBulkExtractor.extractAllModifiers(ContentModifiersBulkExtractor.java:77)
        at com.atlassian.confluence.internal.index.v2.extractors.ContentModifiersBulkExtractor.extractAll(ContentModifiersBulkExtractor.java:55)
        at com.atlassian.confluence.internal.index.lucene.BulkFieldPrefetcher.lambda$prefetch$1(BulkFieldPrefetcher.java:75)
        at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
        at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
        at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1384)
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
        at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
        at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
        at com.atlassian.confluence.internal.index.lucene.BulkFieldPrefetcher.prefetch(BulkFieldPrefetcher.java:73)
        at com.atlassian.confluence.internal.index.lucene.BulkFieldPrefetcher.prefetch(BulkFieldPrefetcher.java:60)
        at com.atlassian.confluence.internal.index.lucene.BulkFieldPrefetcher.createPrefetchedDocumentBuilder(BulkFieldPrefetcher.java:48)
        at com.atlassian.confluence.internal.index.lucene.LuceneBatchIndexer.doIndex(LuceneBatchIndexer.java:165)
        at com.atlassian.confluence.internal.index.lucene.LuceneBatchIndexer.lambda$index$0(LuceneBatchIndexer.java:78)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
        at com.atlassian.confluence.internal.index.lucene.LuceneBatchIndexer.index(LuceneBatchIndexer.java:77)
        at com.atlassian.confluence.internal.index.ConcurrentBatchIndexer.lambda$null$2(ConcurrentBatchIndexer.java:129)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at com.atlassian.confluence.impl.tenant.ThreadLocalTenantGate.lambda$wrap$0(ThreadLocalTenantGate.java:25)
        at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContextInternal(VCacheRequestContextManager.java:84)
        at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:68)
        at com.atlassian.confluence.vcache.VCacheRequestContextOperations.lambda$withRequestContext$1(VCacheRequestContextOperations.java:59)
        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)
        ... 1 more
Caused by: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
        at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:106)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
        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:69)
        at org.hibernate.loader.Loader.getResultSet(Loader.java:2168)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1931)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893)
        at org.hibernate.loader.Loader.doQuery(Loader.java:938)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
        at org.hibernate.loader.Loader.doList(Loader.java:2692)
        at org.hibernate.loader.Loader.doList(Loader.java:2675)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507)
        at org.hibernate.loader.Loader.list(Loader.java:2502)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:392)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1490)
        at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1445)
        at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414)
        ... 44 more
Caused by: org.postgresql.util.PSQLException: ERROR: syntax error at or near ")"
  Position: 1433
         at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2676)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2366)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:356)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:496)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:413)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190)
        at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:134)
        at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
        ... 59 more

In addition to above, the completion percentage is not 100% as well post reindex completion -

2023-01-18 22:49:45,267 INFO [lucene-interactive-reindexing-thread] [internal.index.lucene.LuceneReIndexer] lambda$null$4 full reindex completed for USER_ONLY, 93% complete, start cleaning up files
2023-01-18 22:49:45,294 INFO [lucene-interactive-reindexing-thread] [internal.index.lucene.LuceneReIndexer] lambda$null$4 full reindex cleanup completed for USER_ONLY
2023-01-18 22:49:45,306 INFO [lucene-interactive-reindexing-thread] [internal.index.lucene.LuceneReIndexer] reIndex Indexing completed for stage USER_ONLY

Workaround

Currently there is no known workaround for this behavior. A workaround will be added here when available

Attachments

Issue Links

depended on by

CONFSERVER-81283 Confluence reindexing progress appears to stall at less than 100% when rebuilding index from scratch

Closed

is caused by: SEF-16790 Loading...

links to

CONFSERVER-87272

mentioned in: Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

(12 mentioned in)

Activity

People

Assignee:: Richard Lau

Reporter:: Saurabh Bhatia

Votes:: 40 Vote for this issue

Watchers:: 55 Start watching this issue

Dates

Created:: 18/Jan/2023 1:51 PM

Updated:: 29/Sep/2023 2:27 AM

Resolved:: 22/Feb/2023 5:48 AM