enqueue() skips the corrupt-journal-position check on OpenSearch

XMLWordPrintable

    • 1
    • Severity 3 - Minor

      Issue Summary

      Affects Version: 10.2.14 (build 9422)
      Environment: Confluence Data Center, -Dsearch.platform=opensearch, OpenSearch 2.19.6, PostgreSQL. Reproduced on a 2-node production instance and on a single-node 10.2.14 lab.

      DefaultJournalManager.enqueue() performs its "journal state store is corrupt" check only when the search platform is not a shared index. OpenSearch is a shared index, so on OpenSearch the check never runs. The stored read position is still used on every read, so a position ahead of max(entry_id) causes every poll to return nothing, permanently, and with no diagnostic of any kind.

      // DefaultJournalManager.enqueue
      Long mostRecentId = null;
      if (!this.searchPlatformConfig.isSharedIndex()) {
          mostRecentId = this.journalStateStore.getMostRecentId(journalId);
      }
      long newEntryId = this.journalDao.enqueue(entry);
      LOGGER.debug("Enqueued JournalEntry: {}", entry);
      if (mostRecentId != null && newEntryId <= mostRecentId) {
          log.warn("Newly enqueued entry in journal [{}] has an ID [{}] that should have been "
                 + "higher than the journal state store's most-recent-id [{}]. it is likely that "
                 + "this node's journal state store is corrupt.", journalName, newEntryId, mostRecentId);
      }
      
      // DefaultJournalManager.processNewEntries - the position is read unconditionally
      long mostRecentId = this.journalStateStore.getMostRecentId(journalId);
      List<JournalEntry> entries = this.journalDao.findEntries(journalId, mostRecentId,
                                       this.ignoreSettings.ignoreWithinMillis, maxEntries);
      

      The condition is reached routinely in practice: restoring a database backup onto an instance with a pre-existing OpenSearch domain brings the source instance's journal entry ids while the target retains its own journal positions. Where the source sequence is behind the target's stored positions, every journal is left pointing past the restored data, and nothing reports it.

      On the reporting instance the positions were approximately 46 million ahead of the data, and site reindex and inline-task indexing were silently non-functional from 21 November 2025 until 30 September 2026, ten months with no warning in any log.

      Steps to Reproduce

      1. Install Confluence Data Center 10.2.14 with -Dsearch.platform=opensearch.
      2. Shut the node down. The node must be stopped: a running node holds the value in CachingJournalStateStore and overwrites an external edit within seconds (observed: a write accepted at _version 581 was reverted to the cached value at _version 582 roughly 15 seconds later).
      3. Set a journal read position ahead of the real maximum entry id. For system_maintenance the position is a per-node file in local home; for the index journals it is a document in the shared confluence-journal OpenSearch index.
      4. Start the node and confirm the position is in effect.
      5. Raise com.atlassian.confluence.impl.journal to DEBUG and restart. This is required: the logger ships as WARN, so without it the enqueue produces no output at all. Three further loggers ship at INFO and their absence of output is itself the evidence.
      6. Trigger an action that enqueues to the affected journal. For system_maintenance, request a site reindex; for task_report_index, add an inline task to any page.
      7. Inspect atlassian-confluence-index.log for any warning that the enqueued entry id is below the stored position, and confirm the entry's fate in journalentry.

      Commands for step 3:

      echo -n "999999999" > <confluence-local-home>/journal/system_maintenance
      
      curl -X PUT 'http://<opensearch-host>:9200/confluence-journal/_doc/task_report_index' \
           -H 'Content-Type: application/json' -d '{"id":999999999}'
      curl -X POST 'http://<opensearch-host>:9200/confluence-journal/_refresh'
      

      Logging configuration for step 5, in <confluence-install>/confluence/WEB-INF/classes/log4j.properties:

      log4j.logger.com.atlassian.confluence.impl.journal=DEBUG, indexlog
      log4j.additivity.com.atlassian.confluence.impl.journal=false
      

      The four loggers that carry the evidence:

      Logger Level required Output file Role in the reproduction
      com.atlassian.confluence.impl.journal DEBUG (ships as WARN) atlassian-confluence-index.log Emits "Enqueued JournalEntry: ...", proving the entry was written, with an id below the stored position. Without DEBUG there is no output at all.
      com.atlassian.confluence.internal.index INFO (default) atlassian-confluence-index.log DefaultReIndexJobManager, "onReIndexRequest Scheduled a job to monitor progress of rebuilding index". Confirms the request was accepted.
      com.atlassian.confluence.impl.system.runner INFO (default) atlassian-confluence.log ReIndexMaintenanceTaskRunner. On a healthy instance this logs "Performing reindexing". Its absence proves the work item was never collected.
      com.atlassian.confluence.plugins.tasklist.report.searchindex INFO (default) atlassian-confluence.log InlineTaskSearchIndexListener, "ReIndexRequestEvent received". Confirms the event was published to listeners.

      Two points that materially affect the reproduction. First, com.atlassian.confluence.impl.journal ships with additivity=false, so its output appears only in atlassian-confluence-index.log; grepping atlassian-confluence.log for the enqueue line returns nothing even when DEBUG is correctly enabled. Second, log4j.rootLogger ships as WARN, so a package with no explicit entry produces no INFO output at all. The three INFO loggers above are usable as evidence only because each is declared explicitly in the shipped file. Verified against an unmodified 10.2.14 install:

      6:   log4j.rootLogger=WARN, confluencelog, errorlog, fluentdAppender
      92:  log4j.logger.com.atlassian.confluence.internal.index=INFO, indexlog
      93:  log4j.additivity.com.atlassian.confluence.internal.index=false
      100: log4j.logger.com.atlassian.confluence.impl.journal=WARN, indexlog
      101: log4j.additivity.com.atlassian.confluence.impl.journal=false
      413: log4j.logger.com.atlassian.confluence.impl.system.runner=INFO
      569: log4j.logger.com.atlassian.confluence.plugins.tasklist.report.searchindex=INFO
      

      Before treating the absence of ReIndexMaintenanceTaskRunner output as evidence, confirm line 413 has not been lowered on the instance under test:

      grep -nE 'rootLogger|impl\.system|impl\.journal|internal\.index|tasklist' \
          <confluence-install>/confluence/WEB-INF/classes/log4j.properties
      

      That logger declares no appender, so it inherits the root appenders and its output lands in atlassian-confluence.log. Lines 92 and 100 both declare indexlog with additivity=false, so DefaultReIndexJobManager and DefaultJournalManager write only to atlassian-confluence-index.log. The two halves of the evidence are therefore in two different files.

      Verified on the 10.2.14 lab: with only com.atlassian.confluence.impl.journal raised to DEBUG and the node restarted, a single site reindex produced 13 "Enqueued JournalEntry" lines in atlassian-confluence-index.log and none in atlassian-confluence.log.

      Commands for steps 6 and 7:

      curl -u <admin> -X POST \
        'http://<host>:<port>/rest/prototype/latest/index/reindex?option=CONTENT_ONLY&option=ATTACHMENT_ONLY&option=USER_ONLY'
      
      SELECT entry_id, journal_name, creationdate, type FROM journalentry
      WHERE journal_name = 'system_maintenance' ORDER BY entry_id DESC;
      

      Expected Results

      A WARN from DefaultJournalManager identifying that the newly enqueued entry id is lower than the stored most-recent-id, as is emitted on a non-shared-index platform:

      WARN [...] [confluence.impl.journal.DefaultJournalManager] enqueue Newly enqueued entry in
      journal [task_report_index] has an ID [75426351] that should have been higher than the
      journal state store's most-recent-id [115356248]. it is likely that this node's journal
      state store is corrupt.
      

      The check does not depend on the index being local. It compares a journal entry id with a stored position, both of which exist identically on a shared-index platform.

      Actual Results

      No warning is emitted on a shared-index platform. The entry is enqueued below the stored position, is never collected, and nothing records the inconsistency.

      No exception is thrown in any log file. That is the defect. The only output produced by the enqueue is the following DEBUG line in atlassian-confluence-index.log, visible solely because DEBUG was raised deliberately. At default log levels there is no output at all:

      2026-09-27 18:28:12,125 DEBUG [http-nio-8080-exec-32 url: /rest/prototype/latest/index/reindex;
      user: <redacted>] [confluence.impl.journal.DefaultJournalManager] enqueue Enqueued
      JournalEntry: JournalEntry{id=75721691, journalId='JournalIdentifier{journalName='system_maintenance'}',
      creationDate=Sun Sep 27 18:28:12 GMT 2026, type='REINDEX',
      message='{"jobId":"1fddd489-5687-4313-b7ce-bc10701e9bf3","sourceNodeId":"123456",
      "options":["CONTENT_ONLY","ATTACHMENT_ONLY","USER_ONLY"],...}'}
      

      Observed values from the reporting instance, with the positions roughly 46 million ahead of the data:

      system_maintenance position file, node 1    121842680   (file dated 2025-11-18 23:30)
      system_maintenance position file, node 2    121842680   (file dated 2025-11-18 23:30)
      
      confluence-journal positions before reindex:
        main_index                                121934585
        change_index                              121900194
        edge_index                                121842682
        task_report_index                         121842681
      
      actual journalentry ids                     approximately 75,730,000
      stranded REINDEX entries                    75721641 - 75721691  (27 September)
      first entry collected after correction       75733376
      

      Downstream effect, all without any warning:

      • Site reindex requests created a ReIndexJob, enqueued a work item, and were never collected. The job remained at stage=REBUILDING / progress=0 indefinitely with no indexer thread, no index-log output and no timeout, while SystemMaintenanceTaskQueueFlusherScheduledJob reported Success every 10 seconds throughout, accurately, since there was nothing newer than its position to collect.
      • Content indexing was starved. A page created while the positions were ahead returned totalSize 0 from the search API and was absent from confluence-content.
      • Inline-task indexing remains starved on the reporting instance. A task saved at 14:56:34.211 wrote journalentry id 75734239 at 14:56:34.225, 14 ms later, against a stored task_report_index position of 121842681. The index behind the alias, confluence-custom-task_report_index_1763508618817, was created 2025-11-18 23:30:18, the same minute the position files were last written.
      • Uncollected work items are then deleted once they pass com.atlassian.confluence.journal.timeToLiveInMillis, after which correcting the position no longer recovers the job.

      Confirmed on a single-node 10.2.14 lab instance: with the system_maintenance position set to 999999999, a site reindex remained at REBUILDING / progress=0 for 997 seconds with its work item (entry_id 48494) sitting uncollected in journalentry, zero ReIndexMaintenanceTaskRunner lines, and no warning of any kind. Correcting the position to 0 and restarting caused the entry to be collected and the reindex to complete.

      Workaround

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

      The underlying condition can be corrected once identified, but the defect reported here is the absence of any diagnostic: there is no way to make enqueue() emit the warning it is coded to skip. Detection currently requires comparing stored positions against max(entry_id) manually. Any stored position greater than the corresponding maximum indicates the condition:

      SELECT journal_name, MAX(entry_id) FROM journalentry GROUP BY journal_name;
      
      cat <confluence-local-home>/journal/system_maintenance      # per node
      curl -s 'http://<opensearch-host>:9200/confluence-journal/_search?size=10'
      

      Suggested fix: perform the comparison regardless of platform. The stored position and the new entry id are both available on a shared-index platform, so the check requires no local index. A startup-time comparison of each journal's stored position against max(entry_id) would also surface the condition without waiting for an enqueue, and would have caught this instance on the first restart after the database restore.

      long mostRecentId = this.journalStateStore.getMostRecentId(journalId);
      long newEntryId = this.journalDao.enqueue(entry);
      if (newEntryId <= mostRecentId) {
          log.warn(...);
      }
      

              Assignee:
              Unassigned
              Reporter:
              Derek Howell
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated: