Added log order scripts and more debug output

log_manager/log_manager.cc

@@ -46,7 +46,9 @@ extern char *program_invocation_name;
 extern char *program_invocation_short_name;
 
 #if defined(SS_DEBUG) 
-static long write_index;
+static int write_index;
+static int block_start_index;
+static int block_end_index;
 #endif
 /**
  * Variable holding the enabled logfiles information.
@@ -337,6 +339,8 @@ static bool logmanager_init_nomutex(
         lm->lm_chk_top   = CHK_NUM_LOGMANAGER;
         lm->lm_chk_tail  = CHK_NUM_LOGMANAGER;
 	write_index = 0;
+	block_start_index = 0;
+	block_end_index = 0;
 #endif
         lm->lm_clientmes = skygw_message_init();
         lm->lm_logmes    = skygw_message_init();
@@ -677,6 +681,18 @@ static int logmanager_write_log(
                  * Returned timestamp_len doesn't include terminating null.
                  */
                 timestamp_len = snprint_timestamp(wp, timestamp_len);
+		
+#if defined (SS_DEBUG)
+		// int dbuglen = 0;
+		// char dbugmsg[1024];
+		// memset(dbugmsg,0,1024);
+		// sprintf(dbugmsg,"write:%d ", atomic_add(&write_index, 1));
+		// dbuglen = strlen(dbugmsg);
+		// snprintf(wp, safe_str_len,"%.*s",dbuglen,dbugmsg);
+		// timestamp_len = dbuglen;
+#endif
+
+
                 /**
                  * Write next string to overwrite terminating null character
                  * of the timestamp string.
@@ -862,10 +878,26 @@ static char* blockbuf_get_writepos(
                      * Send flush request to file writer thread. This causes
                      * flushing all buffers, and (eventually) frees buffer space.
                      */
-                    blockbuf_register(bb);
+		  blockbuf_register(bb);
-                    bb->bb_isfull = true;
+		  bb->bb_isfull = true;
+
+#if defined(SS_DEBUG)
+		  {
+		    char* tmp = (char*)calloc(128,sizeof(char));
+		    sprintf(tmp," end:%d\n",atomic_add(&block_end_index,1));
+		    memcpy(bb->bb_buf + strlen(bb->bb_buf) - strlen(tmp),tmp,strlen(tmp));
+		    free(tmp);
+		  }
+#endif
+
                     blockbuf_unregister(bb);
 
+// #if defined (SS_DEBUG)
+// 		    char temp[1024];
+// 		    sprintf(temp, " block: %d ",atomic_add(&block_start_index, 1));
+// 		    memcpy(bb->bb_buf,temp,strlen(temp));
+// #endif
+
                     /** Unlock buffer */
                     simple_mutex_unlock(&bb->bb_mutex);
 
@@ -1025,6 +1057,12 @@ static blockbuf_t* blockbuf_init(
         bb->bb_buf_left = MAX_LOGSTRLEN;
         bb->bb_buf_size = MAX_LOGSTRLEN;
 
+#if defined(SS_DEBUG)
+	sprintf(bb->bb_buf,"start:%d ",atomic_add(&block_start_index,1));
+	bb->bb_buf_used += strlen(bb->bb_buf);
+	bb->bb_buf_left -= strlen(bb->bb_buf);
+#endif
+
         CHK_BLOCKBUF(bb);
         return bb;
 }
@@ -1237,6 +1275,7 @@ int skygw_log_write(
         /**
          * Write log string to buffer and add to file write list.
          */
+
         va_start(valist, str);
         err = logmanager_write_log(id, false, true, true, len, str, valist);
         va_end(valist);
@@ -2378,13 +2417,6 @@ static void* thr_filewriter_fun(
                                                         &bb->bb_mutex,
                                                         true);
                                         }
