Bug #55964 Small race condition in output log writing

• Submitted: 13 Aug 2010 6:50
• Modified: 13 Aug 2010 7:30
• Reporter: Hartmut Holzgraefe
• Status: Verified
• Category: MySQL Cluster: Cluster (NDB) storage engine
• Severity: S3 (Non-critical)
• Version: mysql-5.1-telco-6.3
• OS: Any
• CPU Architecture: Any
• Tags: ALL, mysql-cluster-7.1

[13 Aug 2010 6:50] Hartmut Holzgraefe

Description:
While looking at a nbd_*_out.log file written by a starting ndbmtd process i stumbled across the following pattern a lot:

  RESTORE table: 76 0 rows applied
  RESTORE table: 77 0 rows appliedRESTORE table: 77 0 rows applied

  RESTORE table: 76 0 rows applied

As the incident these logs were related to was about a potentially corrupted storage device i first thought this might be a potential sign of such corruption.
But on a closer look: why would it always only affect newlines?

Turns out that ndbout_c() essentially uses

  ndbout << buf << endl;

to write out log messages after formatting them.
Using the << operator to append the newline leads
to buf and endl being written by two distinct
write() system calls, and there is a window 
of opportunity for other threads to write to the
same file between these two, and that's exactly
what is happening in the log snippet above.

How to repeat:
See ndbout_c() and friends in ndb/src/common/util/NdbOut.cpp

Suggested fix:
Attach a \n to the generated messager buffer buf the C way, then just use "ndbout << buf" to print that buffer to the log file in one go.

[13 Aug 2010 7:30] Hartmut Holzgraefe

proposed patch

Attachment: bug55964.patch (text/x-patch), 927 bytes.

[13 Aug 2010 7:30] Hartmut Holzgraefe

=== modified file 'storage/ndb/src/common/util/NdbOut.cpp'
--- storage/ndb/src/common/util/NdbOut.cpp	2010-01-18 19:20:01 +0000
+++ storage/ndb/src/common/util/NdbOut.cpp	2010-08-13 07:26:45 +0000
@@ -128,9 +128,13 @@
   char buf[1000];
   
   va_start(ap, fmt);
-  if (fmt != 0)
-    BaseString::vsnprintf(buf, sizeof(buf)-1, fmt, ap);
-  *this << buf << endl;
+  *buf = '\0';  
+  if (fmt != 0) {
+    int len = BaseString::vsnprintf(buf, sizeof(buf)-1, fmt, ap);
+    buf[len] = '\n';
+    buf[len+1] = '\0';
+  }
+  *this << buf;
   va_end(ap);
 }
 
@@ -138,12 +142,15 @@
 void 
 vndbout_c(const char * fmt, va_list ap){
   char buf[1000];
-  
+
+  *buf = '\0';  
   if (fmt != 0)
   {
-    BaseString::vsnprintf(buf, sizeof(buf)-1, fmt, ap);
+    int len = BaseString::vsnprintf(buf, sizeof(buf)-1, fmt, ap);
+    buf[len] = '\n';
+    buf[len+1] = '\0';
   }
-  ndbout << buf << endl;
+  ndbout << buf;
 }
 
 extern "C"