Bug#37524092 Improve Api Failure handling logs + limit duration

7.6 backport

Improve observability of API failure handling stall

 - QMGR signals blocks yet to complete API failure handling
   to dump block internal API failure handling state
 - TC enhanced to
   - Track + dump API failure handling sub-state
   - Dump info about remaining transactions to be handled
   - Include TC instance number in generated logs
   - Also dump to node log in cases where truncation may
     occur in cluster log

Change-Id: I20c96ba9081610abd4c4f9696bada496b8f4c1ba

Author: frazerclement

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

@@ -1,4 +1,4 @@
-# Copyright (c) 2003, 2024, Oracle and/or its affiliates.
+# Copyright (c) 2003, 2025, Oracle and/or its affiliates.
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License, version 2.0,
@@ -29,7 +29,7 @@ Next DBTUP 4040
 Next DBLQH 5113
 Next DBDICT 6227
 Next DBDIH 7251
-Next DBTC 8125
+Next DBTC 8127
 Next TRPMAN 9007
 Next CMVMI 9993              Note: CMVMI grows downwards
 Next BACKUP 10057

storage/ndb/src/kernel/blocks/dbtc/Dbtc.hpp

@@ -1,5 +1,5 @@
 /*
-   Copyright (c) 2003, 2024, Oracle and/or its affiliates.
+   Copyright (c) 2003, 2025, Oracle and/or its affiliates.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License, version 2.0,
@@ -1210,6 +1210,16 @@ class Dbtc
 
     Uint32 m_location_domain_id;
 
+    /* Discrete states of API failure handling for logs etc */
+    enum ApiFailStates {
+      AF_IDLE,
+      AF_CHECK_TRANS,
+      AF_CHECK_MARKERS,
+      AF_CHECK_MARKERS_WAIT_TC_TAKEOVER,
+      AF_CHECK_MARKERS_WAIT_TRANS
+    };
+    Uint32 m_af_state;
+    /* Independent steps of Data node failure handling */
     enum NodeFailBits
     {
       NF_TAKEOVER          = 0x1,
@@ -1218,7 +1228,7 @@ class Dbtc
       NF_BLOCK_HANDLE      = 0x8,
       NF_NODE_FAIL_BITS    = 0xF // All bits...
     };
-    Uint32 m_nf_bits;
+    Uint32 m_nf_bits; /* Node fail handling state */
     NdbNodeBitmask m_lqh_trans_conf;
     /**
      * Indicator if any history to track yet

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

@@ -1,4 +1,4 @@
-/* Copyright (c) 2003, 2024, Oracle and/or its affiliates.
+/* Copyright (c) 2003, 2025, Oracle and/or its affiliates.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License, version 2.0,
@@ -1219,6 +1219,7 @@ void Dbtc::execAPI_FAILREQ(Signal* signal)
    **************************************************************************/
   jamEntry();  
 
+  const Uint32 apiNodeId = signal->theData[0];
   if (ERROR_INSERTED(8056))
   {
     CLEAR_ERROR_INSERT_VALUE;
@@ -1227,15 +1228,16 @@ void Dbtc::execAPI_FAILREQ(Signal* signal)
 #ifdef ERROR_INSERT
   if (ERROR_INSERTED(8078))
   {
-    c_lastFailedApi = signal->theData[0];
+    c_lastFailedApi = apiNodeId;
     SET_ERROR_INSERT_VALUE(8079);
   }
 #endif
 
   capiFailRef = signal->theData[1];
-  arrGuard(signal->theData[0], MAX_NODES);
-  capiConnectClosing[signal->theData[0]] = 1;
-  handleFailedApiNode(signal, signal->theData[0], (UintR)0);
+
+  arrGuard(apiNodeId, MAX_NODES);
+  capiConnectClosing[apiNodeId] = 1;
+  handleFailedApiNode(signal, apiNodeId, (UintR)0);
 }
 
 /**
@@ -1425,8 +1427,13 @@ Dbtc::handleFailedApiNode(Signal* signal,
 {
   UintR TloopCount = 0;
   arrGuard(TapiFailedNode, MAX_NODES);
+  hostptr.i = TapiFailedNode;
+  ptrCheckGuard(hostptr, chostFilesize, hostRecord);
+  /* Mark progress */
+  hostptr.p->m_af_state = HostRecord::AF_CHECK_TRANS;
   apiConnectptr.i = TapiConnectPtr;
