Bug #33872 log events cut after 94 characters for important info events

• Submitted: 14 Jan 2008 20:27
• Modified: 5 May 2009 7:25
• Reporter: Bernd Ocklin
• Status: Verified
• Category: MySQL Cluster: Cluster (NDB) storage engine
• Severity: S3 (Non-critical)
• Version: mysql-5.1-telco-6.2
• OS: Any
• CPU Architecture: Any
• Tags: 5.1.23 ndb-6.2.10

[14 Jan 2008 20:27] Bernd Ocklin

Description:
Relevant strings in info events are cut off in the cluster log:

"Connection attempt from api or mysqld id=5 with mysql-5.1.15 ndb-6.1.23
incompatible with mysql" 

is actually coded to write

"Connection attempt from api or mysqld id=5 with mysql-5.1.15 ndb-6.1.23
incompatible with mysql-5.1.23 ndb-6.2.10: micro gcp enabled"

How to repeat:
Try to e.g. connect with a ndb 6.1.23 mysqld to a ndb 6.2.10 having micro gcps enabled. Check cluster log.

Suggested fix:
Make longer log events possible or place important information up front.

[18 Jul 2008 11:26] Geert Vanderkelen

Still problem with MySQL Cluster 6.3bzr.

[30 Jan 2009 20:09] Hartmut Holzgraefe

suggested fix:

- the code of infoEvent() and warningEvent() differed in one line only,
  the new generalEvent() now provides the actual functionality while
  infoEvent() and warningEvent() just invoke it with different logevent
  types
- resized from SignalT<25> to SignalT<100>
- size is now a constant, no more magic numbers throughout the function
- redundant result length check removed

=== modified file 'storage/ndb/src/kernel/vm/SimulatedBlock.cpp'
--- storage/ndb/src/kernel/vm/SimulatedBlock.cpp	2008-11-19 10:13:01 +0000
+++ storage/ndb/src/kernel/vm/SimulatedBlock.cpp	2009-01-30 11:16:37 +0000
@@ -1039,25 +1039,22 @@ SimulatedBlock::progError(int line, int 
 }
 
 void 
-SimulatedBlock::infoEvent(const char * msg, ...) const {
+SimulatedBlock::generalEvent(enum Ndb_logevent_type eventType, const char * msg, ...) const {
+  const int datasize = 100;
+  
   if(msg == 0)
     return;
   
-  SignalT<25> signalT;
-  signalT.theData[0] = NDB_LE_InfoEvent;
+  SignalT<datasize> signalT;
+  signalT.theData[0] = eventType;
+  int bufsize = (datasize - 1) * sizeof(signalT.theData[0]);
   char * buf = (char *)(signalT.theData+1);
   
   va_list ap;
   va_start(ap, msg);
-  BaseString::vsnprintf(buf, 96, msg, ap); // 96 = 100 - 4
+  BaseString::vsnprintf(buf, bufsize, msg, ap); 
   va_end(ap);
   
-  int len = strlen(buf) + 1;
-  if(len > 96){
-    len = 96;
-    buf[95] = 0;
-  }
-
   /**
    * Init and put it into the job buffer
    */
@@ -1072,50 +1069,26 @@ SimulatedBlock::infoEvent(const char * m
   signalT.header.theSendersBlockRef      = reference();
   signalT.header.theTrace                = tTrace;
   signalT.header.theSignalId             = tSignalId;
-  signalT.header.theLength               = ((len+3)/4)+1;
+  signalT.header.theLength               = ((strlen(buf)+3)/4)+1;
   
   globalScheduler.execute(&signalT.header, JBB, signalT.theData,
                           signalT.m_sectionPtrI);
 }
 
 void 
-SimulatedBlock::warningEvent(const char * msg, ...) const {
-  if(msg == 0)
-    return;
-
-  SignalT<25> signalT;
-  signalT.theData[0] = NDB_LE_WarningEvent;
-  char * buf = (char *)(signalT.theData+1);
-  
+SimulatedBlock::infoEvent(const char * msg, ...) const {
   va_list ap;
   va_start(ap, msg);
-  BaseString::vsnprintf(buf, 96, msg, ap); // 96 = 100 - 4
+  generalEvent(NDB_LE_InfoEvent, msg, ap); 
   va_end(ap);
-  
-  int len = strlen(buf) + 1;
-  if(len > 96){
-    len = 96;
-    buf[95] = 0;
-  }
-
-  /**
-   * Init and put it into the job buffer
-   */
-  memset(&signalT.header, 0, sizeof(SignalHeader));
-  
-  const Signal * signal = globalScheduler.getVMSignals();
-  Uint32 tTrace = signal->header.theTrace;
-  Uint32 tSignalId = signal->header.theSignalId;
-  
-  signalT.header.theVerId_signalNumber   = GSN_EVENT_REP;
-  signalT.header.theReceiversBlockNumber = CMVMI;
-  signalT.header.theSendersBlockRef      = reference();
-  signalT.header.theTrace                = tTrace;
-  signalT.header.theSignalId             = tSignalId;
-  signalT.header.theLength               = ((len+3)/4)+1;
+}
 
-  globalScheduler.execute(&signalT.header, JBB, signalT.theData,
-                          signalT.m_sectionPtrI);
+void 
+SimulatedBlock::warningEvent(const char * msg, ...) const {
+  va_list ap;
+  va_start(ap, msg);
+  generalEvent(NDB_LE_WarningEvent, msg, ap); 
+  va_end(ap);
 }
 
 void

=== modified file 'storage/ndb/src/kernel/vm/SimulatedBlock.hpp'
--- storage/ndb/src/kernel/vm/SimulatedBlock.hpp	2008-11-19 10:13:01 +0000
+++ storage/ndb/src/kernel/vm/SimulatedBlock.hpp	2009-01-30 11:13:47 +0000
@@ -425,6 +425,8 @@ protected:
   /**
    * General info event (sent to cluster log)
    */
+  void generalEvent(enum Ndb_logevent_type eventType, const char * msg, ...) const
+    ATTRIBUTE_FORMAT(printf, 3, 4);
   void infoEvent(const char * msg, ...) const
     ATTRIBUTE_FORMAT(printf, 2, 3);
   void warningEvent(const char * msg, ...) const

[31 Jan 2009 6:21] Jonas Oreland

signals is 25 is magic, but impossible to change.
the job buffer consists of fixed-size-slots 28-byte header and 100 byte payload
100 bytes = 25 words.
this concept used to be in silicon and all our code assumes 100 bytes signal data.

in order to send bigger signals, you need to use the "newly" (as in 2002) introduced long signal interface.