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 Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Cluster: Cluster (NDB) storage engine Severity:S3 (Non-critical)
Version:mysql-5.1-telco-6.2 OS:Any
Assigned to: CPU Architecture:Any
Tags: 5.1.23 ndb-6.2.10
Triage: Triaged: D4 (Minor) / R4 (High) / E4 (High)

[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.