-  do {
+  while (TloopCount++ <= 256 && !ERROR_INSERTED(8125))
+  {
     ptrCheckGuard(apiConnectptr, capiConnectFilesize, apiConnectRecord);
     const UintR TapiNode = refToNode(apiConnectptr.p->ndbapiBlockref);
     if (TapiNode == TapiFailedNode)
@@ -1456,7 +1463,7 @@ Dbtc::handleFailedApiNode(Signal* signal,
       removeMarkerForFailedAPI(signal, TapiFailedNode, 0);
       return;
     }//if
-  } while (TloopCount++ < 256);
+  }
   signal->theData[0] = TcContinueB::ZHANDLE_FAILED_API_NODE;
   signal->theData[1] = TapiFailedNode;
   signal->theData[2] = apiConnectptr.i;
@@ -1471,8 +1478,16 @@ Dbtc::removeMarkerForFailedAPI(Signal* signal,
   TcFailRecordPtr node_fail_ptr;
   node_fail_ptr.i = 0;
   ptrAss(node_fail_ptr, tcFailRecord);
-  if(node_fail_ptr.p->failStatus != FS_IDLE) {
+  HostRecordPtr myHostPtr;
+  myHostPtr.i = nodeId;
+  ptrCheckGuard(myHostPtr, chostFilesize, hostRecord);
+  /* Mark progress */
+  myHostPtr.p->m_af_state = HostRecord::AF_CHECK_MARKERS;
+
+  if(node_fail_ptr.p->failStatus != FS_IDLE || ERROR_INSERTED(8126)) {
     jam();
+    /* Mark progress */
+    myHostPtr.p->m_af_state = HostRecord::AF_CHECK_MARKERS_WAIT_TC_TAKEOVER;
     DEBUG("Restarting removeMarkerForFailedAPI");
     /**
      * TC take-over in progress
@@ -1501,6 +1516,8 @@ Dbtc::removeMarkerForFailedAPI(Signal* signal,
       capiConnectClosing[nodeId]--;
       if (capiConnectClosing[nodeId] == 0) {
         jam();
+        /* Mark progress */
+        myHostPtr.p->m_af_state = HostRecord::AF_IDLE;
 
         /********************************************************************/
         // No outstanding ABORT or COMMIT's of this failed API node. 
@@ -1538,6 +1555,9 @@ Dbtc::removeMarkerForFailedAPI(Signal* signal,
          *
          * Don't remove it, but continueb retry with a short delay
          */
+        /* Mark progress */
+        myHostPtr.p->m_af_state = HostRecord::AF_CHECK_MARKERS_WAIT_TRANS;
+
         signal->theData[0] = TcContinueB::ZHANDLE_FAILED_API_NODE_REMOVE_MARKERS;
         signal->theData[1] = nodeId;
         signal->theData[2] = iter.bucket;
@@ -1588,6 +1608,11 @@ void Dbtc::handleApiFailState(Signal* signal, UintR TapiConnectptr)
     {
       jam();
 
+      /* Mark progress */
+      hostptr.i = TfailedApiNode;
+      ptrCheckGuard(hostptr, chostFilesize, hostRecord);
+      hostptr.p->m_af_state = HostRecord::AF_IDLE;
+
       /**
        * Perform block-level cleanups (e.g assembleFragments...)
        */
@@ -15343,6 +15368,7 @@ void Dbtc::inithost(Signal* signal)
       container->noOfPackedWords = 0;
       container->hostBlockRef = numberToRef(DBLQH, i, hostptr.i);
     }
+    hostptr.p->m_af_state = HostRecord::AF_IDLE;
     hostptr.p->m_nf_bits = 0;
   }//for
   c_alive_nodes.clear();
@@ -16617,7 +16643,7 @@ Dbtc::execDUMP_STATE_ORD(Signal* signal)
     if (len + 2 > 25)
     {
       jam();
-      infoEvent("Too long filter");
+      infoEvent("DBTC %u: Too long filter", instance());
       return;
     }
     if (validate_filter(signal))
@@ -16628,7 +16654,7 @@ Dbtc::execDUMP_STATE_ORD(Signal* signal)
       signal->theData[1] = 0;    // record
       sendSignal(reference(), GSN_DUMP_STATE_ORD, signal, len + 2, JBB);
 
-      infoEvent("Starting dump of transactions");
+      infoEvent("DBTC %u: Starting dump of transactions", instance());
     }
     return;
   }
@@ -16663,7 +16689,7 @@ Dbtc::execDUMP_STATE_ORD(Signal* signal)
     if (ap.i == capiConnectFilesize)
     {
       jam();
-      infoEvent("End of transaction dump");
+      infoEvent("DBTC %u: End of transaction dump", instance());
       return;
     }
 
@@ -16695,12 +16721,30 @@ Dbtc::execDUMP_STATE_ORD(Signal* signal)
     NodeId nodeId = signal->theData[1];
     if (nodeId < MAX_NODES && nodeId < NDB_ARRAY_SIZE(capiConnectClosing))
     {
-      warningEvent(" DBTC: capiConnectClosing[%u]: %u",
-                   nodeId, capiConnectClosing[nodeId]);
+      if (getNodeInfo(nodeId).getType() == NODE_TYPE_API) {
+        jam();
+        hostptr.i = nodeId;
+        ptrCheckGuard(hostptr, chostFilesize, hostRecord);
+        warningEvent(" DBTC %u: capiConnectClosing[%u]: %u", instance(), nodeId,
+                     capiConnectClosing[nodeId]);
+        warningEvent(" DBTC %u: apiFailState[%u]: %u", instance(), nodeId,
+                     hostptr.p->m_af_state);
+
+        if (capiConnectClosing[nodeId] > 0) {
+          jam();
+          /* Dump all transactions with given nodeid as client */
+          signal->theData[0] = 2550;
+          signal->theData[1] = 1;
+          signal->theData[2] = nodeId;
+          sendSignal(reference(), GSN_DUMP_STATE_ORD, signal, 3, JBB);
+        }
+      }
+      // Could add more info for Data node failure handling delay
     }
     else
     {
-      warningEvent(" DBTC: dump-%u to unknown node: %u", arg, nodeId);
+      warningEvent(" DBTC %u: dump-%u to unknown node: %u", instance(), arg,
+                   nodeId);
     }
   }
 
