Repository: diennea/herddb
Issue: TableSpace recovery : Corrupted transaction, syncing on a position smaller ((1504,17371917)) than transaction last sequence number ((1504,17371917))

Is this a question, a feature request or a bug report?

- Is a bug report


**BUG REPORT**

1. Please describe the issue you observed:
During recovery of a tablespace i get this error: 
```
19-12-23-15-55-47       herddb.core.DBManager Dec 23, 2019 3:55:47 PM herddb.core.DBManager manageTableSpaces
SEVERE: cannot handle tablespace q1
herddb.log.LogNotAvailableException: java.lang.IllegalStateException: Corrupted transaction, syncing on a position smaller ((1504,17371917)) than transaction last sequence number ((1504,17371917))
        at herddb.cluster.BookkeeperCommitLog.recovery(BookkeeperCommitLog.java:502)
        at herddb.core.TableSpaceManager.recover(TableSpaceManager.java:294)
        at herddb.core.TableSpaceManager.start(TableSpaceManager.java:231)
        at herddb.core.DBManager.handleTableSpace(DBManager.java:537)
        at herddb.core.DBManager.manageTableSpaces(DBManager.java:1120)
        at herddb.core.DBManager.executeActivator(DBManager.java:1066)
        at herddb.core.DBManager.access$500(DBManager.java:113)
        at herddb.core.DBManager$Activator.run(DBManager.java:1009)
        at java.base/java.lang.Thread.run(Thread.java:830)
Caused by: java.lang.IllegalStateException: Corrupted transaction, syncing on a position smaller ((1504,17371917)) than transaction last sequence number ((1504,17371917))
        at herddb.model.Transaction.sync(Transaction.java:567)
        at herddb.core.TableSpaceManager.apply(TableSpaceManager.java:359)
        at herddb.core.TableSpaceManager$ApplyEntryOnRecovery.accept(TableSpaceManager.java:1843)
        at herddb.core.TableSpaceManager$ApplyEntryOnRecovery.accept(TableSpaceManager.java:1832)
        at herddb.cluster.BookkeeperCommitLog.recovery(BookkeeperCommitLog.java:470)
        ... 8 more
```

- What did you do?
It happened during a checkpoint.
From my observations:
The checkpint started in position (1504,17371916) and ended in position (1504,17372323).
During the checkpoint activity, however, there was an already started transaction that continued to go even during the checkpoint.
The transaction finished in position (1504,17371917).

- What did you expect to see?
I expected that before checkpoint started, all transaction are finished, and then not see a "**corrupted transaction**". 


Changed files:
herddb-core/src/main/java/herddb/log/CommitLog.java, herddb-core/src/main/java/herddb/core/TableSpaceManager.java, herddb-core/src/main/java/herddb/cluster/BookkeeperCommitLog.java

diff --git a/herddb-core/src/main/java/herddb/cluster/BookkeeperCommitLog.java b/herddb-core/src/main/java/herddb/cluster/BookkeeperCommitLog.java
index b4c3a3db..f0230270 100644
--- a/herddb-core/src/main/java/herddb/cluster/BookkeeperCommitLog.java
+++ b/herddb-core/src/main/java/herddb/cluster/BookkeeperCommitLog.java
@@ -298,12 +298,19 @@ public class BookkeeperCommitLog extends CommitLog {
                         }
                     }
             );
-            res.thenAccept((pos) -> {
+            // publish the lastSequenceNumber
+            // we must return a new CompletableFuture that completes only
+            // AFTER lastSequenceNumber is updated
+            // otherwise while doing a checkpoint we could observe
+            // an old value for lastSequenceNumber
+            // in case of a slow system
+            res = res.thenApply((pos) -> {
                         if (lastLedgerId == pos.ledgerId) {
                             lastSequenceNumber.accumulateAndGet(pos.offset,
                                     EnsureLongIncrementAccumulator.INSTANCE);
                         }
                         notifyListeners(pos, edit);
+                        return pos;
                     }
             );
         }
diff --git a/herddb-core/src/main/java/herddb/core/TableSpaceManager.java b/herddb-core/src/main/java/herddb/core/TableSpaceManager.java
index 77543882..99338778 100644
--- a/herddb-core/src/main/java/herddb/core/TableSpaceManager.java
+++ b/herddb-core/src/main/java/herddb/core/TableSpaceManager.java
@@ -267,7 +267,7 @@ public class TableSpaceManager {
         }
         dataStorageManager.loadTransactions(logSequenceNumber, tableSpaceUUID, t -> {
             transactions.put(t.transactionId, t);
-            LOGGER.log(Level.FINER, "{0} {1} tx {2} at boot", new Object[]{nodeId, tableSpaceName, t.transactionId});
+            LOGGER.log(Level.FINER, "{0} {1} tx {2} at boot lsn {3}", new Object[]{nodeId, tableSpaceName, t.transactionId, t.lastSequenceNumber});
             try {
                 if (t.newTables != null) {
                     for (Table table : t.newTables.values()) {
@@ -1632,7 +1632,14 @@ public class TableSpaceManager {
                     throw new DataStorageManagerException("actualLogSequenceNumber cannot be null");
                 }
                 // TODO: transactions checkpoint is not atomic
-                actions.addAll(dataStorageManager.writeTransactionsAtCheckpoint(tableSpaceUUID, logSequenceNumber, new ArrayList<>(transactions.values())));
+                Collection<Transaction> currentTransactions = new ArrayList<>(transactions.values());
+                for (Transaction t : currentTransactions) {
+                    LogSequenceNumber txLsn = t.lastSequenceNumber;
+                    if (txLsn != null && txLsn.after(logSequenceNumber)) {
+                        LOGGER.log(Level.SEVERE, "Found transaction {0} with LSN {1} in the future", new Object[]{t.transactionId, txLsn});
+                    }
+                }
+                actions.addAll(dataStorageManager.writeTransactionsAtCheckpoint(tableSpaceUUID, logSequenceNumber, currentTransactions));
                 actions.addAll(writeTablesOnDataStorageManager(new CommitLogResult(logSequenceNumber, false, true), true));
 
                 // we checkpoint all data to disk and save the actual log sequence number
diff --git a/herddb-core/src/main/java/herddb/log/CommitLog.java b/herddb-core/src/main/java/herddb/log/CommitLog.java
index 9c64dc09..7e6a451c 100644
--- a/herddb-core/src/main/java/herddb/log/CommitLog.java
+++ b/herddb-core/src/main/java/herddb/log/CommitLog.java
@@ -87,7 +87,7 @@ public abstract class CommitLog implements AutoCloseable {
     protected synchronized void notifyListeners(LogSequenceNumber logPos, LogEntry edit) {
         if (listeners != null) {
             for (CommitLogListener l : listeners) {
-                LOG.log(Level.SEVERE, "notifyListeners {0}, {1}", new Object[]{logPos, edit});
+                LOG.log(Level.INFO, "notifyListeners {0}, {1}", new Object[]{logPos, edit});
                 l.logEntry(logPos, edit);
             }
         }