Bug#36028828 testNodeRestart -n MixedReadUpdateScan failures

Testcase failure exposed regression from fix to
  Bug#22602898 NDB : CURIOUS STATE OF TC COMMIT_SENT / COMPLETE_SENT TIMEOUT HANDLING

Node failure handling in TC performs 1 pass through the local active
transactions to find those affected by a node failure.

In this pass, all transactions affected by the node failure are queued
for processing, e.g. rollback, commit, complete, via e.g. the serial
abort/commit or complete protocols.

The exceptions are transactions in transient internal states such as
CS_PREPARE_TO_COMMIT, CS_COMMITTING, CS_COMPLETING, which are then followed
by stable 'wait' states such as CS_COMMIT_SENT, CS_COMPLETE_SENT.
Transactions in these states were handled by doing nothing in the node failure
handling pass, and relying on the timeout handling in the subsequent
stable states to queue transactions for processing.

The fix to Bug#22602898 removed this stable state handling to avoid it
accidentally triggering, but also stopped it from triggering when needed
in this case where node failure handling found a transaction in a transient
state.

This is solved by modifying the CS_COMMIT_SENT and CS_COMPLETE_SENT stable
state handling to also perform node failure processing if a timeout has
occurred for a transaction with a failure number different to the current
latest failure number.

This ensures that all transactions involving the failed node are handled
eventually.

A new testcase testNodeRestart -n TransientStatesNF T1 is added to the
AT testsuite to give coverage.

Change-Id: I0c0d4b6f75a97a3a7ff892cc4eafd2351491a8ff

Author: frazerclement

storage/ndb/src/kernel/blocks/ERROR_codes.txt

@@ -28,7 +28,7 @@ Next DBTUP 4039
 Next DBLQH 5112
 Next DBDICT 6223
 Next DBDIH 7251
-Next DBTC 8123
+Next DBTC 8124
 Next CMVMI 9000
 Next TRPMAN 9501
 Next BACKUP 10057

storage/ndb/src/kernel/blocks/dbtc/DbtcMain.cpp

