diff --git a/log_manager/log_manager.cc b/log_manager/log_manager.cc index 733e9fffe..6c40190be 100644 --- a/log_manager/log_manager.cc +++ b/log_manager/log_manager.cc @@ -45,6 +45,12 @@ extern char *program_invocation_name; extern char *program_invocation_short_name; +#if defined(SS_DEBUG) +static int write_index; +static int block_start_index; +static int prevval; +static simple_mutex_t msg_mutex; +#endif /** * Variable holding the enabled logfiles information. * Used from log users to check enabled logs prior calling @@ -113,7 +119,7 @@ typedef struct blockbuf_st { skygw_chk_t bb_chk_top; #endif logfile_id_t bb_fileid; - bool bb_isfull; /**< closed for disk write */ + blockbuf_state_t bb_state; /**State of the block buffer*/ simple_mutex_t bb_mutex; /**< bb_buf_used, bb_isfull */ int bb_refcount; /**< protected by list mutex. #of clients */ // int bb_blankcount; /**< # of blanks used btw strings */ @@ -333,6 +339,10 @@ static bool logmanager_init_nomutex( #if defined(SS_DEBUG) lm->lm_chk_top = CHK_NUM_LOGMANAGER; lm->lm_chk_tail = CHK_NUM_LOGMANAGER; + write_index = 0; + block_start_index = 0; + prevval = -1; + simple_mutex_init(&msg_mutex, "Message mutex"); #endif lm->lm_clientmes = skygw_message_init(); lm->lm_logmes = skygw_message_init(); @@ -652,27 +662,73 @@ static int logmanager_write_log( /** Findout how much can be safely written with current block size */ if (timestamp_len-1+str_len > lf->lf_buf_size) - { - safe_str_len = lf->lf_buf_size; - } + { + safe_str_len = lf->lf_buf_size; + } else - { - safe_str_len = timestamp_len-1+str_len; - } + { + safe_str_len = timestamp_len-1+str_len; + } + /** * Seek write position and register to block buffer. * Then print formatted string to write position. */ + +#if defined (SS_LOG_DEBUG) + { + + char *copy,*tok; + int tokval; + + simple_mutex_lock(&msg_mutex,true); + + copy = strdup(str); + + tok = strtok(copy,"|"); + + tok = strtok(NULL,"|"); + + if(strstr(str,"message|") && tok){ + + tokval = atoi(tok); + + if(prevval > 0){ + ss_dassert(tokval == (prevval + 1)); + } + + prevval = tokval; + } + + free(copy); + simple_mutex_unlock(&msg_mutex); + + } +#endif + wp = blockbuf_get_writepos(&bb, id, safe_str_len, flush); + + +#if defined (SS_LOG_DEBUG) + { + sprintf(wp,"[msg:%d]",atomic_add(&write_index,1)); + safe_str_len -= strlen(wp); + wp += strlen(wp); + } +#endif + /** * Write timestamp with at most characters * to wp. * Returned timestamp_len doesn't include terminating null. */ timestamp_len = snprint_timestamp(wp, timestamp_len); + + + /** * Write next string to overwrite terminating null character * of the timestamp string. @@ -682,7 +738,7 @@ static int logmanager_write_log( } else { snprintf(wp+timestamp_len, safe_str_len-timestamp_len, "%s", str); } - + /** write to syslog */ if (lf->lf_write_syslog) { @@ -753,7 +809,7 @@ static int logmanager_write_log( wp_c[timestamp_len-1+str_len-1]='\n'; /** lock-free unregistration, includes flush if - * bb_isfull */ + * bb_state == BB_FULL */ blockbuf_unregister(bb_c); } } /* if (spread_down) */ @@ -784,7 +840,7 @@ static void blockbuf_unregister( /** * if this is the last client in a full buffer, send write request. */ - if (atomic_add(&bb->bb_refcount, -1) == 1 && bb->bb_isfull) { + if (atomic_add(&bb->bb_refcount, -1) == 1 && bb->bb_state == BB_FULL) { skygw_message_send(lf->lf_logmes); } ss_dassert(bb->bb_refcount >= 0); @@ -816,12 +872,12 @@ static char* blockbuf_get_writepos( size_t str_len, bool flush) { - logfile_t* lf; - mlist_t* bb_list; - char* pos = NULL; - mlist_node_t* node; - blockbuf_t* bb; - ss_debug(bool succp;) + logfile_t* lf; + mlist_t* bb_list; + char* pos = NULL; + mlist_node_t* node; + blockbuf_t* bb; + ss_debug(bool succp;) CHK_LOGMANAGER(lm); @@ -838,6 +894,7 @@ static char* blockbuf_get_writepos( * At least block buffer exists on the list. */ node = bb_list->mlist_first; + /** Loop over blockbuf list to find write position */ while (true) { @@ -852,22 +909,25 @@ static char* blockbuf_get_writepos( /** Lock buffer */ simple_mutex_lock(&bb->bb_mutex, true); - if (bb->bb_isfull || bb->bb_buf_left < str_len) { + if (bb->bb_state == BB_FULL || bb->bb_buf_left < str_len) { /** * This block buffer is too full. * Send flush request to file writer thread. This causes * flushing all buffers, and (eventually) frees buffer space. */ - blockbuf_register(bb); - bb->bb_isfull = true; - blockbuf_unregister(bb); + blockbuf_register(bb); + + bb->bb_state = BB_FULL; + + blockbuf_unregister(bb); + + /** Unlock buffer */ + simple_mutex_unlock(&bb->bb_mutex); + + /** Lock list */ + simple_mutex_lock(&bb_list->mlist_mutex, true); - /** Unlock buffer */ - simple_mutex_unlock(&bb->bb_mutex); - /** Lock list */ - simple_mutex_lock(&bb_list->mlist_mutex, true); - /** * If next node exists move forward. Else check if there is * space for a new block buffer on the list. @@ -916,7 +976,28 @@ static char* blockbuf_get_writepos( node = bb_list->mlist_first; continue; } - } else { + + + }else if(bb->bb_state == BB_CLEARED){ + + /** + *Move the full buffer to the end of the list + */ + + simple_mutex_unlock(&bb->bb_mutex); + simple_mutex_lock(&bb_list->mlist_mutex, true); + + if(node->mlnode_next){ + bb_list->mlist_first = node->mlnode_next; + bb_list->mlist_last->mlnode_next = node; + node->mlnode_next = NULL; + bb_list->mlist_last = node; + node = bb_list->mlist_first; + } + + bb->bb_state = BB_READY; + + }else if (bb->bb_state == BB_READY){ /** * There is space for new log string. */ @@ -924,9 +1005,11 @@ static char* blockbuf_get_writepos( } } /** while (true) */ } else { + /** * Create the first block buffer to logfile's blockbuf list. */ + bb = blockbuf_init(id); CHK_BLOCKBUF(bb); @@ -952,7 +1035,7 @@ static char* blockbuf_get_writepos( } /* if (bb_list->mlist_nodecount > 0) */ ss_dassert(pos == NULL); - ss_dassert(!(bb->bb_isfull || bb->bb_buf_left < str_len)); + ss_dassert(!(bb->bb_state == BB_FULL || bb->bb_buf_left < str_len)); ss_dassert(bb_list->mlist_nodecount <= bb_list->mlist_nodecount_max); /** @@ -991,7 +1074,7 @@ static char* blockbuf_get_writepos( * If flush flag is set, set buffer full. As a consequence, no-one * can write to it before it is flushed to disk. */ - bb->bb_isfull = (flush == true ? true : bb->bb_isfull); + bb->bb_state = (flush == true ? BB_FULL : bb->bb_state); /** Unlock buffer */ simple_mutex_unlock(&bb->bb_mutex); @@ -1021,6 +1104,12 @@ static blockbuf_t* blockbuf_init( bb->bb_buf_left = MAX_LOGSTRLEN; bb->bb_buf_size = MAX_LOGSTRLEN; +#if defined(SS_LOG_DEBUG) + sprintf(bb->bb_buf,"[block:%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; } @@ -1170,6 +1259,9 @@ int skygw_log_write_flush( /** * Find out the length of log string (to be formatted str). */ + + + va_start(valist, str); len = vsnprintf(NULL, 0, str, valist); va_end(valist); @@ -1220,6 +1312,9 @@ int skygw_log_write( err = 1; goto return_unregister; } + + + /** * Find out the length of log string (to be formatted str). */ @@ -1233,6 +1328,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); @@ -2257,7 +2353,7 @@ static void filewriter_done( * lists of each logfile object. * * Block buffer is written to log file if - * 1. bb_isfull == true, + * 1. bb_state == true, * 2. logfile object's lf_flushflag == true, or * 3. skygw_thread_must_exit returns true. * @@ -2297,7 +2393,7 @@ static void* thr_filewriter_fun( blockbuf_t* bb; mlist_node_t* node; int i; - bool flush_blockbuf; /**< flush single block buffer. */ + blockbuf_state_t flush_blockbuf; /**< flush single block buffer. */ bool flush_logfile; /**< flush logfile */ bool flushall_logfiles;/**< flush all logfiles */ size_t vn1; @@ -2356,10 +2452,10 @@ static void* thr_filewriter_fun( /** Lock block buffer */ simple_mutex_lock(&bb->bb_mutex, true); - flush_blockbuf = bb->bb_isfull; + flush_blockbuf = bb->bb_state; if (bb->bb_buf_used != 0 && - (flush_blockbuf || + (flush_blockbuf == BB_FULL || flush_logfile || flushall_logfiles)) { @@ -2374,7 +2470,7 @@ static void* thr_filewriter_fun( &bb->bb_mutex, true); } - + skygw_file_write(file, (void *)bb->bb_buf, bb->bb_buf_used, @@ -2387,7 +2483,13 @@ static void* thr_filewriter_fun( bb->bb_buf_left = bb->bb_buf_size; bb->bb_buf_used = 0; memset(bb->bb_buf, 0, bb->bb_buf_size); - bb->bb_isfull = false; + bb->bb_state = BB_CLEARED; +#if defined(SS_LOG_DEBUG) + sprintf(bb->bb_buf,"[block:%d]",atomic_add(&block_start_index,1)); + bb->bb_buf_used += strlen(bb->bb_buf); + bb->bb_buf_left -= strlen(bb->bb_buf); +#endif + } /** Release lock to block buffer */ simple_mutex_unlock(&bb->bb_mutex); diff --git a/log_manager/log_manager.h b/log_manager/log_manager.h index b96669fa2..d9932d640 100644 --- a/log_manager/log_manager.h +++ b/log_manager/log_manager.h @@ -22,6 +22,12 @@ typedef struct logfile_st logfile_t; typedef struct fnames_conf_st fnames_conf_t; typedef struct logmanager_st logmanager_t; +typedef enum { + BB_READY = 0x00, + BB_FULL, + BB_CLEARED +} blockbuf_state_t; + typedef enum { LOGFILE_ERROR = 1, LOGFILE_FIRST = LOGFILE_ERROR, diff --git a/log_manager/makefile b/log_manager/makefile index a020c7932..7f35c13f6 100644 --- a/log_manager/makefile +++ b/log_manager/makefile @@ -8,6 +8,11 @@ SRCS := log_manager.cc UTILS_PATH := $(ROOT_PATH)/utils CUR_DIR := $(shell pwd) +ifeq ($(ADD_DEBUG_TAGS),Y) +CFLAGS += -DSS_LOG_DEBUG +endif + + makeall: clean all clean: diff --git a/log_manager/test/logorder.sh b/log_manager/test/logorder.sh new file mode 100755 index 000000000..bbdcaf0f7 --- /dev/null +++ b/log_manager/test/logorder.sh @@ -0,0 +1,61 @@ +#! /bin/bash + +if [[ $# -lt 4 ]] +then + echo "Usage: logorder.sh " + echo "To disable log flushing, use 0 for flush frequency" + exit +fi + +rm *.log + +#Create large messages +$PWD/testorder $1 $2 $3 + +TESTLOG=$4 +MCOUNT=$1 + +BLOCKS=`cat skygw_err1.log |tr -s ' '|grep -o 'block:[[:digit:]]\+'|cut -d ':' -f 2` +MESSAGES=`cat skygw_err1.log |tr -s ' '|grep -o 'message|[[:digit:]]\+'|cut -d '|' -f 2` + +prev=0 +error=0 + +for i in $BLOCKS +do + + if [[ $i -le $prev ]] + then + error=1 + echo "block mismatch: $i was after $prev." >> $TESTLOG + fi + prev=$i +done + +if [[ error -eq 0 ]] +then + echo "Block buffers were in order" >> $TESTLOG +else + echo "Error: block buffers were written in the wrong order" >> $TESTLOG +fi + +prev=0 +error=0 + +for i in $MESSAGES +do + + if [[ $i -ne $(( prev + 1 )) ]] + then + error=1 + echo "message mismatch: $i was after $prev." >> $TESTLOG + fi + prev=$i +done + +if [[ error -eq 0 ]] +then + echo "Block buffer messages were in order" >> $TESTLOG +else + echo "Error: block buffer messages were written in the wrong order" >> $TESTLOG +fi diff --git a/log_manager/test/makefile b/log_manager/test/makefile index 71fd074f1..f3e0dc362 100644 --- a/log_manager/test/makefile +++ b/log_manager/test/makefile @@ -28,10 +28,13 @@ testall: cleantests: - $(DEL) *.o + - $(DEL) *.log - $(DEL) testlog + - $(DEL) testorder - $(DEL) *~ buildtests: + $(MAKE) -C $(LOG_MANAGER_PATH) ADD_DEBUG_TAGS=Y $(CC) $(CFLAGS) \ -L$(LOG_MANAGER_PATH) \ -Wl,-rpath,$(DEST)/lib \ @@ -41,6 +44,17 @@ buildtests: -I$(LOG_MANAGER_PATH) -I$(UTILS_PATH) testlog.c \ -lstdc++ -llog_manager $(LDLIBS) \ $(UTILS_PATH)/skygw_utils.o + $(CC) $(CFLAGS) \ + -L$(LOG_MANAGER_PATH) \ + -Wl,-rpath,$(DEST)/lib \ + -Wl,-rpath,$(LOG_MANAGER_PATH)/ \ + -o testorder \ + -I$(MARIADB_SRC_PATH)/include \ + -I$(LOG_MANAGER_PATH) -I$(UTILS_PATH) testorder.c \ + -lstdc++ -llog_manager $(LDLIBS) \ + $(UTILS_PATH)/skygw_utils.o + + runtests: @@ -61,6 +75,10 @@ runtests: @echo "Use 16 threads" >> $(TESTLOG) @echo "" >> $(TESTLOG) @-$(LAUNCH_DEBUGGER) $(TESTAPP) "-t 16" 2>>$(TESTLOG) + @echo "" >> $(TEST_MAXSCALE_LOG) + @echo "Test Message Order" >> $(TEST_MAXSCALE_LOG) + @echo "" >> $(TEST_MAXSCALE_LOG) + ./logorder.sh 500 0 500 $(TEST_MAXSCALE_LOG) @echo "Log Manager PASSED" >> $(TESTLOG) @echo "" >> $(TESTLOG) diff --git a/log_manager/test/testorder.c b/log_manager/test/testorder.c new file mode 100644 index 000000000..e2bb94a7b --- /dev/null +++ b/log_manager/test/testorder.c @@ -0,0 +1,105 @@ +/* + * This file is distributed as part of the SkySQL Gateway. It is free + * software: you can redistribute it and/or modify it under the terms of the + * GNU General Public License as published by the Free Software Foundation, + * version 2. + * + * This program is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS + * FOR A PARTICULAR PURPOSE. See the GNU General Public License for more + * details. + * + * You should have received a copy of the GNU General Public License along with + * this program; if not, write to the Free Software Foundation, Inc., 51 + * Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Copyright SkySQL Ab 2013 + */ + +#include +#include +#include +#include +#include +#include + +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; + char** optstr; + long msg_index = 1; + + + memset(cwd,0,1024); + if( argc <4){ + fprintf(stderr, + "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 \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; + } + + memset(tmp,0,1024); + + sprintf(tmp,"%s",cwd); + optstr[0] = strdup("log_manager"); + optstr[1] = strdup("-j"); + optstr[2] = strdup(tmp); + optstr[3] = NULL; + + iterations = atoi(argv[1]); + interval = atoi(argv[2]); + + succp = skygw_logmanager_init( 3, optstr); + ss_dassert(succp); + + skygw_log_disable(LOGFILE_TRACE); + skygw_log_disable(LOGFILE_MESSAGE); + skygw_log_disable(LOGFILE_DEBUG); + + for(i = 0;i 0 && i % interval == 0){ + err = skygw_log_write_flush(LOGFILE_ERROR, message); + }else{ + err = skygw_log_write(LOGFILE_ERROR, message); + } + if(err){ + fprintf(stderr,"Error: log_manager returned %d",err); + break; + } + usleep(100); + //printf("%s\n",message); + } + + skygw_log_flush(LOGFILE_ERROR); + skygw_logmanager_done(); + free(message); + free(optstr[0]); + free(optstr[1]); + free(optstr[2]); + free(optstr[3]); + free(optstr); + return 0; +}