diff --git a/log_manager/log_manager.cc b/log_manager/log_manager.cc index 89d9df82b..3d61f9487 100644 --- a/log_manager/log_manager.cc +++ b/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. @@ -686,7 +702,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) { @@ -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); - bb->bb_isfull = true; + blockbuf_register(bb); + 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, diff --git a/log_manager/test/logorder.sh b/log_manager/test/logorder.sh new file mode 100755 index 000000000..098ea30ef --- /dev/null +++ b/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 diff --git a/log_manager/test/testorder.c b/log_manager/test/testorder.c index 3aa7e763a..7fdcda0e1 100644 --- a/log_manager/test/testorder.c +++ b/log_manager/test/testorder.c @@ -15,6 +15,7 @@ * * Copyright SkySQL Ab 2013 */ + #include #include #include @@ -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 || - getcwd(cwd,sizeof(cwd)) == NULL || - (optstr = malloc(sizeof(char*)*4)) == NULL){ + 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; } @@ -60,10 +77,9 @@ int main(int argc, char** argv) for(i = 0;i 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]);