@@ -6081,8 +6081,10 @@ void Dbtc::commit020Lab(Signal *signal,
     Tcount += sendCommitLqh(signal, localTcConnectptr.p, apiConnectptr.p);
 
     if (tcConList.next(localTcConnectptr)) {
-      if (Tcount < 16 && !(ERROR_INSERTED(8057) || ERROR_INSERTED(8073) ||
-                           ERROR_INSERTED(8089))) {
+      if (Tcount < 16 &&
+          !(ERROR_INSERTED(8057) || ERROR_INSERTED(8073) ||
+            ERROR_INSERTED(8089) ||
+            (ERROR_INSERTED(8123) && ((apiConnectptr.i & 0x1) == 0)))) {
         jam();
         continue;
       } else {
@@ -6101,7 +6103,7 @@ void Dbtc::commit020Lab(Signal *signal,
         signal->theData[0] = TcContinueB::ZSEND_COMMIT_LOOP;
         signal->theData[1] = apiConnectptr.i;
         signal->theData[2] = localTcConnectptr.i;
-        if (ERROR_INSERTED(8089)) {
+        if (ERROR_INSERTED(8089) || ERROR_INSERTED(8123)) {
           sendSignalWithDelay(cownref, GSN_CONTINUEB, signal, 100, 3);
           return;
         }
@@ -6513,7 +6515,8 @@ void Dbtc::complete010Lab(Signal *signal,
     /* ************ */
     Tcount += sendCompleteLqh(signal, localTcConnectptr.p, apiConnectptr.p);
     if (tcConList.next(localTcConnectptr)) {
-      if (Tcount < 16 && !ERROR_INSERTED(8112)) {
+      if (Tcount < 16 && !ERROR_INSERTED(8112) &&
+          !(ERROR_INSERTED(8123) && ((apiConnectptr.i & 0x1) != 0))) {
         jamDebug();
         continue;
       } else {
@@ -6525,7 +6528,7 @@ void Dbtc::complete010Lab(Signal *signal,
         signal->theData[0] = TcContinueB::ZSEND_COMPLETE_LOOP;
         signal->theData[1] = apiConnectptr.i;
         signal->theData[2] = localTcConnectptr.i;
-        if (ERROR_INSERTED(8112)) {
+        if (ERROR_INSERTED(8112) || ERROR_INSERTED(8123)) {
           sendSignalWithDelay(cownref, GSN_CONTINUEB, signal, 100, 3);
           return;
         }
@@ -8995,7 +8998,8 @@ void Dbtc::timeOutFoundLab(Signal *signal, Uint32 TapiConPtr, Uint32 errCode) {
       /* or more LQH instances.  We cannot speed this up.                 */
       /* Only in confirmed node failure situations do we take action.     */
       /*------------------------------------------------------------------*/
-      if (errCode == ZNODEFAIL_BEFORE_COMMIT) {
+      if (errCode == ZNODEFAIL_BEFORE_COMMIT ||
+          apiConnectptr.p->failureNr != cfailure_nr) {
         jam();
         /**
          * Node failure handling, switch to serial commit handling
@@ -9022,7 +9026,8 @@ void Dbtc::timeOutFoundLab(Signal *signal, Uint32 TapiConPtr, Uint32 errCode) {
       /* or more LQH instances.  We cannot speed this up.                   */
       /* Only in confirmed node failure situations do we take action.       */
       /*--------------------------------------------------------------------*/
-      if (errCode == ZNODEFAIL_BEFORE_COMMIT) {
+      if (errCode == ZNODEFAIL_BEFORE_COMMIT ||
+          apiConnectptr.p->failureNr != cfailure_nr) {
         jam();
         /**
          * Node failure handling, switch to serial complete handling

storage/ndb/test/ndbapi/testNodeRestart.cpp

@@ -65,14 +65,15 @@ static int changeStartPartitionedTimeout(NDBT_Context *ctx, NDBT_Step *step) {
     g_err << "Setting StartPartitionedTimeout to " << startPartitionedTimeout
           << endl;
     ConfigValues::Iterator iter(conf.m_configuration->m_config_values);
-    for(int idx=0; iter.openSection(CFG_SECTION_NODE, idx); idx++) {
+    for (int idx = 0; iter.openSection(CFG_SECTION_NODE, idx); idx++) {
       Uint32 oldValue = 0;
       if (iter.get(CFG_DB_START_PARTITION_TIMEOUT, oldValue)) {
         if (defaultValue == Uint32(~0)) {
           defaultValue = oldValue;
         } else if (oldValue != defaultValue) {
           g_err << "StartPartitionedTimeout is not consistent across data node"
-                   "sections" << endl;
+                   "sections"
+                << endl;
           break;
         }
       }
@@ -2832,7 +2833,8 @@ int runCreateBigTable(NDBT_Context *ctx, NDBT_Step *step) {
   do {
     hugoTrans.loadTableStartFrom(GETNDB(step), cnt, 10000);
     cnt += 10000;
-  } while (cnt < rows && (NdbTick_CurrentMillisecond() - now) < 180000);  // 180s
+  } while (cnt < rows &&
+           (NdbTick_CurrentMillisecond() - now) < 180000);  // 180s
   ndbout_c("Loaded %u rows in %llums", cnt, NdbTick_CurrentMillisecond() - now);
 
   return NDBT_OK;
@@ -7870,10 +7872,10 @@ int run_PLCP_many_parts(NDBT_Context *ctx, NDBT_Step *step) {
   }
   ConfigValues::Iterator iter(conf.m_configuration->m_config_values);
   Uint32 enabledPartialLCP = 1;
-  for(int idx=0; iter.openSection(CFG_SECTION_NODE, idx); idx++) {
-    Uint32 nodeId=0;
-    if(iter.get(CFG_NODE_ID, &nodeId)) {
-      if(nodeId == (Uint32) node_1) {
+  for (int idx = 0; iter.openSection(CFG_SECTION_NODE, idx); idx++) {
+    Uint32 nodeId = 0;
+    if (iter.get(CFG_NODE_ID, &nodeId)) {
+      if (nodeId == (Uint32)node_1) {
         iter.get(CFG_DB_ENABLE_PARTIAL_LCP, &enabledPartialLCP);
         iter.closeSection();
         break;
@@ -7882,8 +7884,7 @@ int run_PLCP_many_parts(NDBT_Context *ctx, NDBT_Step *step) {
     iter.closeSection();
   }
 
-  if (enabledPartialLCP == 0)
-  {
+  if (enabledPartialLCP == 0) {
     g_err << "[SKIPPED] Test skipped. Needs EnablePartialLcp=1" << endl;
     iter.closeSection();
     return NDBT_SKIPPED;
@@ -9456,7 +9457,8 @@ int runTestStallTimeoutAndNF(NDBT_Context *ctx, NDBT_Step *step) {
 
       CHECK(hugoOps.startTransaction(pNdb, rowNum) == 0,
             "Start transaction failed");
-      CHECK(hugoOps.pkUpdateRecord(pNdb, rowNum, 1) == 0, "Define Update failed");
+      CHECK(hugoOps.pkUpdateRecord(pNdb, rowNum, 1) == 0,
+            "Define Update failed");
       CHECK(hugoOps.execute_NoCommit(pNdb) == 0, "Execute NoCommit failed");
 
       NdbTransaction *trans = hugoOps.getTransaction();
@@ -9534,8 +9536,7 @@ int runTestStallTimeoutAndNF(NDBT_Context *ctx, NDBT_Step *step) {
 
       if (trans->getNdbError().code != 0) {
         ndbout_c("Got unexpected failure code : %u : %s",
-                 trans->getNdbError().code,
-                 trans->getNdbError().message);
+                 trans->getNdbError().code, trans->getNdbError().message);
         return NDBT_FAILED;
       }
 
@@ -9557,6 +9558,86 @@ int runTestStallTimeoutAndNF(NDBT_Context *ctx, NDBT_Step *step) {
   return NDBT_OK;
 }
 
+int runLargeLockingReads(NDBT_Context *ctx, NDBT_Step *step) {
+  int result = NDBT_OK;
+  int readsize = MIN(100, ctx->getNumRecords());
+  int i = 0;
+  HugoTransactions hugoTrans(*ctx->getTab());
+  while (ctx->isTestStopped() == false) {
+    g_info << i << ": ";
+    if (hugoTrans.pkReadRecords(GETNDB(step), readsize, readsize,
+                                NdbOperation::LM_Read) != 0) {
+      return NDBT_FAILED;
+    }
+    i++;
+  }
+  return result;
+}
+
+int runRestartsWithSlowCommitComplete(NDBT_Context *ctx, NDBT_Step *step) {
+  int result = NDBT_OK;
+  NdbRestarter restarter;
+  const int numRestarts = 4;
+
+  if (restarter.getNumDbNodes() < 2) {
+    g_err << "Too few nodes" << endl;
+    ctx->stopTest();
+    return NDBT_SKIPPED;
+  }
+
+  for (int i = 0; i < numRestarts && !ctx->isTestStopped(); i++) {
+    int errorCode = 8123;  // Slow commit and complete sending at TC
+    ndbout << "Injecting error " << errorCode << " for slow commits + completes"
+           << endl;
+    restarter.insertErrorInAllNodes(errorCode);
+
+    /* Give some time for things to get stuck in slowness */
+    NdbSleep_MilliSleep(1000);
+
+    const int id = restarter.getNode(NdbRestarter::NS_RANDOM);
+    ndbout << "Restart node " << id << endl;
+
+    if (restarter.restartOneDbNode(id, false, true, true) != 0) {
+      g_err << "Failed to restart Db node" << endl;
+      result = NDBT_FAILED;
+      break;
+    }
+
+    if (restarter.waitNodesNoStart(&id, 1)) {
+      g_err << "Failed to waitNodesNoStart" << endl;
+      result = NDBT_FAILED;
+      break;
+    }
+
+    restarter.insertErrorInAllNodes(0);
+
+    if (restarter.startNodes(&id, 1)) {
+      g_err << "Failed to start node" << endl;
+      result = NDBT_FAILED;
+      break;
+    }
+
+    if (restarter.waitClusterStarted() != 0) {
+      g_err << "Cluster failed to start" << endl;
+      result = NDBT_FAILED;
+      break;
+    }
+
+    /* Ensure connected */
+    if (GETNDB(step)->get_ndb_cluster_connection().wait_until_ready(30, 30) !=
+        0) {
+      g_err << "Timeout waiting for NdbApi reconnect" << endl;
+      result = NDBT_FAILED;
+      break;
+    }
+  }
+
+  restarter.insertErrorInAllNodes(0);
+  ctx->stopTest();
+
+  return result;
+}
+
 NDBT_TESTSUITE(testNodeRestart);
 TESTCASE("NoLoad",
          "Test that one node at a time can be stopped and then restarted "
@@ -10329,6 +10410,13 @@ TESTCASE("TransStallTimeoutNF", "") {
   STEP(runTestStallTimeoutAndNF);
   FINALIZER(runClearTable);
 }
+TESTCASE("TransientStatesNF",
+         "Test node failure handling with transactions in transient states") {
+  INITIALIZER(runLoadTable);
+  STEPS(runLargeLockingReads, 5);
+  STEP(runRestartsWithSlowCommitComplete);
+  FINALIZER(runClearTable);
+}
 NDBT_TESTSUITE_END(testNodeRestart)
 
 int main(int argc, const char **argv) {

storage/ndb/test/run-test/daily-devel--07-tests.txt

@@ -324,3 +324,7 @@ cmd: test_event
 args: -n SubscribeEventsNRAF T1
 max-time: 240
 
+cmd: testNodeRestart
+args: -n TransientStatesNF T1
+max-time: 360
+