-#if defined (SS_DEBUG)
-					if(bb->bb_buf_used > 0 && bb->bb_buf_size > 0){
-					  char tmpstr[512];
-					  sprintf(tmpstr,"filewrite:%lu\n",write_index++);
-					  memcpy(bb->bb_buf,tmpstr,strlen(tmpstr)-1);
-					}
-#endif
 					
                                         skygw_file_write(file,
                                                          (void *)bb->bb_buf,

log_manager/test/logorder.sh

@@ -0,0 +1,68 @@
+#! /bin/bash
+
+#create the logfile with flushes every seven writes
+
+rm *.log
+
+$PWD/testorder 200 0 8000
+
+STARTS=`cat skygw_err1.log |tr -s ' '|grep -a -o 'start:[[:alnum:]]\+'|cut -d ':' -f 2`
+MESSAGES=`cat skygw_err1.log |tr -s ' '|grep -a -o 'message:[[:alnum:]]\+'|cut -d ':' -f 2`
+ENDS=`cat skygw_err1.log |tr -s ' '|grep -a -o 'end:[[:alnum:]]\+'|cut -d ':' -f 2`
+
+prev=0
+error=0
+
+for i in $STARTS
+do
+    if [[ $i -le $prev ]]
+    then
+	error=1
+	echo "start mismatch: $i was after $prev."
+    fi
+done
+
+if [[ error -eq 0 ]]
+then
+    echo "Block buffer starts were in order"
+else
+    echo "Error: block buffers were written in the wrong order"
+fi
+
+prev=0
+error=0
+
+for i in $MESSAGES
+do
+    if [[ $i -le $prev ]]
+    then
+	error=1
+	echo "message mismatch: $i was after $prev."
+    fi
+done
+
+if [[ error -eq 0 ]]
+then
+    echo "Block buffer messages were in order"
+else
+    echo "Error: block buffer messages were written in the wrong order"
+fi
+
+prev=0
+error=0
+
+for i in $ENDS
+do
+    if [[ $i -le $prev ]]
+    then
+	error=1
+	echo "end mismatch: $i was after $prev."
+    fi
+done
+
+if [[ error -eq 0 ]]
+then
+    echo "Block buffer ends were in order"
+else
+    echo "Error: block buffers were written in the wrong order"
+fi

log_manager/test/testorder.c

@@ -15,6 +15,7 @@
  *
  * Copyright SkySQL Ab 2013
  */
+
 #include <unistd.h>
 #include <stdio.h>
 #include <stdlib.h>
@@ -25,18 +26,34 @@
 int main(int argc, char** argv)
 {
   int iterations = 0, i, interval = 10;
+  int block_size;
   int succp = 0, err = 0;
   char cwd[1024];
   char tmp[2048];
-  char message[1024];
+  char *message;
   char** optstr;
   long msg_index = 1;
 
   
   memset(cwd,0,1024);
-  if( argc <3 ||
+  if( argc <4){
-      getcwd(cwd,sizeof(cwd)) == NULL ||
+    fprintf(stderr,
-      (optstr = malloc(sizeof(char*)*4)) == NULL){
+	    "Log Manager Log Order Test\n"
+	    "Writes an ascending number into the error log to determine if log writes are in order.\n"
+	    "Usage:\t	testorder <iterations> <frequency of log flushes> <size of message in bytes>\n");
+    return 1;
+  }
+  
+  block_size = atoi(argv[3]);
+  if(block_size < 1){
+    fprintf(stderr,"Message size too small, must be at least 1 byte long.");
+  }
+
+
+  if(getcwd(cwd,sizeof(cwd)) == NULL ||
+     (optstr = (char**)malloc(sizeof(char*)*4)) == NULL || 
+     (message = (char*)malloc(sizeof(char)*block_size))== NULL){
+    fprintf(stderr,"Fatal Error, exiting...");
     return 1;
   }
   
@@ -60,10 +77,9 @@ int main(int argc, char** argv)
 
   for(i = 0;i<iterations;i++){
 
-    memset(message,' ',1024);
     sprintf(message,"message:%ld",msg_index++);
-    message[1023] = '\0';
+    memset(message + strlen(message),' ',block_size - strlen(message));
-
+    memset(message + block_size - 1,'\0',1);
     if(interval > 0 && i % interval == 0){
       err = skygw_log_write_flush(LOGFILE_ERROR, message);
     }else{
@@ -76,6 +92,7 @@ int main(int argc, char** argv)
   }
 
   skygw_logmanager_done();
+  free(message);
   free(optstr[0]);
   free(optstr[1]);
   free(optstr[2]);