@@ -17268,19 +17312,18 @@ Dbtc::match_and_print(Signal* signal, ApiConnectRecordPtr apiPtr)
     break;
   }
 
-  char buf[100];
-  BaseString::snprintf(buf, sizeof(buf),
-		       "TRX[%u]: API: %d(0x%x)"
-		       "transid: 0x%x 0x%x inactive: %u(%d) state: %s",
-		       apiPtr.i,
-		       refToNode(apiPtr.p->ndbapiBlockref),
-		       refToBlock(apiPtr.p->ndbapiBlockref),
-		       apiPtr.p->transid[0],
-		       apiPtr.p->transid[1],
-		       apiTimer ? (ctcTimer - apiTimer) / 100 : 0,
-		       c_apiConTimer_line[apiPtr.i],
-		       stateptr);
+  char buf[150];
+  BaseString::snprintf(
+      buf, sizeof(buf),
+      "DBTC %u TRX[%u] API %d(0x%x)"
+      "trid 0x%x 0x%x inact %u(%d) state %s nodes %s",
+      instance(), apiPtr.i, refToNode(apiPtr.p->ndbapiBlockref),
+      refToBlock(apiPtr.p->ndbapiBlockref), apiPtr.p->transid[0],
+      apiPtr.p->transid[1], apiTimer ? (ctcTimer - apiTimer) / 100 : 0,
+      c_apiConTimer_line[apiPtr.i], stateptr,
+      BaseString::getPrettyText(apiPtr.p->m_transaction_nodes).c_str());
   infoEvent("%s", buf);
+  g_eventLogger->info("%s", buf);
 
   memcpy(signal->theData, temp, 4*len);
   return true;

storage/ndb/src/kernel/blocks/qmgr/QmgrMain.cpp

@@ -1,5 +1,5 @@
 /*
-   Copyright (c) 2003, 2023, Oracle and/or its affiliates.
+   Copyright (c) 2003, 2025, Oracle and/or its affiliates.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License, version 2.0,
@@ -3188,6 +3188,18 @@ void Qmgr::checkStartInterface(Signal* signal, NDB_TICKS now)
                                    nodePtr.p->m_failconf_blocks[3],
                                    nodePtr.p->m_failconf_blocks[4]);
               warningEvent("%s", buf);
+
+              /* Ask delayed block(s) to explain themselves */
+              for (Uint32 i = 0;
+                   i < NDB_ARRAY_SIZE(nodePtr.p->m_failconf_blocks); i++) {
+                if (nodePtr.p->m_failconf_blocks[i] != 0) {
+                  signal->theData[0] = DumpStateOrd::DihTcSumaNodeFailCompleted;
+                  signal->theData[1] = nodePtr.i;
+                  const Uint32 dstRef =
+                      numberToRef(nodePtr.p->m_failconf_blocks[i], 0);
+                  sendSignal(dstRef, GSN_DUMP_STATE_ORD, signal, 2, JBB);
+                }
+              }
             }
           }
 	}