diff --git a/log_manager/log_manager.cc b/log_manager/log_manager.cc index 8a721837f..69667fa4e 100644 --- a/log_manager/log_manager.cc +++ b/log_manager/log_manager.cc @@ -15,12 +15,16 @@ * * Copyright SkySQL Ab 2013 */ +#include +#include +#include #include #include #include #include #include +#include #include #include @@ -45,7 +49,14 @@ */ #endif +/** + * Path to directory in which all files are stored to shared memory + * by the OS. + */ +const char* shm_pathname = "/dev/shm"; +/** Logfile ids from call argument '-s' */ +char* shmem_id_str = NULL; /** * Global log manager pointer and lock variable. * lmlock protects logmanager access. @@ -56,7 +67,9 @@ static logmanager_t* lm; /** Writer thread structure */ struct filewriter_st { +#if defined(SS_DEBUG) skygw_chk_t fwr_chk_top; +#endif flat_obj_state_t fwr_state; logmanager_t* fwr_logmgr; /** Physical files */ @@ -66,7 +79,9 @@ struct filewriter_st { /** fwr_clientmes is for messages to log clients */ skygw_message_t* fwr_clientmes; skygw_thread_t* fwr_thread; +#if defined(SS_DEBUG) skygw_chk_t fwr_chk_tail; +#endif }; /** @@ -74,7 +89,9 @@ struct filewriter_st { * to file writer thread. */ typedef struct blockbuf_st { +#if defined(SS_DEBUG) skygw_chk_t bb_chk_top; +#endif logfile_id_t bb_fileid; bool bb_isfull; /**< closed for disk write */ simple_mutex_t bb_mutex; /**< bb_buf_used, bb_isfull */ @@ -84,7 +101,9 @@ typedef struct blockbuf_st { size_t bb_buf_left; size_t bb_buf_used; char bb_buf[BUFSIZ]; +#if defined(SS_DEBUG) skygw_chk_t bb_chk_tail; +#endif } blockbuf_t; /** @@ -92,19 +111,24 @@ typedef struct blockbuf_st { * certain log is written. */ struct logfile_st { +#if defined(SS_DEBUG) skygw_chk_t lf_chk_top; +#endif flat_obj_state_t lf_state; bool lf_init_started; bool lf_enabled; + bool lf_store_shmem; logmanager_t* lf_lmgr; /** fwr_logmes is for messages from log clients */ skygw_message_t* lf_logmes; logfile_id_t lf_id; - char* lf_logpath; + char* lf_filepath; /**< path to file used for logging */ + char* lf_linkpath; /**< path to symlink file. */ char* lf_name_prefix; char* lf_name_suffix; - int lf_name_sequence; - char* lf_full_name; + int lf_name_seqno; + char* lf_full_file_name; /**< complete log file name */ + char* lf_full_link_name; /**< complete symlink name */ int lf_nfiles_max; size_t lf_file_size; /** list of block-sized log buffers */ @@ -112,13 +136,19 @@ struct logfile_st { bool lf_flushflag; int lf_spinlock; /**< lf_flushflag */ int lf_npending_writes; +#if defined(SS_DEBUG) skygw_chk_t lf_chk_tail; +#endif }; struct fnames_conf_st { +#if defined(SS_DEBUG) skygw_chk_t fn_chk_top; +#endif flat_obj_state_t fn_state; + char* fn_debug_prefix; + char* fn_debug_suffix; char* fn_trace_prefix; char* fn_trace_suffix; char* fn_msg_prefix; @@ -126,11 +156,15 @@ struct fnames_conf_st { char* fn_err_prefix; char* fn_err_suffix; char* fn_logpath; +#if defined(SS_DEBUG) skygw_chk_t fn_chk_tail; +#endif }; struct logmanager_st { +#if defined(SS_DEBUG) skygw_chk_t lm_chk_top; +#endif bool lm_enabled; int lm_enabled_logfiles; simple_mutex_t lm_mutex; @@ -142,7 +176,20 @@ struct logmanager_st { fnames_conf_t lm_fnames_conf; logfile_t lm_logfile[LOGFILE_LAST+1]; filewriter_t lm_filewriter; +#if defined(SS_DEBUG) skygw_chk_t lm_chk_tail; +#endif +}; + +/** + * Type definition for string part. It is used in forming the log file name + * from string parts provided by the client of log manager, as arguments. + */ +typedef struct strpart_st strpart_t; + +struct strpart_st { + char* sp_string; + strpart_t* sp_next; }; @@ -151,7 +198,8 @@ static bool logfiles_init(logmanager_t* lmgr); static bool logfile_init( logfile_t* logfile, logfile_id_t logfile_id, - logmanager_t* logmanager); + logmanager_t* logmanager, + bool store_shmem); static void logfile_done(logfile_t* logfile); static void logfile_free_memory(logfile_t* lf); static void logfile_flush(logfile_t* lf); @@ -192,9 +240,14 @@ static char* blockbuf_get_writepos( size_t str_len, bool flush); -static void blockbuf_register(blockbuf_t* bb); -static void blockbuf_unregister(blockbuf_t* bb); -static bool logfile_set_enabled(logfile_id_t id, bool val); +static void blockbuf_register(blockbuf_t* bb); +static void blockbuf_unregister(blockbuf_t* bb); +static bool logfile_set_enabled(logfile_id_t id, bool val); +static char* add_slash(char* str); +static bool file_exists(char* filename); +static bool file_is_symlink(char* filename); + + const char* get_suffix_default(void) @@ -202,6 +255,16 @@ const char* get_suffix_default(void) return ".log"; } +const char* get_debug_prefix_default(void) +{ + return "skygw_debug"; +} + +const char* get_debug_suffix_default(void) +{ + return get_suffix_default(); +} + const char* get_trace_prefix_default(void) { return "skygw_trace"; @@ -247,14 +310,17 @@ static bool logmanager_init_nomutex( bool succp = false; lm = (logmanager_t *)calloc(1, sizeof(logmanager_t)); +#if defined(SS_DEBUG) lm->lm_chk_top = CHK_NUM_LOGMANAGER; lm->lm_chk_tail = CHK_NUM_LOGMANAGER; +#endif lm->lm_clientmes = skygw_message_init(); lm->lm_logmes = skygw_message_init(); lm->lm_enabled_logfiles |= LOGFILE_ERROR; lm->lm_enabled_logfiles |= LOGFILE_MESSAGE; #if defined(SS_DEBUG) lm->lm_enabled_logfiles |= LOGFILE_TRACE; + lm->lm_enabled_logfiles |= LOGFILE_DEBUG; #endif fn = &lm->lm_fnames_conf; fw = &lm->lm_filewriter; @@ -517,25 +583,25 @@ static int logmanager_write_log( CHK_LOGMANAGER(lm); if (id < LOGFILE_FIRST || id > LOGFILE_LAST) { - char* errstr = "Invalid logfile id argument."; - /** - * invalid id, since we don't have logfile yet. - */ - err = logmanager_write_log(LOGFILE_ERROR, - true, - false, - false, - strlen(errstr)+1, - errstr, - valist); - if (err != 0) { - fprintf(stderr, - "Writing to logfile %s failed.\n", - STRLOGID(LOGFILE_ERROR)); - } - err = -1; - ss_dassert(false); - goto return_err; + char* errstr = "Invalid logfile id argument."; + /** + * invalid id, since we don't have logfile yet. + */ + err = logmanager_write_log(LOGFILE_ERROR, + true, + false, + false, + strlen(errstr)+1, + errstr, + valist); + if (err != 0) { + fprintf(stderr, + "Writing to logfile %s failed.\n", + STRLOGID(LOGFILE_ERROR)); + } + err = -1; + ss_dassert(false); + goto return_err; } lf = &lm->lm_logfile[id]; CHK_LOGFILE(lf); @@ -546,84 +612,90 @@ static int logmanager_write_log( * skygw_log_write_flush. */ if (str == NULL) { - ss_dassert(flush); - logfile_flush(lf); /**< here we wake up file writer */ + ss_dassert(flush); + logfile_flush(lf); /**< here we wake up file writer */ } else { - timestamp_len = get_timestamp_len(); - /** - * Seek write position and register to block buffer. - * Then print formatted string to write position. - */ - wp = blockbuf_get_writepos(&bb, - id, - timestamp_len-1+str_len, - flush); - /** - * Write timestamp with at most characters - * to wp - */ - timestamp_len = snprint_timestamp(wp, timestamp_len); - /** - * Write next string to overwrite terminating null character - * of the timestamp string. - */ - if (use_valist) { - vsnprintf(wp+timestamp_len-1, str_len, str, valist); - } else { - snprintf(wp+timestamp_len-1, str_len, str); - } - /** remove double line feed */ - if (wp[timestamp_len-1+str_len-2] == '\n') { - wp[timestamp_len-1+str_len-2]=' '; - } - wp[timestamp_len-1+str_len-1]='\n'; - blockbuf_unregister(bb); + timestamp_len = get_timestamp_len(); + /** + * Seek write position and register to block buffer. + * Then print formatted string to write position. + */ + wp = blockbuf_get_writepos(&bb, + id, + timestamp_len-1+str_len, + flush); + /** + * Write timestamp with at most characters + * to wp + */ + timestamp_len = snprint_timestamp(wp, timestamp_len); + /** + * Write next string to overwrite terminating null character + * of the timestamp string. + */ + if (use_valist) { + vsnprintf(wp+timestamp_len-1, str_len, str, valist); + } else { + snprintf(wp+timestamp_len-1, str_len, str); + } + /** remove double line feed */ + if (wp[timestamp_len-1+str_len-2] == '\n') { + wp[timestamp_len-1+str_len-2]=' '; + } + wp[timestamp_len-1+str_len-1]='\n'; + blockbuf_unregister(bb); - if (spread_down) { - /** - * Write to target log. If spread_down == true, then write - * also to all logs with greater logfile id. - * LOGFILE_ERROR = 1, - * LOGFILE_MESSAGE = 2, - * LOGFILE_TRACE = 4 - * - * So everything written to error log will appear in - * message and trace log. Messages will be written in - * trace log. - */ - for (i=(id<<1); i<=LOGFILE_LAST; i<<=1) { - /** pointer to write buffer of larger-id log */ - char* wp_c; + if (spread_down && false) { + /** + * Write to target log. If spread_down == true, then + * write also to all logs with greater logfile id. + * LOGFILE_ERROR = 1, + * LOGFILE_MESSAGE = 2, + * LOGFILE_TRACE = 4, + * LOGFILE_DEBUG = 8 + * + * So everything written to error log will appear in + * message, trace and debuglog. Messages will be + * written in trace and debug log. + */ + for (i=(id<<1); i<=LOGFILE_LAST; i<<=1) + { + /** pointer to write buffer of larger-id log */ + char* wp_c; - /**< Check if particular log is enabled */ - if (!(lm->lm_enabled_logfiles & i)) { - continue; - } - /** - * Seek write position and register to block buffer. - * Then print formatted string to write position. - */ - wp_c = blockbuf_get_writepos(&bb_c, - (logfile_id_t)i, - timestamp_len-1+str_len, - flush); - /** - * Copy original string from block buffer to other - * logs' block buffers. - */ - snprintf(wp_c, timestamp_len+str_len, wp); + /**< Check if particular log is enabled */ + if (!(lm->lm_enabled_logfiles & i)) + { + continue; + } + /** + * Seek write position and register to block + * buffer. Then print formatted string to + * write position. + */ + wp_c = blockbuf_get_writepos( + &bb_c, + (logfile_id_t)i, + timestamp_len-1+str_len, + flush); + /** + * Copy original string from block buffer to + * other logs' block buffers. + */ + snprintf(wp_c, timestamp_len+str_len, wp); - /** remove double line feed */ - if (wp_c[timestamp_len-1+str_len-2] == '\n') { - wp_c[timestamp_len-1+str_len-2]=' '; - } - wp_c[timestamp_len-1+str_len-1]='\n'; + /** remove double line feed */ + if (wp_c[timestamp_len-1+str_len-2] == '\n') + { + wp_c[timestamp_len-1+str_len-2]=' '; + } + wp_c[timestamp_len-1+str_len-1]='\n'; - /** lock-free unregistration, includes flush if - * bb_isfull */ - blockbuf_unregister(bb_c); - } - } /* if (spread_down) */ + /** lock-free unregistration, includes flush if + * bb_isfull */ + blockbuf_unregister(bb_c); + } + } /* if (spread_down) */ } return_err: @@ -875,8 +947,10 @@ static blockbuf_t* blockbuf_init( bb = (blockbuf_t *)calloc(1, sizeof(blockbuf_t)); bb->bb_fileid = id; +#if defined(SS_DEBUG) bb->bb_chk_top = CHK_NUM_BLOCKBUF; bb->bb_chk_tail = CHK_NUM_BLOCKBUF; +#endif simple_mutex_init(&bb->bb_mutex, "Blockbuf mutex"); bb->bb_buf_left = BUFSIZ; bb->bb_buf_size = BUFSIZ; @@ -1226,7 +1300,7 @@ static void logmanager_unregister(void) * @return pointer to object which is either in RUN or DONE state. * * - * @details + * @details Note that input parameter lenghts are checked here. * */ static bool fnames_conf_init( @@ -1235,97 +1309,118 @@ static bool fnames_conf_init( char* argv[]) { int opt; - int i; bool succp = false; const char* argstr = - "-h - help\n" - "-a ............(\"skygw_trace\")\n" - "-b ............(\".log\")\n" - "-c ............(\"skygw_msg\")\n" - "-d ............(\".log\")\n" - "-e ............(\"skygw_err\")\n" - "-f ............(\".log\")\n" - "-g ............(\"/tmp\")\n"; + "-h - help\n" + "-a ............(\"skygw_debug\")\n" + "-b ............(\".log\")\n" + "-c ............(\"skygw_trace\")\n" + "-d ............(\".log\")\n" + "-e ............(\"skygw_msg\")\n" + "-f ............(\".log\")\n" + "-g ............(\"skygw_err\")\n" + "-i ............(\".log\")\n" + "-j ............(\"/tmp\")\n" + "-s ........(no default)\n"; /** * When init_started is set, clean must be done for it. */ fn->fn_state = INIT; +#if defined(SS_DEBUG) fn->fn_chk_top = CHK_NUM_FNAMES; fn->fn_chk_tail = CHK_NUM_FNAMES; - - while ((opt = getopt(argc, argv, "+a:b:c:d:e:f:g:h")) != -1) { - switch (opt) { +#endif + while ((opt = getopt(argc, argv, "+a:b:c:d:e:f:g:h:i:j:s:")) != -1) { + switch (opt) { case 'a': - fn->fn_trace_prefix = strndup(optarg, MAX_PREFIXLEN); - break; + fn->fn_debug_prefix = strndup(optarg, MAX_PREFIXLEN); + break; case 'b': - fn->fn_trace_suffix = strndup(optarg, MAX_SUFFIXLEN); - break; - + fn->fn_debug_suffix = strndup(optarg, MAX_SUFFIXLEN); + break; case 'c': - fn->fn_msg_prefix = strndup(optarg, MAX_PREFIXLEN); - break; + fn->fn_trace_prefix = strndup(optarg, MAX_PREFIXLEN); + break; case 'd': - fn->fn_msg_suffix = strndup(optarg, MAX_SUFFIXLEN); - break; + fn->fn_trace_suffix = strndup(optarg, MAX_SUFFIXLEN); + break; case 'e': - fn->fn_err_prefix = strndup(optarg, MAX_PREFIXLEN); - break; - + fn->fn_msg_prefix = strndup(optarg, MAX_PREFIXLEN); + break; + case 'f': - fn->fn_err_suffix = strndup(optarg, MAX_SUFFIXLEN); - break; + fn->fn_msg_suffix = strndup(optarg, MAX_SUFFIXLEN); + break; case 'g': - fn->fn_logpath = strndup(optarg, MAX_PATHLEN); - break; + fn->fn_err_prefix = strndup(optarg, MAX_PREFIXLEN); + break; + + case 'i': + fn->fn_err_suffix = strndup(optarg, MAX_SUFFIXLEN); + break; + case 'j': + fn->fn_logpath = strndup(optarg, MAX_PATHLEN); + break; + + case 's': + /** record list of log file ids for later use */ + shmem_id_str = optarg; + break; case 'h': default: - fprintf(stderr, - "\nSupported arguments are (default)\n%s\n", - argstr); - goto return_conf_init; - } /** switch (opt) */ + fprintf(stderr, + "\nSupported arguments are (default)\n%s\n", + argstr); + goto return_conf_init; + } /** switch (opt) */ } - + /** If log file name is not specified in call arguments, use default. */ + fn->fn_debug_prefix = (fn->fn_debug_prefix == NULL) ? + strdup(get_debug_prefix_default()) : fn->fn_debug_prefix; + fn->fn_debug_suffix = (fn->fn_debug_suffix == NULL) ? + strdup(get_debug_suffix_default()) : fn->fn_debug_suffix; fn->fn_trace_prefix = (fn->fn_trace_prefix == NULL) ? - strdup(get_trace_prefix_default()) : fn->fn_trace_prefix; + strdup(get_trace_prefix_default()) : fn->fn_trace_prefix; fn->fn_trace_suffix = (fn->fn_trace_suffix == NULL) ? - strdup(get_trace_suffix_default()) : fn->fn_trace_suffix; + strdup(get_trace_suffix_default()) : fn->fn_trace_suffix; fn->fn_msg_prefix = (fn->fn_msg_prefix == NULL) ? - strdup(get_msg_prefix_default()) : fn->fn_msg_prefix; + strdup(get_msg_prefix_default()) : fn->fn_msg_prefix; fn->fn_msg_suffix = (fn->fn_msg_suffix == NULL) ? - strdup(get_msg_suffix_default()) : fn->fn_msg_suffix; + strdup(get_msg_suffix_default()) : fn->fn_msg_suffix; fn->fn_err_prefix = (fn->fn_err_prefix == NULL) ? - strdup(get_err_prefix_default()) : fn->fn_err_prefix; + strdup(get_err_prefix_default()) : fn->fn_err_prefix; fn->fn_err_suffix = (fn->fn_err_suffix == NULL) ? - strdup(get_err_suffix_default()) : fn->fn_err_suffix; + strdup(get_err_suffix_default()) : fn->fn_err_suffix; fn->fn_logpath = (fn->fn_logpath == NULL) ? - strdup(get_logpath_default()) : fn->fn_logpath; + strdup(get_logpath_default()) : fn->fn_logpath; /* ss_dfprintf(stderr, "\n\n\tCommand line : "); - for (i=0; ifn_logpath, fn->fn_err_prefix, fn->fn_err_suffix, fn->fn_msg_prefix, fn->fn_msg_suffix, fn->fn_trace_prefix, - fn->fn_trace_suffix); + fn->fn_trace_suffix, + fn->fn_debug_prefix, + fn->fn_debug_suffix); succp = true; fn->fn_state = RUN; @@ -1333,7 +1428,7 @@ static bool fnames_conf_init( return_conf_init: if (!succp) { - fnames_conf_done(fn); + fnames_conf_done(fn); } ss_dassert(fn->fn_state == RUN || fn->fn_state == DONE); return succp; @@ -1348,6 +1443,10 @@ static char* fname_conf_get_prefix( ss_dassert(id >= LOGFILE_FIRST && id <= LOGFILE_LAST); switch (id) { + case LOGFILE_DEBUG: + return strdup(fn->fn_debug_prefix); + break; + case LOGFILE_TRACE: return strdup(fn->fn_trace_prefix); break; @@ -1373,7 +1472,11 @@ static char* fname_conf_get_suffix( ss_dassert(id >= LOGFILE_FIRST && id <= LOGFILE_LAST); switch (id) { - case LOGFILE_TRACE: + case LOGFILE_DEBUG: + return strdup(fn->fn_debug_suffix); + break; + + case LOGFILE_TRACE: return strdup(fn->fn_trace_suffix); break; @@ -1391,21 +1494,62 @@ static char* fname_conf_get_suffix( } +/** + * @node Calls logfile initializer for each logfile. + * + * + * Parameters: + * @param lm - + * + * + * @return + * + * + * @details If logfile is supposed to be located to shared memory + * it is specified here. In the case of shared memory file, a soft + * link is created to log directory. + * + * Motivation is performance. LOGFILE_DEBUG, for example, has so much data + * that writing it to disk slows execution down remarkably. + * + */ static bool logfiles_init( logmanager_t* lm) { bool succp = true; - int i = LOGFILE_FIRST; - - while(i<=LOGFILE_LAST && succp) { - succp = logfile_init(&lm->lm_logfile[i], (logfile_id_t)i, lm); - - if (!succp) { - fprintf(stderr, "Initializing logfiles failed\n"); - break; - } - i <<= 1; - + int lid = LOGFILE_FIRST; + int i = 0; + bool store_shmem; + + /** + * Initialize log files, pass softlink flag if necessary. + */ + while (lid<=LOGFILE_LAST && succp) { + /** + * Check if the file is stored in shared memory. If so, + * a symbolic link will be created to log directory. + */ + if (shmem_id_str != NULL && + strcasestr(shmem_id_str, + STRLOGID(logfile_id_t(lid))) != NULL) + { + store_shmem = true; + } + else + { + store_shmem = false; + } + succp = logfile_init(&lm->lm_logfile[lid], + (logfile_id_t)lid, + lm, + store_shmem); + + if (!succp) { + fprintf(stderr, "Initializing logfiles failed\n"); + break; + } + lid <<= 1; + i += 1; } return succp; } @@ -1420,80 +1564,398 @@ static void logfile_flush( skygw_message_send(lf->lf_logmes); } + +/** + * @node Combine all name parts from left to right. + * + * Parameters: + * @param parts - + * + * + * @param seqno - in, use + * specifies the the sequence number which will be added as a part + * of full file name. + * seqno == -1 indicates that sequence number won't be used. + * + * @param seqnoidx - in, use + * Specifies the seqno position in the 'array' of name parts. + * If seqno == -1 seqnoidx will be set -1 as well. + * + * @return Pointer to filename, of NULL if failed. + * + * + * @details (write detailed description here) + * + */ +static char* form_full_file_name( + strpart_t* parts, + int seqno, + int seqnoidx) +{ + int i; + size_t s; + size_t fnlen; + char* filename = NULL; + char* seqnostr = NULL; + strpart_t* p; + + if (seqno != -1) + { + s = UINTLEN(seqno); + seqnostr = (char *)malloc((int)s); + } + else + { + /** + * These magic numbers are needed to indicate this and + * in subroutines that sequence number is not used. + */ + s = 0; + seqnoidx = -1; + } + + if (parts == NULL || parts->sp_string == NULL) { + goto return_filename; + } + /** + * Length of path, file name, separating slash, sequence number and + * terminating character. + */ + fnlen = sizeof('/') + s + sizeof('\0'); + p = parts; + /** Calculate the combined length of all parts put together */ + while (p->sp_string != NULL) + { + fnlen += strnlen(p->sp_string, NAME_MAX); + + if (p->sp_next == NULL) + { + break; + } + p = p->sp_next; + } + + if (fnlen > NAME_MAX) { + fprintf(stderr, "Error : Too long file name= %d.\n", (int)fnlen); + goto return_filename; + } + + filename = (char*)calloc(1, fnlen); + snprintf(seqnostr, s+1, "%d", seqno); + + for (i=0, p=parts; p->sp_string != NULL; i++, p=p->sp_next) + { + if (i == seqnoidx) + { + strcat(filename, seqnostr); + } + strcat(filename, p->sp_string); + + if (p->sp_next == NULL) + { + break; + } + } + +return_filename: + if (seqnostr != NULL) free(seqnostr); + return filename; +} + +/** + * @node Allocate new buffer where argument string with a slash is copied. + * Original string buffer is freed. + * added. + * + * Parameters: + * @param str - + * + * + * @return + * + * + * @details (write detailed description here) + * + */ +static char* add_slash( + char* str) +{ + char* p = str; + size_t plen = strlen(p); + + /** Add slash if missing */ + if (p[plen-1] != '/') + { + str = (char *)malloc(plen+2); + snprintf(str, plen+2, "%s/", p); + free(p); + } + return str; +} + +/** + * @node Check if the file exists in the local file system and if it does, + * whether it is writable. + * + * Parameters: + * @param filename - + * + * + * @param writable - + * + * + * @return + * + * + * @details Note, that an space character is written to the end of file. + * + */ +static bool file_exists( + char* filename, + bool* writable) +{ + int fd; + bool exists = true; + + if (filename == NULL) + { + exists = false; + } + else + { + fd = open(filename, O_CREAT|O_EXCL); + + /** file exist */ + if (fd == -1) + { + /** Open file and write a byte for test */ + fd = open(filename, O_CREAT|O_RDWR, S_IRWXU|S_IRWXG); + + if (fd != -1) + { + char c = ' '; + if (write(fd, &c, 1) == 1) + { + *writable = true; + } + close(fd); + } + } + else + { + close(fd); + unlink(filename); + exists = false; + } + } + return exists; +} + +static bool file_is_symlink( + char* filename) +{ + int rc; + bool succp = false; + struct stat b; + + if (filename != NULL) + { + rc = lstat(filename, &b); + + if (rc != -1 && S_ISLNK(b.st_mode)) { + succp = true; + } + } + return succp; +} + + + +/** + * @node Initialize logfile structure. Form log file name, and optionally + * link name. Create block buffer for logfile. + * + * Parameters: + * @param logfile - + * + * + * @param logfile_id - + * + * + * @param logmanager - + * + * + * @param store_shmem - + * + * + * @return true if succeed, false otherwise + * + * + * @details (write detailed description here) + * + */ static bool logfile_init( logfile_t* logfile, logfile_id_t logfile_id, - logmanager_t* logmanager) + logmanager_t* logmanager, + bool store_shmem) { bool succp = false; - size_t namelen; - size_t s; fnames_conf_t* fn = &logmanager->lm_fnames_conf; + /** string parts of which the file is composed of */ + strpart_t strparts[3]; + bool namecreatefail; + bool nameconflicts; + bool writable; logfile->lf_state = INIT; +#if defined(SS_DEBUG) logfile->lf_chk_top = CHK_NUM_LOGFILE; logfile->lf_chk_tail = CHK_NUM_LOGFILE; +#endif logfile->lf_logmes = logmanager->lm_logmes; logfile->lf_id = logfile_id; - logfile->lf_logpath = strdup(fn->fn_logpath); logfile->lf_name_prefix = fname_conf_get_prefix(fn, logfile_id); logfile->lf_name_suffix = fname_conf_get_suffix(fn, logfile_id); logfile->lf_npending_writes = 0; - logfile->lf_name_sequence = 1; + logfile->lf_name_seqno = 1; logfile->lf_lmgr = logmanager; logfile->lf_flushflag = false; logfile->lf_spinlock = 0; + logfile->lf_store_shmem = store_shmem; logfile->lf_enabled = logmanager->lm_enabled_logfiles & logfile_id; - /** Read existing files to logfile->lf_files_list and create - * new file for log named after / + /** + * strparts is an array but next pointers are used to walk through + * the list of string parts. */ - s = UINTLEN(logfile->lf_name_sequence); - namelen = strlen(logfile->lf_logpath) + - sizeof('/') + - strlen(logfile->lf_name_prefix) + - s + - strlen(logfile->lf_name_suffix) + - sizeof('\0'); + strparts[0].sp_next = &strparts[1]; + strparts[1].sp_next = &strparts[2]; + strparts[2].sp_next = NULL; - logfile->lf_full_name = (char *)malloc(namelen); - - if (logfile->lf_full_name == NULL) { - fprintf(stderr, "Memory allocation for full logname failed\n"); - goto return_with_succp; + strparts[1].sp_string = logfile->lf_name_prefix; + strparts[2].sp_string = logfile->lf_name_suffix; + /** + * If file is stored in shared memory in /dev/shm, a link + * pointing to shm file is created and located to the file + * directory. + */ + if (store_shmem) { + logfile->lf_filepath = strdup(shm_pathname); + logfile->lf_linkpath = strdup(fn->fn_logpath); + logfile->lf_linkpath = add_slash(logfile->lf_linkpath); + } else { + logfile->lf_filepath = strdup(fn->fn_logpath); } - ss_dassert(logfile->lf_full_name != NULL); - - snprintf(logfile->lf_full_name, - namelen, - "%s/%s%d%s", - logfile->lf_logpath, - logfile->lf_name_prefix, - logfile->lf_name_sequence, - logfile->lf_name_suffix); + logfile->lf_filepath = add_slash(logfile->lf_filepath); + + do { + namecreatefail = false; + nameconflicts = false; + + strparts[0].sp_string = logfile->lf_filepath; + /** + * Create name for log file. Seqno is added between prefix & + * suffix (index == 2) + */ + logfile->lf_full_file_name = + form_full_file_name(strparts, logfile->lf_name_seqno, 2); + + if (store_shmem) { + strparts[0].sp_string = logfile->lf_linkpath; + /** + * Create name for link file + */ + logfile->lf_full_link_name = + form_full_file_name(strparts, + logfile->lf_name_seqno, + 2); + } + /** + * At least one of the files couldn't be created. Increase + * sequence number and retry until succeeds. + */ + if (logfile->lf_full_file_name == NULL || + (store_shmem && logfile->lf_full_link_name == NULL)) + { + namecreatefail = true; + goto file_create_fail; + } + /** + * If file exists but is different type, create fails and + * new, increased sequence number is added to file name. + */ + if (file_exists(logfile->lf_full_file_name, &writable)) + { + if (!writable || + file_is_symlink(logfile->lf_full_file_name)) + { + nameconflicts = true; + goto file_create_fail; + } + } + + if (store_shmem) + { + writable = false; + + if (file_exists(logfile->lf_full_link_name, &writable)) + { + if (!writable || + !file_is_symlink(logfile->lf_full_link_name)) + { + nameconflicts = true; + goto file_create_fail; + } + } + } + file_create_fail: + if (namecreatefail || nameconflicts) + { + logfile->lf_name_seqno += 1; + + if (logfile->lf_full_file_name != NULL) + { + free(logfile->lf_full_file_name); + logfile->lf_full_file_name = NULL; + } + if (logfile->lf_full_link_name != NULL) + { + free(logfile->lf_full_link_name); + logfile->lf_full_link_name = NULL; + } + + } + } while (namecreatefail || nameconflicts); + /** + * Create a block buffer list for log file. Clients' writes go to buffers + * from where separate log flusher thread writes them to disk. + */ if (mlist_init(&logfile->lf_blockbuf_list, NULL, strdup("logfile block buffer list"), NULL, MAXNBLOCKBUFS) == NULL) { - ss_dfprintf(stderr, "Initializing logfile blockbuf list failed\n"); - logfile_free_memory(logfile); - goto return_with_succp; + ss_dfprintf(stderr, + "Initializing logfile blockbuf list " + "failed\n"); + logfile_free_memory(logfile); + goto return_with_succp; } succp = true; logfile->lf_state = RUN; CHK_LOGFILE(logfile); - + return_with_succp: if (!succp) { - logfile_done(logfile); + logfile_done(logfile); } ss_dassert(logfile->lf_state == RUN || logfile->lf_state == DONE); return succp; } - + /** * @node Flush logfile and free memory allocated for it. * @@ -1534,10 +1996,11 @@ static void logfile_done( static void logfile_free_memory( logfile_t* lf) { - if (lf->lf_logpath != NULL) free(lf->lf_logpath); - if (lf->lf_name_prefix != NULL) free(lf->lf_name_prefix); - if (lf->lf_name_suffix != NULL) free(lf->lf_name_suffix); - if (lf->lf_full_name != NULL) free(lf->lf_full_name); + if (lf->lf_filepath != NULL) free(lf->lf_filepath); + if (lf->lf_name_prefix != NULL) free(lf->lf_name_prefix); + if (lf->lf_name_suffix != NULL) free(lf->lf_name_suffix); + if (lf->lf_full_link_name != NULL) free(lf->lf_full_link_name); + if (lf->lf_full_file_name != NULL) free(lf->lf_full_file_name); } /** @@ -1568,8 +2031,10 @@ static bool filewriter_init( CHK_LOGMANAGER(logmanager); fw->fwr_state = INIT; +#if defined(SS_DEBUG) fw->fwr_chk_top = CHK_NUM_FILEWRITER; fw->fwr_chk_tail = CHK_NUM_FILEWRITER; +#endif fw->fwr_logmgr = logmanager; /** Message from filewriter to clients */ fw->fwr_logmes = logmes; @@ -1577,33 +2042,45 @@ static bool filewriter_init( fw->fwr_clientmes = clientmes; if (fw->fwr_logmes == NULL || fw->fwr_clientmes == NULL) { - goto return_succp; + goto return_succp; } for (i=LOGFILE_FIRST; i<=LOGFILE_LAST; i <<= 1) { - id = (logfile_id_t)i; - lf = logmanager_get_logfile(logmanager, id); - fw->fwr_file[id] = skygw_file_init(lf->lf_full_name); + id = (logfile_id_t)i; + lf = logmanager_get_logfile(logmanager, id); - if (fw->fwr_file[id] == NULL) { - goto return_succp; - } - if (lf->lf_enabled) { - start_msg_str = strdup("---\tLogging is enabled.\n"); - } else { - start_msg_str = strdup("---\tLogging is disabled.\n"); - } - skygw_file_write(fw->fwr_file[id], - (void *)start_msg_str, - strlen(start_msg_str), - true); - free(start_msg_str); + if (lf->lf_store_shmem) + { + /** Create symlink pointing to log file */ + fw->fwr_file[id] = skygw_file_init(lf->lf_full_file_name, + lf->lf_full_link_name); + } + else + { + /** Create normal disk-resident log file */ + fw->fwr_file[id] = skygw_file_init(lf->lf_full_file_name, + NULL); + } + + if (fw->fwr_file[id] == NULL) { + goto return_succp; + } + if (lf->lf_enabled) { + start_msg_str = strdup("---\tLogging is enabled.\n"); + } else { + start_msg_str = strdup("---\tLogging is disabled.\n"); + } + skygw_file_write(fw->fwr_file[id], + (void *)start_msg_str, + strlen(start_msg_str), + true); + free(start_msg_str); } fw->fwr_state = RUN; CHK_FILEWRITER(fw); succp = true; return_succp: if (!succp) { - filewriter_done(fw); + filewriter_done(fw); } ss_dassert(fw->fwr_state == RUN || fw->fwr_state == DONE); return succp; @@ -1703,97 +2180,108 @@ static void* thr_filewriter_fun( skygw_message_send(fwr->fwr_clientmes); while(!skygw_thread_must_exit(thr)) { - /** - * Wait until new log arrival message appears. - * Reset message to avoid redundant calls. - */ - skygw_message_wait(fwr->fwr_logmes); + /** + * Wait until new log arrival message appears. + * Reset message to avoid redundant calls. + */ + skygw_message_wait(fwr->fwr_logmes); - flushall_logfiles = skygw_thread_must_exit(thr); + flushall_logfiles = skygw_thread_must_exit(thr); - /** Process all logfiles which have buffered writes. */ - for (i=LOGFILE_FIRST; i<=LOGFILE_LAST; i <<= 1) { - retry_flush_on_exit: - /** - * Get file pointer of current logfile. - */ - file = fwr->fwr_file[i]; - lf = &lm->lm_logfile[(logfile_id_t)i]; + /** Process all logfiles which have buffered writes. */ + for (i=LOGFILE_FIRST; i<=LOGFILE_LAST; i <<= 1) { + retry_flush_on_exit: + /** + * Get file pointer of current logfile. + */ + file = fwr->fwr_file[i]; + lf = &lm->lm_logfile[(logfile_id_t)i]; - /** - * read and reset logfile's flushflag - */ - acquire_lock(&lf->lf_spinlock); - flush_logfile = lf->lf_flushflag; - lf->lf_flushflag = false; - release_lock(&lf->lf_spinlock); + /** + * read and reset logfile's flushflag + */ + acquire_lock(&lf->lf_spinlock); + flush_logfile = lf->lf_flushflag; + lf->lf_flushflag = false; + release_lock(&lf->lf_spinlock); - /** - * get logfile's block buffer list - */ - bb_list = &lf->lf_blockbuf_list; + /** + * get logfile's block buffer list + */ + bb_list = &lf->lf_blockbuf_list; #if defined(SS_DEBUG) - simple_mutex_lock(&bb_list->mlist_mutex, true); - CHK_MLIST(bb_list); - simple_mutex_unlock(&bb_list->mlist_mutex); + simple_mutex_lock(&bb_list->mlist_mutex, true); + CHK_MLIST(bb_list); + simple_mutex_unlock(&bb_list->mlist_mutex); #endif - node = bb_list->mlist_first; + node = bb_list->mlist_first; - while (node != NULL) { - CHK_MLIST_NODE(node); - bb = (blockbuf_t *)node->mlnode_data; - CHK_BLOCKBUF(bb); + while (node != NULL) { + CHK_MLIST_NODE(node); + bb = (blockbuf_t *)node->mlnode_data; + CHK_BLOCKBUF(bb); - /** Lock block buffer */ - simple_mutex_lock(&bb->bb_mutex, true); + /** Lock block buffer */ + simple_mutex_lock(&bb->bb_mutex, true); - flush_blockbuf = bb->bb_isfull; + flush_blockbuf = bb->bb_isfull; - if (bb->bb_buf_used != 0 && - (flush_blockbuf || flush_logfile || flushall_logfiles)) - { + if (bb->bb_buf_used != 0 && + (flush_blockbuf || + flush_logfile || + flushall_logfiles)) + { + /** + * buffer is at least half-full + * -> write to disk + */ + while(bb->bb_refcount > 0) { + simple_mutex_unlock( + &bb->bb_mutex); + simple_mutex_lock( + &bb->bb_mutex, + true); + } + + skygw_file_write(file, + (void *)bb->bb_buf, + bb->bb_buf_used, + (flush_logfile || + flushall_logfiles)); + /** + * Reset buffer's counters and mark + * not full. + */ + 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; + } + /** Release lock to block buffer */ + simple_mutex_unlock(&bb->bb_mutex); + + /** Consistent lock-free read on the list */ + do { + while ((vn1 = bb_list->mlist_versno)%2 + != 0); + node = node->mlnode_next; + vn2 = bb_list->mlist_versno; + } while (vn1 != vn2); + + } /* while (node != NULL) */ + /** - * buffer is at least half-full -> write to disk + * Writer's exit flag was set after checking it. + * Loop is restarted to ensure that all logfiles are + * flushed. */ - while(bb->bb_refcount > 0) { - simple_mutex_unlock(&bb->bb_mutex); - simple_mutex_lock(&bb->bb_mutex, true); + if (!flushall_logfiles && skygw_thread_must_exit(thr)) + { + flushall_logfiles = true; + i = LOGFILE_FIRST; + goto retry_flush_on_exit; } - - skygw_file_write(file, - (void *)bb->bb_buf, - bb->bb_buf_used, - (flush_logfile || flushall_logfiles)); - /** - * Reset buffer's counters and mark not full. - */ - 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; - } - /** Release lock to block buffer */ - simple_mutex_unlock(&bb->bb_mutex); - - /** Consistent lock-free read on the list */ - do { - while ((vn1 = bb_list->mlist_versno)%2 != 0); - node = node->mlnode_next; - vn2 = bb_list->mlist_versno; - } while (vn1 != vn2); - - } /* while (node != NULL) */ - - /** - * Writer's exit flag was set after checking it. - * Loop is restarted to ensure that all logfiles are flushed. - */ - if (!flushall_logfiles && skygw_thread_must_exit(thr)) { - flushall_logfiles = true; - i = LOGFILE_FIRST; - goto retry_flush_on_exit; - } - } /* for */ + } /* for */ } /* while (!skygw_thread_must_exit) */ ss_debug(skygw_thread_set_state(thr, THR_STOPPED)); @@ -1823,6 +2311,8 @@ static void fnames_conf_done( static void fnames_conf_free_memory( fnames_conf_t* fn) { + if (fn->fn_debug_prefix != NULL) free(fn->fn_debug_prefix); + if (fn->fn_debug_suffix!= NULL) free(fn->fn_debug_suffix); if (fn->fn_trace_prefix != NULL) free(fn->fn_trace_prefix); if (fn->fn_trace_suffix!= NULL) free(fn->fn_trace_suffix); if (fn->fn_msg_prefix != NULL) free(fn->fn_msg_prefix); diff --git a/log_manager/log_manager.h b/log_manager/log_manager.h index 1fa2c973e..a4a767913 100644 --- a/log_manager/log_manager.h +++ b/log_manager/log_manager.h @@ -27,13 +27,10 @@ typedef enum { LOGFILE_FIRST = LOGFILE_ERROR, LOGFILE_MESSAGE = 2, LOGFILE_TRACE = 4, - LOGFILE_LAST = LOGFILE_TRACE + LOGFILE_DEBUG = 8, + LOGFILE_LAST = LOGFILE_DEBUG } logfile_id_t; -/** - * This is for the future where LOGFILE_DEBUG has separate file. - */ -#define LOGFILE_DEBUG LOGFILE_TRACE typedef enum { FILEWRITER_INIT, FILEWRITER_RUN, FILEWRITER_DONE } filewriter_state_t; diff --git a/server/core/dcb.c b/server/core/dcb.c index ec3ec7e53..4bee9a23f 100644 --- a/server/core/dcb.c +++ b/server/core/dcb.c @@ -106,10 +106,6 @@ if ((rval = calloc(1, sizeof(DCB))) == NULL) rval->dcb_chk_tail = CHK_NUM_DCB; #endif rval->dcb_role = role; - simple_mutex_init(&rval->dcb_write_lock, "DCB write mutex"); - simple_mutex_init(&rval->dcb_read_lock, "DCB read mutex"); - rval->dcb_write_active = false; - rval->dcb_read_active = false; spinlock_init(&rval->dcb_initlock); spinlock_init(&rval->writeqlock); spinlock_init(&rval->delayqlock); @@ -169,7 +165,13 @@ dcb_add_to_zombieslist(DCB *dcb) spinlock_release(&zombiespin); return; } - +#if 1 + /** + * Add closing dcb to the top of the list. + */ + dcb->memdata.next = zombies; + zombies = dcb; +#else if (zombies == NULL) { zombies = dcb; } else { @@ -199,6 +201,7 @@ dcb_add_to_zombieslist(DCB *dcb) ptr->memdata.next = dcb; } } +#endif /** * Set state which indicates that it has been added to zombies * list. @@ -319,7 +322,7 @@ bool succp = false; { /* * Remove the DCB from the zombie queue - * and call the final free routine for the + * and call the final free routine for the * DCB * * ptr is the DCB we are processing @@ -334,7 +337,7 @@ bool succp = false; else lptr->memdata.next = tptr; skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_process_zombies] Remove dcb %p fd %d " "in state %s from zombies list.", pthread_self(), @@ -389,7 +392,7 @@ bool succp = false; #if defined(SS_DEBUG) else { skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_process_zombies] Closed socket " "%d on dcb %p.", pthread_self(), @@ -454,7 +457,7 @@ int rc; if (!session_link_dcb(session, dcb)) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_connect] Failed to link to session, the " "session has been removed.", pthread_self()); @@ -465,7 +468,7 @@ int rc; if (fd == -1) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_connect] Failed to connect to server %s:%d, " "from backend dcb %p, client dcp %p fd %d.", pthread_self(), @@ -479,7 +482,7 @@ int rc; return NULL; } else { skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_connect] Connected to server %s:%d, " "from backend dcb %p, client dcp %p fd %d.", pthread_self(), @@ -621,7 +624,7 @@ int eno = 0; goto return_n; } skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_read] Read %d bytes from dcb %p in state %s " "fd %d.", pthread_self(), @@ -671,7 +674,7 @@ dcb_write(DCB *dcb, GWBUF *queue) dcb->writeq = gwbuf_append(dcb->writeq, queue); dcb->stats.n_buffered++; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_write] Append to writequeue. %d writes " "buffered for dcb %p in state %s fd %d", pthread_self(), @@ -722,7 +725,7 @@ dcb_write(DCB *dcb, GWBUF *queue) if (saved_errno == EPIPE) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_write] Write to dcb " "%p in state %s fd %d failed " "due errno %d, %s", @@ -754,7 +757,7 @@ dcb_write(DCB *dcb, GWBUF *queue) */ queue = gwbuf_consume(queue, w); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_write] Wrote %d Bytes to dcb %p in " "state %s fd %d", pthread_self(), @@ -853,7 +856,7 @@ int saved_errno = 0; */ dcb->writeq = gwbuf_consume(dcb->writeq, w); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_drain_writeq] Wrote %d Bytes to dcb %p " "in state %s fd %d", pthread_self(), @@ -902,8 +905,8 @@ dcb_close(DCB *dcb) } ss_dassert(dcb->state == DCB_STATE_POLLING || - dcb->state == DCB_STATE_NOPOLLING || - dcb->state == DCB_STATE_ZOMBIE); + dcb->state == DCB_STATE_NOPOLLING || + dcb->state == DCB_STATE_ZOMBIE); /** * Stop dcb's listening and modify state accordingly. @@ -915,7 +918,7 @@ dcb_close(DCB *dcb) if (rc == 0) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_close] Removed dcb %p in state %s from " "poll set.", pthread_self(), @@ -1262,7 +1265,7 @@ static bool dcb_set_state_nomutex( if (succp) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [dcb_set_state_nomutex] dcb %p fd %d %s -> %s", pthread_self(), dcb, diff --git a/server/core/gateway.c b/server/core/gateway.c index d26bdb7fb..93cda2e23 100644 --- a/server/core/gateway.c +++ b/server/core/gateway.c @@ -112,24 +112,23 @@ static void sighup_handler (int i) } static void sigterm_handler (int i) { - extern void shutdown_gateway(); + extern void shutdown_server(); skygw_log_write_flush( LOGFILE_ERROR, - "Error : Signal SIGTERM %i received ...Exiting!", i); - shutdown_gateway(); + "MaxScale received signal SIGTERM. Exiting."); + shutdown_server(); } static void sigint_handler (int i) { - extern void shutdown_gateway(); + extern void shutdown_server(); skygw_log_write_flush( LOGFILE_ERROR, - "Error : Signal SIGINT %i received ...Exiting!", - i); - shutdown_gateway(); + "MaxScale received signal SIGINT. Shutting down."); + shutdown_server(); fprintf(stderr, "\n\nShutting down MaxScale\n\n"); } @@ -485,15 +484,17 @@ main(int argc, char **argv) if (home) { char buf[1024]; - char *argv[4]; + char *argv[6]; sprintf(buf, "%s/log", home); mkdir(buf, 0777); argv[0] = "MaxScale"; - argv[1] = "-g"; + argv[1] = "-j"; argv[2] = buf; - argv[3] = NULL; - skygw_logmanager_init(3, argv); + argv[3] = "-s"; /**state != DCB_STATE_DISCONNECTED); ss_dassert(dcb->state != DCB_STATE_FREED); ss_debug(spinlock_release(&dcb->dcb_initlock);) - - skygw_log_write_flush( - LOGFILE_DEBUG, + + skygw_log_write( + LOGFILE_TRACE, "%lu [poll_waitevents] event %d dcb %p " "role %s", pthread_self(), @@ -388,7 +388,7 @@ poll_waitevents(void *arg) eno = gw_getsockerrno(dcb->fd); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [poll_waitevents] " "EPOLLHUP on dcb %p, fd %d. " "Errno %d, %s.", @@ -406,25 +406,13 @@ poll_waitevents(void *arg) eno = gw_getsockerrno(dcb->fd); if (eno == 0) { -#if 0 - simple_mutex_lock( - &dcb->dcb_write_lock, - true); - ss_info_dassert( - !dcb->dcb_write_active, - "Write already active"); - dcb->dcb_write_active = TRUE; -#endif - atomic_add(&pollStats.n_write, 1); + atomic_add( + &pollStats.n_write, + 1); dcb->func.write_ready(dcb); -#if 0 - dcb->dcb_write_active = FALSE; - simple_mutex_unlock( - &dcb->dcb_write_lock); -#endif } else { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [poll_waitevents] " "EPOLLOUT due %d, %s. " "dcb %p, fd %i", @@ -437,13 +425,6 @@ poll_waitevents(void *arg) } if (ev & EPOLLIN) { -#if 0 - simple_mutex_lock(&dcb->dcb_read_lock, - true); - ss_info_dassert(!dcb->dcb_read_active, - "Read already active"); - dcb->dcb_read_active = TRUE; -#endif if (dcb->state == DCB_STATE_LISTENING) { skygw_log_write( @@ -468,11 +449,6 @@ poll_waitevents(void *arg) atomic_add(&pollStats.n_read, 1); dcb->func.read(dcb); } -#if 0 - dcb->dcb_read_active = FALSE; - simple_mutex_unlock( - &dcb->dcb_read_lock); -#endif } } /**< for */ no_op = FALSE; diff --git a/server/include/dcb.h b/server/include/dcb.h index da042aaac..6a15b4509 100644 --- a/server/include/dcb.h +++ b/server/include/dcb.h @@ -156,11 +156,7 @@ typedef struct dcb { #endif dcb_role_t dcb_role; SPINLOCK dcb_initlock; - simple_mutex_t dcb_read_lock; - simple_mutex_t dcb_write_lock; - int fd; /**< The descriptor */ - bool dcb_read_active; - bool dcb_write_active; + int fd; /**< The descriptor */ dcb_state_t state; /**< Current descriptor state */ char *remote; /**< Address of remote end */ void *protocol; /**< The protocol specific state */ diff --git a/server/modules/protocol/mysql_backend.c b/server/modules/protocol/mysql_backend.c index 01f1ac435..48edc7ab0 100644 --- a/server/modules/protocol/mysql_backend.c +++ b/server/modules/protocol/mysql_backend.c @@ -253,7 +253,7 @@ static int gw_read_backend_event(DCB *dcb) { backend_protocol->state = MYSQL_IDLE; skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_read_backend_event] " "gw_receive_backend_auth succeed. " "dcb %p fd %d, user %s.", @@ -265,7 +265,7 @@ static int gw_read_backend_event(DCB *dcb) { default: ss_dassert(receive_rc == 0); skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_read_backend_event] " "gw_receive_backend_auth read " "successfully " @@ -436,7 +436,7 @@ static int gw_write_backend_event(DCB *dcb) { "Writing to backend failed due invalid Maxscale " "state."); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_write_backend_event] Write to backend " "dcb %p fd %d " "failed due invalid state %s.", @@ -454,7 +454,7 @@ static int gw_write_backend_event(DCB *dcb) { rc = 0; } else { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_write_backend_event] Dcb %p in state %s " "but there's nothing to write either.", pthread_self(), @@ -474,7 +474,7 @@ static int gw_write_backend_event(DCB *dcb) { rc = 1; return_rc: skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_write_backend_event] " "wrote to dcb %p fd %d, return %d", pthread_self(), @@ -508,7 +508,7 @@ gw_MySQLWrite_backend(DCB *dcb, GWBUF *queue) gwbuf_consume(queue, GWBUF_LENGTH(queue)); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_MySQLWrite_backend] Write to backend failed. " "Backend dcb %p fd %d is %s.", pthread_self(), @@ -602,7 +602,7 @@ static int gw_error_backend_event(DCB *dcb) { * rsession should never be NULL here. */ skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_error_backend_event] " "Call closeSession for backend " "session.", @@ -641,7 +641,7 @@ static int gw_create_backend_connection( if (protocol == NULL) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_create_backend_connection] Failed to create " "protocol object for backend connection.", pthread_self()); @@ -664,7 +664,7 @@ static int gw_create_backend_connection( protocol->fd = fd; protocol->state = MYSQL_CONNECTED; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_create_backend_connection] Established " "connection to %s:%i, protocol fd %d client " "fd %d.", @@ -680,7 +680,7 @@ static int gw_create_backend_connection( protocol->state = MYSQL_PENDING_CONNECT; protocol->fd = fd; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_create_backend_connection] Connection " "pending to %s:%i, protocol fd %d client fd %d.", pthread_self(), @@ -694,7 +694,7 @@ static int gw_create_backend_connection( ss_dassert(fd == -1); ss_dassert(protocol->state == MYSQL_ALLOC); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_create_backend_connection] Connection " "failed to %s:%i, protocol fd %d client fd %d.", pthread_self(), diff --git a/server/modules/protocol/mysql_client.c b/server/modules/protocol/mysql_client.c index c873b16ef..162148abc 100644 --- a/server/modules/protocol/mysql_client.c +++ b/server/modules/protocol/mysql_client.c @@ -977,7 +977,7 @@ int gw_MySQLAccept(DCB *listener) listener->stats.n_accepts++; #if defined(SS_DEBUG) skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_MySQLAccept] Accepted fd %d.", pthread_self(), c_sock); @@ -1046,7 +1046,7 @@ int gw_MySQLAccept(DCB *listener) else { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_MySQLAccept] Added dcb %p for fd " "%d to epoll set.", pthread_self(), diff --git a/server/modules/protocol/mysql_common.c b/server/modules/protocol/mysql_common.c index 9c3eeda8d..a4136cfd6 100644 --- a/server/modules/protocol/mysql_common.c +++ b/server/modules/protocol/mysql_common.c @@ -328,7 +328,7 @@ int gw_receive_backend_auth( (uint8_t *)calloc(1, GWBUF_LENGTH(head)+1); memcpy(tmpbuf, ptr, GWBUF_LENGTH(head)); skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_receive_backend_auth] Invalid " "authentication message from backend dcb %p " "fd %d, ptr[4] = %p, msg %s.", @@ -358,7 +358,7 @@ int gw_receive_backend_auth( */ rc = 0; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_receive_backend_auth] Read zero bytes from " "backend dcb %p fd %d in state %s. n %d, head %p, len %d", pthread_self(), @@ -374,7 +374,7 @@ int gw_receive_backend_auth( ss_dassert(n < 0 && head == NULL); rc = -1; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_receive_backend_auth] Reading from backend dcb %p " "fd %d in state %s failed. n %d, head %p, len %d", pthread_self(), @@ -672,7 +672,7 @@ int gw_do_connect_to_backend( } *fd = so; skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [gw_do_connect_to_backend] Connected to backend server " "%s:%d, fd %d.", pthread_self(), diff --git a/server/modules/routing/debugcmd.c b/server/modules/routing/debugcmd.c index fd726480d..f44031eb6 100644 --- a/server/modules/routing/debugcmd.c +++ b/server/modules/routing/debugcmd.c @@ -114,7 +114,7 @@ struct subcommand showoptions[] = { {0, 0, 0} } }; -extern void shutdown_gateway(); +extern void shutdown_maxscale(); static void shutdown_service(DCB *dcb, SERVICE *service); static void shutdown_monitor(DCB *dcb, MONITOR *monitor); @@ -122,16 +122,37 @@ static void shutdown_monitor(DCB *dcb, MONITOR *monitor); * The subcommands of the shutdown command */ struct subcommand shutdownoptions[] = { - { "maxscale", 0, shutdown_gateway, "Shutdown the MaxScale gateway", - {0, 0, 0} }, - { "monitor", 1, shutdown_monitor, "Shutdown a monitor, e.g. shutdown monitor 0x48381e0", - {ARG_TYPE_ADDRESS, 0, 0} }, - { "service", 1, shutdown_service, "Shutdown a service, e.g. shutdown service 0x4838320", - {ARG_TYPE_ADDRESS, 0, 0} }, - { NULL, 0, NULL, NULL, - {0, 0, 0} } + { "maxscale", + 0, + shutdown_maxscale, + "Shutdown MaxScale", + + {0, 0, 0} + }, + { + "monitor", + 1, + shutdown_monitor, + "Shutdown a monitor, e.g. shutdown monitor 0x48381e0", + {ARG_TYPE_ADDRESS, 0, 0} + }, + { + "service", + 1, + shutdown_service, + "Shutdown a service, e.g. shutdown service 0x4838320", + {ARG_TYPE_ADDRESS, 0, 0} + }, + { + NULL, + 0, + NULL, + NULL, + {0, 0, 0} + } }; + static void restart_service(DCB *dcb, SERVICE *service); static void restart_monitor(DCB *dcb, MONITOR *monitor); /** @@ -216,8 +237,8 @@ struct subcommand disableoptions[] = { "log", 1, disable_log_action, - "Disable Log for MaxScale, Options: trace | error | message E.g. " - "disable log trace", + "Disable Log for MaxScale, Options: debug | trace | error | message " + "E.g. disable log debug", {ARG_TYPE_STRING, 0, 0} }, { @@ -726,7 +747,9 @@ static void enable_log_action(DCB *dcb, char *arg1) { logfile_id_t type; int max_len = strlen("message"); - if (strncmp(arg1, "trace", max_len) == 0) { + if (strncmp(arg1, "debug", max_len) == 0) { + type = LOGFILE_DEBUG; + } else if (strncmp(arg1, "trace", max_len) == 0) { type = LOGFILE_TRACE; } else if (strncmp(arg1, "error", max_len) == 0) { type = LOGFILE_ERROR; @@ -748,7 +771,9 @@ static void disable_log_action(DCB *dcb, char *arg1) { logfile_id_t type; int max_len = strlen("message"); - if (strncmp(arg1, "trace", max_len) == 0) { + if (strncmp(arg1, "debug", max_len) == 0) { + type = LOGFILE_DEBUG; + } else if (strncmp(arg1, "trace", max_len) == 0) { type = LOGFILE_TRACE; } else if (strncmp(arg1, "error", max_len) == 0) { type = LOGFILE_ERROR; diff --git a/server/modules/routing/readconnroute.c b/server/modules/routing/readconnroute.c index cd668c8f7..0a527350e 100644 --- a/server/modules/routing/readconnroute.c +++ b/server/modules/routing/readconnroute.c @@ -282,7 +282,7 @@ BACKEND *candidate = NULL; int i; skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [newSession] new router session with session " "%p, and inst %p.", pthread_self(), @@ -322,7 +322,7 @@ int i; for (i = 0; inst->servers[i]; i++) { if(inst->servers[i]) { skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [newSession] Examine server in port %d with " "%d connections. Status is %d, " "inst->bitvalue is %d", @@ -383,7 +383,7 @@ int i; atomic_add(&candidate->current_connection_count, 1); client_rses->backend = candidate; skygw_log_write( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [newSession] Selected server in port %d. " "Connections : %d\n", pthread_self(), @@ -465,7 +465,7 @@ static void freeSession( spinlock_release(&router->lock); skygw_log_write_flush( - LOGFILE_TRACE, + LOGFILE_DEBUG, "%lu [freeSession] Unlinked router_client_session %p from " "router %p and from server on port %d. Connections : %d. ", pthread_self(), diff --git a/server/modules/routing/readwritesplit/readwritesplit.c b/server/modules/routing/readwritesplit/readwritesplit.c index a6b6bb7e4..a59def81f 100644 --- a/server/modules/routing/readwritesplit/readwritesplit.c +++ b/server/modules/routing/readwritesplit/readwritesplit.c @@ -547,14 +547,16 @@ static int routeQuery( "%s.", STRPACKETTYPE(packet_type), STRQTYPE(qtype), - querystr, + (querystr == NULL ? "(empty)" : querystr), (rses_is_closed ? "Router was closed" : "Router has no backend servers where to route to")); goto return_ret; } - skygw_log_write(LOGFILE_TRACE, "String\t\"%s\"", querystr); + skygw_log_write(LOGFILE_TRACE, + "String\t\"%s\"", + querystr == NULL ? "(empty)" : querystr); skygw_log_write(LOGFILE_TRACE, "Packet type\t%s", STRPACKETTYPE(packet_type)); @@ -590,7 +592,7 @@ static int routeQuery( case QUERY_TYPE_SESSION_WRITE: skygw_log_write(LOGFILE_TRACE, "%lu [routeQuery:rwsplit] Query type\t%s, " - "routing to All servers.", + "routing to all servers.", pthread_self(), STRQTYPE(qtype)); /** @@ -865,8 +867,8 @@ static bool search_backend_servers( if (be != NULL) { skygw_log_write( LOGFILE_TRACE, - "%lu [search_backend_servers] Examine server %s:%d " - "with %d connections. Status is %d, " + "%lu [search_backend_servers] Examine server " + "%s:%d with %d connections. Status is %d, " "router->bitvalue is %d", pthread_self(), be->backend_server->name, @@ -931,7 +933,8 @@ static bool search_backend_servers( succp = false; skygw_log_write_flush( LOGFILE_ERROR, - "Error : Couldn't find suitable Slave from %d candidates.", + "Error : Couldn't find suitable Slave from %d " + "candidates.", i); } @@ -939,7 +942,8 @@ static bool search_backend_servers( succp = false; skygw_log_write_flush( LOGFILE_ERROR, - "Error : Couldn't find suitable Master from %d candidates.", + "Error : Couldn't find suitable Master from %d " + "candidates.", i); } diff --git a/utils/skygw_debug.h b/utils/skygw_debug.h index 19bb52e39..92d022d4f 100644 --- a/utils/skygw_debug.h +++ b/utils/skygw_debug.h @@ -19,6 +19,7 @@ #include #include #include +#include #define __USE_UNIX98 1 #include @@ -120,16 +121,19 @@ typedef enum skygw_chk_t { } skygw_chk_t; # define STRBOOL(b) ((b) ? "true" : "false") + # define STRQTYPE(t) ((t) == QUERY_TYPE_WRITE ? "QUERY_TYPE_WRITE" : \ ((t) == QUERY_TYPE_READ ? "QUERY_TYPE_READ" : \ ((t) == QUERY_TYPE_SESSION_WRITE ? "QUERY_TYPE_SESSION_WRITE" : \ ((t) == QUERY_TYPE_UNKNOWN ? "QUERY_TYPE_UNKNWON" : \ ((t) == QUERY_TYPE_LOCAL_READ ? "QUERY_TYPE_LOCAL_READ" : \ "Unknown query type"))))) + #define STRLOGID(i) ((i) == LOGFILE_TRACE ? "LOGFILE_TRACE" : \ - ((i) == LOGFILE_MESSAGE ? "LOGFILE_MESSAGE" : \ - ((i) == LOGFILE_ERROR ? "LOGFILE_ERROR" : \ - "Unknown logfile type"))) + ((i) == LOGFILE_MESSAGE ? "LOGFILE_MESSAGE" : \ + ((i) == LOGFILE_ERROR ? "LOGFILE_ERROR" : \ + ((i) == LOGFILE_DEBUG ? "LOGFILE_DEBUG" : \ + "Unknown logfile type")))) #define STRPACKETTYPE(p) ((p) == COM_INIT_DB ? "COM_INIT_DB" : \ ((p) == COM_CREATE_DB ? "COM_CREATE_DB" : \ @@ -285,11 +289,11 @@ typedef enum skygw_chk_t { ss_info_dassert((n->slnode_chk_top == CHK_NUM_SLIST_NODE && \ n->slnode_chk_tail == CHK_NUM_SLIST_NODE), \ "Single-linked list node under- or overflow"); \ - } + } #define CHK_SLIST_CURSOR(c) { \ - ss_info_dassert(c->slcursor_chk_top == CHK_NUM_SLIST_CURSOR && \ - c->slcursor_chk_tail == CHK_NUM_SLIST_CURSOR, \ + ss_info_dassert(c->slcursor_chk_top == CHK_NUM_SLIST_CURSOR && \ + c->slcursor_chk_tail == CHK_NUM_SLIST_CURSOR, \ "List cursor under- or overflow"); \ ss_info_dassert(c->slcursor_list != NULL, \ "List cursor doesn't have list"); \ @@ -297,34 +301,35 @@ typedef enum skygw_chk_t { (c->slcursor_pos == NULL && \ c->slcursor_list->slist_head == NULL), \ "List cursor doesn't have position"); \ - } + } -#define CHK_QUERY_TEST(q) { \ - ss_info_dassert(q->qt_chk_top == CHK_NUM_QUERY_TEST && \ - q->qt_chk_tail == CHK_NUM_QUERY_TEST, \ - "Query test under- or overflow."); \ - } +#define CHK_QUERY_TEST(q) { \ + ss_info_dassert(q->qt_chk_top == CHK_NUM_QUERY_TEST && \ + q->qt_chk_tail == CHK_NUM_QUERY_TEST, \ + "Query test under- or overflow."); \ + } #define CHK_LOGFILE(lf) { \ - ss_info_dassert(lf->lf_chk_top == CHK_NUM_LOGFILE && \ + ss_info_dassert(lf->lf_chk_top == CHK_NUM_LOGFILE && \ lf->lf_chk_tail == CHK_NUM_LOGFILE, \ "Logfile struct under- or overflow"); \ - ss_info_dassert(lf->lf_logpath != NULL && \ - lf->lf_name_prefix != NULL && \ - lf->lf_name_suffix != NULL && \ - lf->lf_full_name != NULL, \ - "NULL in name variable\n"); \ + ss_info_dassert(lf->lf_filepath != NULL && \ + lf->lf_name_prefix != NULL && \ + lf->lf_name_suffix != NULL && \ + lf->lf_full_file_name != NULL, \ + "NULL in name variable\n"); \ ss_info_dassert(lf->lf_id >= LOGFILE_FIRST && \ - lf->lf_id <= LOGFILE_LAST, \ - "Invalid logfile id\n"); \ + lf->lf_id <= LOGFILE_LAST, \ + "Invalid logfile id\n"); \ + ss_debug( \ (lf->lf_chk_top != CHK_NUM_LOGFILE || \ lf->lf_chk_tail != CHK_NUM_LOGFILE ? \ false : \ - (lf->lf_logpath == NULL || \ + (lf->lf_filepath == NULL || \ lf->lf_name_prefix == NULL || \ lf->lf_name_suffix == NULL || \ - lf->lf_full_name == NULL ? false : true)); \ - } + lf->lf_full_file_name == NULL ? false : true));) \ + } #define CHK_FILEWRITER(fwr) { \ ss_info_dassert(fwr->fwr_chk_top == CHK_NUM_FILEWRITER && \ diff --git a/utils/skygw_utils.cc b/utils/skygw_utils.cc index ef638b10b..5fdd706e2 100644 --- a/utils/skygw_utils.cc +++ b/utils/skygw_utils.cc @@ -279,8 +279,9 @@ mlist_node_t* mlist_detach_nodes( * @return Address of mlist_t struct. * * - * @details Cursor must protect its reads with read lock, and after acquiring - * read lock reader must check whether the list is deleted (mlist_deleted). + * @details Cursor must protect its reads with read lock, and after + * acquiring read lock reader must check whether the list is deleted + * (mlist_deleted). * */ mlist_t* mlist_init( @@ -1240,8 +1241,10 @@ simple_mutex_t* simple_mutex_init( sm = (simple_mutex_t *)calloc(1, sizeof(simple_mutex_t)); } ss_dassert(sm != NULL); +#if defined(SS_DEBUG) sm->sm_chk_top = CHK_NUM_SIMPLE_MUTEX; sm->sm_chk_tail = CHK_NUM_SIMPLE_MUTEX; +#endif sm->sm_name = name; /** Create pthread mutex */ @@ -1746,8 +1749,8 @@ return_succp: } skygw_file_t* skygw_file_init( - char* fname) - + char* fname, + char* symlinkname) { skygw_file_t* file; @@ -1780,16 +1783,46 @@ skygw_file_t* skygw_file_init( setvbuf(file->sf_file, NULL, _IONBF, 0); if (!file_write_header(file)) { + int eno = errno; + errno = 0; fprintf(stderr, - "* Writing header of log file %s failed.\n", - file->sf_fname); - perror("SkyGW file open\n"); + "* Writing header of log file %s failed due %d, %s.\n", + file->sf_fname, + eno, + strerror(eno)); free(file); file = NULL; goto return_file; } CHK_FILE(file); - ss_dfprintf(stderr, "Opened %s\n", file->sf_fname); + ss_dfprintf(stderr, "Opened %s\n", file->sf_fname); + + /** + * Create symlink to newly created file if name was provided. + */ + if (symlinkname != NULL) + { + int rc; + + unlink(symlinkname); + rc = symlink(fname, symlinkname); + + if (rc != 0) + { + int eno = errno; + errno = 0; + fprintf(stderr, + "failed to create symlink %s -> " + "%s due %d, %s. Exiting.", + fname, + symlinkname, + eno, + strerror(eno)); + free(file); + file = NULL; + goto return_file; + } + } return_file: return file; diff --git a/utils/skygw_utils.h b/utils/skygw_utils.h index aeadaca6c..4868fb511 100644 --- a/utils/skygw_utils.h +++ b/utils/skygw_utils.h @@ -145,7 +145,7 @@ EXTERN_C_BLOCK_END /** Skygw thread routines */ /** Skygw file routines */ -skygw_file_t* skygw_file_init(char* fname); +skygw_file_t* skygw_file_init(char* fname, char* symlinkname); void skygw_file_done(skygw_file_t* file); bool skygw_file_write( skygw_file_t* file,