Bug#36218231 NdbApi logging cleanup

General cleanup

 - Use g_eventLogger for events that should be async / are potentially
   generated from threads delivering signals
 - Use fprintf(stderr) / Ndberr for 'pre-crash' states which should be
   flushed before process exit/abort
   Add a Timestamp and 'NDBAPI FATAL ERROR' to these occurrences.
 - Remove unnecessary logging
 - Remove non standard 'user help' logging
 - Add some more context info to async messages to understand e.g.
   - What the message is about
   - Which instance(s) it is referring to (connection id, event buffer)

Not a complete cleanup, more can be done.

Change-Id: I904435608f699401e7431bb5c68c0c5fb0bd8df1

Author: frazerclement

storage/ndb/include/logger/Logger.hpp

@@ -122,6 +122,17 @@ class Logger {
   */
   static void format_timestamp(const time_t epoch, char *str, size_t len);
 
+  // Timestamp - handy class for getting a timestamp string
+  class Timestamp {
+   public:
+    Timestamp();
+    const char *c_str() const { return buff; }
+
+   private:
+    static constexpr Uint32 TsLen = 64;
+    char buff[TsLen];
+  };
+
   /** The log levels. NOTE: Could not use the name LogLevel since
    * it caused conflicts with another class.
    */

storage/ndb/src/common/logger/Logger.cpp

@@ -394,6 +394,10 @@ void Logger::setRepeatFrequency(unsigned val) {
   m_internalLogListHandler->setRepeatFrequency(val);
 }
 
+Logger::Timestamp::Timestamp() {
+  Logger::format_timestamp(time(nullptr), buff, TsLen);
+}
+
 void Logger::format_timestamp(const time_t epoch, char *str, size_t len) {
   assert(len > 0);  // Assume buffer has size
 

storage/ndb/src/ndbapi/ClusterMgr.cpp

@@ -99,7 +99,10 @@ ClusterMgr::ClusterMgr(TransporterFacade &_facade)
 
   Uint32 ret = this->open(&theFacade, API_CLUSTERMGR);
   if (unlikely(ret == 0)) {
-    g_eventLogger->info("Failed to register ClusterMgr! ret: %d", ret);
+    fprintf(stderr,
+            "%s NDBAPI FATAL ERROR : Failed to register "
+            "ClusterMgr! ret: %d\n",
+            Logger::Timestamp().c_str(), ret);
     abort();
   }
   DBUG_VOID_RETURN;
@@ -223,10 +226,11 @@ void ClusterMgr::startThread() {
                        0,  // default stack size
                        "ndb_clustermgr", NDB_THREAD_PRIO_HIGH);
   if (theClusterMgrThread == nullptr) {
-    g_eventLogger->info(
-        "ClusterMgr::startThread:"
-        " Failed to create thread for cluster management.");
-    assert(theClusterMgrThread != nullptr);
+    fprintf(stderr,
+            "%s NDBAPI FATAL ERROR : ClusterMgr::startThread:"
+            " Failed to create thread for cluster management.\n",
+            Logger::Timestamp().c_str());
+    abort();
     DBUG_VOID_RETURN;
   }
 
@@ -904,8 +908,10 @@ void ClusterMgr::execAPI_REGREF(const Uint32 *theData) {
 
   switch (ref->errorCode) {
     case ApiRegRef::WrongType:
-      g_eventLogger->info("Node %d reports that this node should be a NDB node",
-                          nodeId);
+      fprintf(stderr,
+              "%s NDBAPI FATAL ERROR : Node %d reports that "
+              "this node %d should be an NDB node\n",
+              Logger::Timestamp().c_str(), nodeId, getOwnNodeId());
       abort();
     case ApiRegRef::UnsupportedVersion:
     default:
@@ -1462,9 +1468,11 @@ void ArbitMgr::doStart(const Uint32 *theData) {
                                0,  // default stack size
                                "ndb_arbitmgr", NDB_THREAD_PRIO_HIGH);
   if (theThread == nullptr) {
-    g_eventLogger->info(
-        "ArbitMgr::doStart: Failed to create thread for arbitration.");
-    assert(theThread != nullptr);
+    fprintf(stderr,
+            "%s NDBAPI FATAL ERROR : ArbitMgr::doStart: Failed to "
+            "create thread for arbitration.\n",
+            Logger::Timestamp().c_str());
+    abort();
   }
   NdbMutex_Unlock(theThreadMutex);
   DBUG_VOID_RETURN;

storage/ndb/src/ndbapi/Ndb.cpp

@@ -967,7 +967,7 @@ void Ndb::closeTransaction(NdbTransaction *aConnection) {
 // application behaviour.
 //-----------------------------------------------------
 #ifdef VM_TRACE
-    printf("NULL into closeTransaction\n");
+    g_eventLogger->info("Ndb::closeTransaction passed nullptr");
 #endif
     DBUG_VOID_RETURN;
   }  // if
@@ -1003,15 +1003,18 @@ void Ndb::closeTransaction(NdbTransaction *aConnection) {
            * something else...
            */
 #ifdef VM_TRACE
-          printf(
-              "Scan timeout:ed NdbTransaction-> "
-              "not returning it-> memory leak\n");
+          g_eventLogger->warning(
+              "Ndb::closeTransaction() scan time out, not "
+              "returning NdbTransaction -> memory leak");
 #endif
           DBUG_VOID_RETURN;
         }
 
 #ifdef VM_TRACE
-        printf("Non-existing transaction into closeTransaction\n");
+        fprintf(stderr,
+                "%s NDBAPI FATAL ERROR : Non-existing transaction %p "
+                "passed into closeTransaction on Ndb %p\n",
+                Logger::Timestamp().c_str(), aConnection, this);
         abort();
 #endif
         DBUG_VOID_RETURN;
@@ -1032,9 +1035,9 @@ void Ndb::closeTransaction(NdbTransaction *aConnection) {
      * to reuse. And TC crashes when the API tries to reuse it to
      * something else...
      */
-#ifdef VM_TRACE
-    printf("Con timeout:ed NdbTransaction-> not returning it-> memory leak\n");
-#endif
+    g_eventLogger->warning(
+        "Ndb::closeTransaction() passed a timed out NdbTransaction, not "
+        "returning it -> resource leak");
     DBUG_VOID_RETURN;
   }
 
@@ -1861,9 +1864,6 @@ NdbEventOperation *Ndb::getEventOperation(NdbEventOperation *tOp) {
 
 int Ndb::pollEvents2(int aMillisecondNumber, Uint64 *highestQueuedEpoch) {
   if (unlikely(aMillisecondNumber < 0)) {
-    g_eventLogger->error(
-        "Ndb::pollEvents2: negative aMillisecondNumber %d 0x%x %s",
-        aMillisecondNumber, getReference(), getNdbObjectName());
     return -1;
   }
 
@@ -1893,19 +1893,21 @@ bool Ndb::isExpectingHigherQueuedEpochs() {
 }
 
 void Ndb::printOverflowErrorAndExit() {
-  g_eventLogger->error("Ndb Event Buffer : 0x%x %s", getReference(),
-                       getNdbObjectName());
-  g_eventLogger->error("Ndb Event Buffer : Event buffer out of memory.");
-  g_eventLogger->error("Ndb Event Buffer : Fatal error.");
+  fprintf(stderr,
+          "%s NDBAPI FATAL ERROR : Ndb Event Buffer : 0x%x %s\n"
+          "Event buffer out of memory.\n",
+          Logger::Timestamp().c_str(), getReference(), getNdbObjectName());
   Uint64 maxalloc = get_eventbuf_max_alloc();
   if (maxalloc != 0) {
     // limited memory is allocated for event buffer, give recommendation
-    g_eventLogger->error(
-        "Ndb Event Buffer : Change eventbuf_max_alloc (Current max_alloc is "
-        "%llu).",
-        maxalloc);
-  }
-  g_eventLogger->error("Ndb Event Buffer : Consider using the new API.");
+    fprintf(stderr,
+            "Consider changing eventbuf_max_alloc (Current max_alloc is "
+            "%llu).\n",
+            maxalloc);
+  }
+  fprintf(stderr,
+          "Out of Memory events can be handled non fatally "
+          "using nextEvent2().\n");
   exit(-1);
 }
 
@@ -1962,11 +1964,14 @@ NdbEventOperation *Ndb::nextEvent() {
   }
 
   if (unlikely(op->isEmptyEpoch())) {
-    g_eventLogger->error(
-        "Ndb::nextEvent: Found exceptional event type "
-        "TE_EMPTY when using old event API. "
-        "Turn off empty epoch queuing by "
-        "setEventBufferQueueEmptyEpoch(false).");
+    fprintf(stderr,
+            "%s NDBAPI FATAL ERROR : Ndb::nextEvent() : Found "
+            "exceptional event type TE_EMPTY when using old "
+            "event API nextEvent() call. "
+            "Turn off empty epoch queuing by "
+            "setEventBufferQueueEmptyEpoch(false) "
+            "or use new API nextEvent2().\n",
+            Logger::Timestamp().c_str());
     exit(-1);
   }
   return op;

storage/ndb/src/ndbapi/NdbDictionaryImpl.cpp

@@ -2616,7 +2616,9 @@ int NdbDictInterface::dictSignal(NdbApiSignal *sig, LinearSectionPtr ptr[3],
     if (i > 0) {
       Uint32 t = sleep + 10 * (rand() % mod);
 #ifdef VM_TRACE
-      g_eventLogger->info("retry sleep %ums on error %u", t, m_error.code);
+      g_eventLogger->info(
+          "NdbDictionary::dictSignal() : retry sleep %ums on error %u", t,
+          m_error.code);
 #endif
       NdbSleep_MilliSleep(t);
     }
@@ -5158,8 +5160,6 @@ int NdbDictionaryImpl::createEvent(NdbEventImpl &evnt) {
     if (col_impl) {
       evnt.m_facade->addColumn(*(col_impl->m_facade));
     } else {
-      g_eventLogger->info("Attr id %u in table %s not found", evnt.m_attrIds[i],
-                          evnt.getTableName());
       m_error.code = 4713;
       ERR_RETURN(getNdbError(), -1);
     }
@@ -5361,7 +5361,6 @@ int NdbDictInterface::createEvent(NdbEventImpl &evnt, int getFlag) {
         evnt.m_tableImpl->m_version != evntConf->getTableVersion() ||
         // evnt.m_attrListBitmask != evntConf->getAttrListBitmask() ||
         evnt.mi_type != evntConf->getEventType()) {
-      g_eventLogger->info("ERROR*************");
       m_buffer.clear();
       m_tableData.clear();
       ERR_RETURN(getNdbError(), 1);
@@ -5911,9 +5910,6 @@ static int scanEventTable(Ndb *pNdb, const NdbDictionary::Table *pTab,
 
     if (retryAttempt) {
       if (retryAttempt >= retryMax) {
-        g_eventLogger->info(
-            "ERROR: has retried this operation %d times, failing!",
-            retryAttempt);
         goto error;
       }
       if (pTrans) pNdb->closeTransaction(pTrans);