diff options
Diffstat (limited to 'libglusterfs')
-rw-r--r-- | libglusterfs/src/Makefile.am | 3 | ||||
-rw-r--r-- | libglusterfs/src/common-utils.c | 241 | ||||
-rw-r--r-- | libglusterfs/src/common-utils.h | 1 | ||||
-rw-r--r-- | libglusterfs/src/glfs-message-id.h | 48 | ||||
-rw-r--r-- | libglusterfs/src/glusterfs.h | 1 | ||||
-rw-r--r-- | libglusterfs/src/logging.c | 1074 | ||||
-rw-r--r-- | libglusterfs/src/logging.h | 129 | ||||
-rw-r--r-- | libglusterfs/src/mem-pool.c | 6 | ||||
-rw-r--r-- | libglusterfs/src/mem-pool.h | 6 | ||||
-rw-r--r-- | libglusterfs/src/template-component-messages.h | 55 | ||||
-rw-r--r-- | libglusterfs/src/unittest/log_mock.c | 7 |
11 files changed, 1242 insertions, 329 deletions
diff --git a/libglusterfs/src/Makefile.am b/libglusterfs/src/Makefile.am index 634e217ed4d..b1a8536877d 100644 --- a/libglusterfs/src/Makefile.am +++ b/libglusterfs/src/Makefile.am @@ -42,7 +42,8 @@ noinst_HEADERS = common-utils.h defaults.h dict.h glusterfs.h hashfn.h timespec. $(CONTRIBDIR)/uuid/uuid.h $(CONTRIBDIR)/uuid/uuidP.h \ $(CONTRIB_BUILDDIR)/uuid/uuid_types.h syncop.h graph-utils.h trie.h \ run.h options.h lkowner.h fd-lk.h circ-buff.h event-history.h \ - gidcache.h client_t.h glusterfs-acl.h + gidcache.h client_t.h glusterfs-acl.h glfs-message-id.h \ + template-component-messages.h EXTRA_DIST = graph.l graph.y diff --git a/libglusterfs/src/common-utils.c b/libglusterfs/src/common-utils.c index 1dfb418e4a8..1ccb27d164c 100644 --- a/libglusterfs/src/common-utils.c +++ b/libglusterfs/src/common-utils.c @@ -281,26 +281,37 @@ err: struct xldump { int lineno; - FILE *logfp; }; - +/* to catch any format discrepencies that may arise in code */ +static int nprintf (struct xldump *dump, const char *fmt, ...) + __attribute__ ((__format__ (__printf__, 2, 3))); static int nprintf (struct xldump *dump, const char *fmt, ...) { - va_list ap; - int ret = 0; - + va_list ap; + char *msg = NULL; + char header[32]; + int ret = 0; - ret += fprintf (dump->logfp, "%3d: ", ++dump->lineno); + ret = snprintf (header, 32, "%3d:", ++dump->lineno); + if (ret < 0) + goto out; - va_start (ap, fmt); - ret += vfprintf (dump->logfp, fmt, ap); - va_end (ap); + va_start (ap, fmt); + ret = vasprintf (&msg, fmt, ap); + va_end (ap); + if (-1 == ret) + goto out; - ret += fprintf (dump->logfp, "\n"); + /* NOTE: No ret value from gf_msg_plain, so unable to compute printed + * characters. The return value from nprintf is not used, so for now + * living with it */ + gf_msg_plain (GF_LOG_WARNING, "%s %s", header, msg); - return ret; +out: + FREE (msg); + return 0; } @@ -349,175 +360,125 @@ xldump (xlator_t *each, void *d) xldump_subvolumes (each, d); nprintf (d, "end-volume"); - nprintf (d, ""); + nprintf (d, " "); } void gf_log_dump_graph (FILE *specfp, glusterfs_graph_t *graph) { - glusterfs_ctx_t *ctx; struct xldump xld = {0, }; - - ctx = THIS->ctx; - xld.logfp = ctx->log.gf_log_logfile; - - fprintf (ctx->log.gf_log_logfile, "Final graph:\n"); - fprintf (ctx->log.gf_log_logfile, - "+---------------------------------------" - "---------------------------------------+\n"); + gf_msg_plain (GF_LOG_WARNING, "Final graph:"); + gf_msg_plain (GF_LOG_WARNING, + "+---------------------------------------" + "---------------------------------------+"); xlator_foreach_depth_first (graph->top, xldump, &xld); - fprintf (ctx->log.gf_log_logfile, - "+---------------------------------------" - "---------------------------------------+\n"); - fflush (ctx->log.gf_log_logfile); + gf_msg_plain (GF_LOG_WARNING, + "+---------------------------------------" + "---------------------------------------+"); } static void -gf_dump_config_flags (int fd) +gf_dump_config_flags () { - int ret = 0; - - ret = write (fd, "configuration details:\n", 23); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "configuration details:"); /* have argp */ #ifdef HAVE_ARGP - ret = write (fd, "argp 1\n", 7); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "argp 1"); #endif /* ifdef if found backtrace */ #ifdef HAVE_BACKTRACE - ret = write (fd, "backtrace 1\n", 12); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "backtrace 1"); #endif /* Berkeley-DB version has cursor->get() */ #ifdef HAVE_BDB_CURSOR_GET - ret = write (fd, "bdb->cursor->get 1\n", 19); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "bdb->cursor->get 1"); #endif /* Define to 1 if you have the <db.h> header file. */ #ifdef HAVE_DB_H - ret = write (fd, "db.h 1\n", 7); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "db.h 1"); #endif /* Define to 1 if you have the <dlfcn.h> header file. */ #ifdef HAVE_DLFCN_H - ret = write (fd, "dlfcn 1\n", 8); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "dlfcn 1"); #endif /* define if fdatasync exists */ #ifdef HAVE_FDATASYNC - ret = write (fd, "fdatasync 1\n", 12); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "fdatasync 1"); #endif /* Define to 1 if you have the `pthread' library (-lpthread). */ #ifdef HAVE_LIBPTHREAD - ret = write (fd, "libpthread 1\n", 13); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "libpthread 1"); #endif /* define if llistxattr exists */ #ifdef HAVE_LLISTXATTR - ret = write (fd, "llistxattr 1\n", 13); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "llistxattr 1"); #endif /* define if found setfsuid setfsgid */ #ifdef HAVE_SET_FSID - ret = write (fd, "setfsid 1\n", 10); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "setfsid 1"); #endif /* define if found spinlock */ #ifdef HAVE_SPINLOCK - ret = write (fd, "spinlock 1\n", 11); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "spinlock 1"); #endif /* Define to 1 if you have the <sys/epoll.h> header file. */ #ifdef HAVE_SYS_EPOLL_H - ret = write (fd, "epoll.h 1\n", 10); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "epoll.h 1"); #endif /* Define to 1 if you have the <sys/extattr.h> header file. */ #ifdef HAVE_SYS_EXTATTR_H - ret = write (fd, "extattr.h 1\n", 12); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "extattr.h 1"); #endif /* Define to 1 if you have the <sys/xattr.h> header file. */ #ifdef HAVE_SYS_XATTR_H - ret = write (fd, "xattr.h 1\n", 10); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "xattr.h 1"); #endif /* define if found st_atim.tv_nsec */ #ifdef HAVE_STRUCT_STAT_ST_ATIM_TV_NSEC - ret = write (fd, "st_atim.tv_nsec 1\n", 18); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "st_atim.tv_nsec 1"); #endif /* define if found st_atimespec.tv_nsec */ #ifdef HAVE_STRUCT_STAT_ST_ATIMESPEC_TV_NSEC - ret = write (fd, "st_atimespec.tv_nsec 1\n",23); - if (ret == -1) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, "st_atimespec.tv_nsec 1"); #endif /* Define to the full name and version of this package. */ #ifdef PACKAGE_STRING { char msg[128]; - sprintf (msg, "package-string: %s\n", PACKAGE_STRING); - ret = write (fd, msg, strlen (msg)); - if (ret == -1) - goto out; + sprintf (msg, "package-string: %s", PACKAGE_STRING); + gf_msg_plain_nomem (GF_LOG_ALERT, msg); } #endif -out: return; } -/* Obtain a backtrace and print it to stdout. */ -/* TODO: It looks like backtrace_symbols allocates memory, - it may be problem because mostly memory allocation/free causes 'sigsegv' */ - +/* Obtain a backtrace and print it to the log */ void gf_print_trace (int32_t signum, glusterfs_ctx_t *ctx) { char msg[1024] = {0,}; char timestr[64] = {0,}; - int ret = 0; - int fd = 0; - - fd = fileno (ctx->log.gf_log_logfile); /* Now every gf_log call will just write to a buffer and when the * buffer becomes full, its written to the log-file. Suppose the process @@ -526,75 +487,51 @@ gf_print_trace (int32_t signum, glusterfs_ctx_t *ctx) * contents of the buffer to the log file before printing the backtrace * which helps in debugging. */ - fflush (ctx->log.gf_log_logfile); + gf_log_flush(); /* Pending frames, (if any), list them in order */ - ret = write (fd, "pending frames:\n", 16); - if (ret < 0) - goto out; - + gf_msg_plain_nomem (GF_LOG_ALERT, "pending frames:"); { - struct list_head *trav = ((call_pool_t *)ctx->pool)->all_frames.next; + struct list_head *trav = + ((call_pool_t *)ctx->pool)->all_frames.next; while (trav != (&((call_pool_t *)ctx->pool)->all_frames)) { - call_frame_t *tmp = (call_frame_t *)(&((call_stack_t *)trav)->frames); + call_frame_t *tmp = + (call_frame_t *)(&((call_stack_t *)trav)->frames); if (tmp->root->type == GF_OP_TYPE_FOP) - sprintf (msg,"frame : type(%d) op(%s)\n", + sprintf (msg,"frame : type(%d) op(%s)", tmp->root->type, gf_fop_list[tmp->root->op]); else - sprintf (msg,"frame : type(%d) op(%d)\n", + sprintf (msg,"frame : type(%d) op(%d)", tmp->root->type, tmp->root->op); - ret = write (fd, msg, strlen (msg)); - if (ret < 0) - goto out; + gf_msg_plain_nomem (GF_LOG_ALERT, msg); trav = trav->next; } - ret = write (fd, "\n", 1); - if (ret < 0) - goto out; } - sprintf (msg, "patchset: %s\n", GLUSTERFS_REPOSITORY_REVISION); - ret = write (fd, msg, strlen (msg)); - if (ret < 0) - goto out; - - sprintf (msg, "signal received: %d\n", signum); - ret = write (fd, msg, strlen (msg)); - if (ret < 0) - goto out; + sprintf (msg, "patchset: %s", GLUSTERFS_REPOSITORY_REVISION); + gf_msg_plain_nomem (GF_LOG_ALERT, msg); + sprintf (msg, "signal received: %d", signum); + gf_msg_plain_nomem (GF_LOG_ALERT, msg); { /* Dump the timestamp of the crash too, so the previous logs can be related */ - gf_time_fmt (timestr, sizeof timestr, time (NULL), gf_timefmt_FT); - ret = write (fd, "time of crash: ", 15); - if (ret < 0) - goto out; - ret = write (fd, timestr, strlen (timestr)); - if (ret < 0) - goto out; + gf_time_fmt (timestr, sizeof timestr, time (NULL), + gf_timefmt_FT); + gf_msg_plain_nomem (GF_LOG_ALERT, "time of crash: "); + gf_msg_plain_nomem (GF_LOG_ALERT, timestr); } - gf_dump_config_flags (fd); + gf_dump_config_flags (); #if HAVE_BACKTRACE - /* Print 'backtrace' */ - { - void *array[200]; - size_t size; - - size = backtrace (array, 200); - backtrace_symbols_fd (&array[1], size-1, fd); - sprintf (msg, "---------\n"); - ret = write (fd, msg, strlen (msg)); - if (ret < 0) - goto out; - } + gf_msg_backtrace_nomem (GF_LOG_ALERT, 200); + sprintf (msg, "---------"); + gf_msg_plain_nomem (GF_LOG_ALERT, msg); #endif /* HAVE_BACKTRACE */ -out: /* Send a signal to terminate the process */ signal (signum, SIG_DFL); raise (signum); @@ -2919,6 +2856,42 @@ done: } int +gf_set_log_ident (cmd_args_t *cmd_args) +{ + int ret = 0; + char *ptr = NULL; + + if (cmd_args->log_file == NULL) { + /* no ident source */ + return 0; + } + + /* TODO: Some idents would look like, etc-glusterfs-glusterd.vol, which + * seems ugly and can be bettered? */ + /* just get the filename as the ident */ + if (NULL != (ptr = strrchr (cmd_args->log_file, '/'))) { + ret = gf_asprintf (&cmd_args->log_ident, "%s", ptr + 1); + } else { + ret = gf_asprintf (&cmd_args->log_ident, "%s", + cmd_args->log_file); + } + + if (ret > 0) + ret = 0; + else + return ret; + + /* remove .log suffix */ + if (NULL != (ptr = strrchr (cmd_args->log_ident, '.'))) { + if (strcmp (ptr, ".log") == 0) { + ptr[0] = '\0'; + } + } + + return ret; +} + +int gf_thread_create (pthread_t *thread, const pthread_attr_t *attr, void *(*start_routine)(void *), void *arg) { diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h index f877590f4ca..ee4e5b7e6ee 100644 --- a/libglusterfs/src/common-utils.h +++ b/libglusterfs/src/common-utils.h @@ -121,6 +121,7 @@ int32_t gf_resolve_ip6 (const char *hostname, uint16_t port, int family, void gf_log_dump_graph (FILE *specfp, glusterfs_graph_t *graph); void gf_print_trace (int32_t signal, glusterfs_ctx_t *ctx); int gf_set_log_file_path (cmd_args_t *cmd_args); +int gf_set_log_ident (cmd_args_t *cmd_args); #define VECTORSIZE(count) (count * (sizeof (struct iovec))) diff --git a/libglusterfs/src/glfs-message-id.h b/libglusterfs/src/glfs-message-id.h new file mode 100644 index 00000000000..42c16f12d91 --- /dev/null +++ b/libglusterfs/src/glfs-message-id.h @@ -0,0 +1,48 @@ +/* + Copyright (c) 2013 Red Hat, Inc. <http://www.redhat.com> + This file is part of GlusterFS. + + This file is licensed to you under your choice of the GNU Lesser + General Public License, version 3 or any later version (LGPLv3 or + later), or the GNU General Public License, version 2 (GPLv2), in all + cases as published by the Free Software Foundation. +*/ + +#ifndef _GLFS_MESSAGE_ID_H_ +#define _GLFS_MESSAGE_ID_H_ + +#ifndef _CONFIG_H +#define _CONFIG_H +#include "config.h" +#endif + +/* Base of all message IDs, all message IDs would be + * greater than this */ +#define GLFS_MSGID_BASE 100000 + +/* Segment size of allocated range. Any component needing more than this + * segment size should take multiple segments (at times non contiguous, + * if extensions are being made post the next segment already allocated) */ +#define GLFS_MSGID_SEGMENT 1000 + +/* Per module message segments allocated */ +/* NOTE: For any new module add to the end the modules */ +#define GLFS_MSGID_COMP_GLUSTERFSD GLFS_MSGID_BASE +#define GLFS_MSGID_COMP_LIBGLUSTERFS GLFS_MSGID_COMP_GLUSTERFSD + \ + GLFS_MSGID_SEGMENT +#define GLFS_MSGID_COMP_RPC_LIB GLFS_MSGID_COMP_LIBGLUSTERFS + \ + GLFS_MSGID_SEGMENT +#define GLFS_MSGID_COMP_RPC_TRANSPORT GLFS_MSGID_COMP_RPC_LIB + \ + GLFS_MSGID_SEGMENT +#define GLFS_MSGID_COMP_API GLFS_MSGID_COMP_RPC_TRANSPORT + \ + GLFS_MSGID_SEGMENT +#define GLFS_MSGID_COMP_CLI GLFS_MSGID_COMP_API + \ + GLFS_MSGID_SEGMENT +/* glusterd has a lot of messages, taking 2 segments for the same */ +#define GLFS_MSGID_GLUSTERD GLFS_MSGID_COMP_CLI + \ + GLFS_MSGID_SEGMENT + \ + GLFS_MSGID_SEGMENT + +/* --- new segments for messages goes above this line --- */ + +#endif /* !_GLFS_MESSAGE_ID_H_ */ diff --git a/libglusterfs/src/glusterfs.h b/libglusterfs/src/glusterfs.h index 5ce0d6e70bb..852d686c13c 100644 --- a/libglusterfs/src/glusterfs.h +++ b/libglusterfs/src/glusterfs.h @@ -342,6 +342,7 @@ struct _cmd_args { char *log_server; gf_loglevel_t log_level; char *log_file; + char *log_ident; int32_t max_connect_attempts; /* advanced options */ uint32_t volfile_server_port; diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c index 2bd40b2c2d6..f343731c7f4 100644 --- a/libglusterfs/src/logging.c +++ b/libglusterfs/src/logging.c @@ -22,7 +22,6 @@ #include <string.h> #include <stdlib.h> -#ifdef GF_USE_SYSLOG #include <libintl.h> #include <syslog.h> #include <sys/stat.h> @@ -32,7 +31,9 @@ #define GF_SYSLOG_CEE_FORMAT \ "@cee: {\"msg\": \"%s\", \"gf_code\": \"%u\", \"gf_message\": \"%s\"}" #define GF_LOG_CONTROL_FILE "/etc/glusterfs/logger.conf" -#endif /* GF_USE_SYSLOG */ +#define GF_LOG_BACKTRACE_DEPTH 5 +#define GF_LOG_BACKTRACE_SIZE 4096 +#define GF_LOG_TIMESTR_SIZE 256 #include "xlator.h" #include "logging.h" @@ -47,6 +48,19 @@ #include <execinfo.h> #endif +static char *gf_level_strings[] = {"", /* NONE */ + "M", /* EMERGENCY */ + "A", /* ALERT */ + "C", /* CRITICAL */ + "E", /* ERROR */ + "W", /* WARNING */ + "N", /* NOTICE */ + "I", /* INFO */ + "D", /* DEBUG */ + "T", /* TRACE */ + "" +}; + /* Ideally this should get moved to logging.h */ struct _msg_queue { struct list_head msgs; @@ -60,41 +74,77 @@ struct _log_msg { void gf_log_logrotate (int signum) { - THIS->ctx->log.logrotate = 1; + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.logrotate = 1; } void gf_log_enable_syslog (void) { - THIS->ctx->log.gf_log_syslog = 1; + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.gf_log_syslog = 1; } void gf_log_disable_syslog (void) { - THIS->ctx->log.gf_log_syslog = 0; + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.gf_log_syslog = 0; } gf_loglevel_t gf_log_get_loglevel (void) { - return THIS->ctx->log.loglevel; + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + return ctx->log.loglevel; + else + /* return global defaluts (see gf_log_globals_init) */ + return GF_LOG_INFO; } void gf_log_set_loglevel (gf_loglevel_t level) { - THIS->ctx->log.loglevel = level; -} + glusterfs_ctx_t *ctx = NULL; + ctx = THIS->ctx; -gf_loglevel_t -gf_log_get_xl_loglevel (void *this) + if (ctx) + ctx->log.loglevel = level; +} + +void +gf_log_flush (void) { - xlator_t *xl = this; - if (!xl) - return 0; - return xl->loglevel; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + if (ctx && ctx->log.logger == gf_logger_glusterlog) { + pthread_mutex_lock (&ctx->log.logfile_mutex); + fflush (ctx->log.gf_log_logfile); + pthread_mutex_unlock (&ctx->log.logfile_mutex); + } + + return; } void @@ -107,9 +157,142 @@ gf_log_set_xl_loglevel (void *this, gf_loglevel_t level) xl->loglevel = level; } +/* TODO: The following get/set functions are yet not invoked from anywhere + * in the code. The _intention_ is to pass CLI arguments to various daemons + * that are started, which would then invoke these set APIs as required. + * + * glusterd would read the defaults from its .vol file configuration shipped + * as a part of the packages distributed. + * + * For any gluster* daemon that is started the shipped configuration becomes the + * default, if a volume has to change its logging format or logger, then a + * gluster CLI is invoked to set this property for the volume in question. + * + * The property is maintained by glusterd, and passed to the daemon as a CLI + * option, IOW persistence of the option is maintained by glusterd persistent + * storage (i.e .vol file) only + * + * care needs to be taken to configure and start daemons based on the versions + * that supports these features */ +gf_log_format_t +gf_log_get_logformat (void) +{ + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + return ctx->log.logformat; + else + /* return global defaluts (see gf_log_globals_init) */ + return gf_logformat_withmsgid; +} + +void +gf_log_set_logformat (gf_log_format_t format) +{ + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.logformat = format; +} + +gf_log_logger_t +gf_log_get_logger (void) +{ + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + return ctx->log.logger; + else + /* return global defaluts (see gf_log_globals_init) */ + return gf_logger_glusterlog; +} + +void +gf_log_set_logger (gf_log_logger_t logger) +{ + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.logger = logger; +} + +gf_loglevel_t +gf_log_get_xl_loglevel (void *this) +{ + xlator_t *xl = this; + if (!xl) + return 0; + return xl->loglevel; +} + +static void +gf_log_rotate(glusterfs_ctx_t *ctx) +{ + int fd = -1; + FILE *new_logfile = NULL; + FILE *old_logfile = NULL; + + /* not involving locks on initial check to speed it up */ + if (ctx->log.logrotate) { + /* let only one winner through on races */ + pthread_mutex_lock (&ctx->log.logfile_mutex); + + if (!ctx->log.logrotate) { + pthread_mutex_unlock (&ctx->log.logfile_mutex); + return; + } else { + ctx->log.logrotate = 0; + pthread_mutex_unlock (&ctx->log.logfile_mutex); + } + + fd = open (ctx->log.filename, + O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR); + if (fd < 0) { + gf_log ("logrotate", GF_LOG_ERROR, + "%s", strerror (errno)); + return; + } + close (fd); + + new_logfile = fopen (ctx->log.filename, "a"); + if (!new_logfile) { + gf_log ("logrotate", GF_LOG_CRITICAL, + "failed to open logfile %s (%s)", + ctx->log.filename, strerror (errno)); + return; + } + + pthread_mutex_lock (&ctx->log.logfile_mutex); + { + if (ctx->log.logfile) + old_logfile = ctx->log.logfile; + + ctx->log.gf_log_logfile = ctx->log.logfile = + new_logfile; + } + pthread_mutex_unlock (&ctx->log.logfile_mutex); + + if (old_logfile != NULL) + fclose (old_logfile); + } + + return; +} + void gf_log_globals_fini (void) { + /* TODO: Nobody is invoking the fini, but cleanup needs to happen here, + * needs cleanup for, log.ident, log.filename, closelog, log file close + * rotate state, possibly under a lock */ pthread_mutex_destroy (&THIS->ctx->log.logfile_mutex); } @@ -122,7 +305,8 @@ int gf_log_fini (void *data) { glusterfs_ctx_t *ctx = data; - int ret = 0; + int ret = 0; + FILE *old_logfile = NULL; if (ctx == NULL) { ret = -1; @@ -132,8 +316,8 @@ gf_log_fini (void *data) pthread_mutex_lock (&ctx->log.logfile_mutex); { if (ctx->log.logfile) { - if (fclose (ctx->log.logfile) != 0) - ret = -1; + old_logfile = ctx->log.logfile; + /* Logfile needs to be set to NULL, so that any call to gf_log after calling gf_log_fini, will log the message to stderr. @@ -144,11 +328,13 @@ gf_log_fini (void *data) } pthread_mutex_unlock (&ctx->log.logfile_mutex); + if (old_logfile && (fclose (old_logfile) != 0)) + ret = -1; + out: return ret; } -#ifdef GF_USE_SYSLOG /** * gf_get_error_message -function to get error message for given error code * @error_code: error code defined by log book @@ -186,10 +372,13 @@ gf_openlog (const char *ident, int option, int facility) _facility = LOG_LOCAL1; } + /* TODO: Should check for errors here and return appropriately */ setlocale(LC_ALL, ""); bindtextdomain("gluster", "/usr/share/locale"); textdomain("gluster"); + /* close the previous syslog if open as we are changing settings */ + closelog (); openlog(ident, _option, _facility); } @@ -347,7 +536,6 @@ gf_syslog (int error_code, int facility_priority, char *format, ...) } va_end (ap); } -#endif /* GF_USE_SYSLOG */ void gf_log_globals_init (void *data) @@ -359,47 +547,45 @@ gf_log_globals_init (void *data) ctx->log.loglevel = GF_LOG_INFO; ctx->log.gf_log_syslog = 1; ctx->log.sys_log_level = GF_LOG_CRITICAL; + ctx->log.logger = gf_logger_glusterlog; + ctx->log.logformat = gf_logformat_withmsgid; -#ifndef GF_USE_SYSLOG #ifdef GF_LINUX_HOST_OS /* For the 'syslog' output. one can grep 'GlusterFS' in syslog for serious logs */ openlog ("GlusterFS", LOG_PID, LOG_DAEMON); #endif -#endif + } int gf_log_init (void *data, const char *file, const char *ident) { glusterfs_ctx_t *ctx = NULL; - int fd = -1; + int fd = -1; + struct stat buf; ctx = data; -#if defined(GF_USE_SYSLOG) - { - /* use default ident and option */ - /* TODO: make FACILITY configurable than LOG_DAEMON */ - struct stat buf; - - if (stat (GF_LOG_CONTROL_FILE, &buf) == 0) { - /* use syslog logging */ - ctx->log.log_control_file_found = 1; - if (ident) { - /* we need to keep this value as */ - /* syslog uses it on every logging */ - ctx->log.ident = gf_strdup (ident); - gf_openlog (ctx->log.ident, -1, LOG_DAEMON); - } else { - gf_openlog (NULL, -1, LOG_DAEMON); - } - } else { - /* use old style logging */ - ctx->log.log_control_file_found = 0; - } + if (ident) { + ctx->log.ident = gf_strdup (ident); + } + + /* we keep the files and the syslog open, so that on logger change, we + * are ready to log anywhere, that the new value specifies */ + if (ctx->log.ident) { + gf_openlog (ctx->log.ident, -1, LOG_DAEMON); + } else { + gf_openlog (NULL, -1, LOG_DAEMON); + } + /* TODO: make FACILITY configurable than LOG_DAEMON */ + if (stat (GF_LOG_CONTROL_FILE, &buf) == 0) { + /* use syslog logging */ + ctx->log.log_control_file_found = 1; + } else { + /* use old style logging */ + ctx->log.log_control_file_found = 0; } -#endif if (!file){ fprintf (stderr, "ERROR: no filename specified\n"); @@ -407,7 +593,7 @@ gf_log_init (void *data, const char *file, const char *ident) } if (strcmp (file, "-") == 0) { - file = "/dev/stderr"; + file = "/dev/stderr"; } ctx->log.filename = gf_strdup (file); @@ -419,8 +605,8 @@ gf_log_init (void *data, const char *file, const char *ident) fd = open (file, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR); if (fd < 0) { - fprintf (stderr, "ERROR: failed to create logfile \"%s\" (%s)\n", - file, strerror (errno)); + fprintf (stderr, "ERROR: failed to create logfile" + " \"%s\" (%s)\n", file, strerror (errno)); return -1; } close (fd); @@ -440,21 +626,29 @@ gf_log_init (void *data, const char *file, const char *ident) void set_sys_log_level (gf_loglevel_t level) { - THIS->ctx->log.sys_log_level = level; + glusterfs_ctx_t *ctx = NULL; + + ctx = THIS->ctx; + + if (ctx) + ctx->log.sys_log_level = level; } int -_gf_log_nomem (const char *domain, const char *file, - const char *function, int line, gf_loglevel_t level, - size_t size) +_gf_log_callingfn (const char *domain, const char *file, const char *function, + int line, gf_loglevel_t level, const char *fmt, ...) { const char *basename = NULL; xlator_t *this = NULL; - struct timeval tv = {0,}; - int ret = 0; - char msg[8092] = {0,}; + char *str1 = NULL; + char *str2 = NULL; + char *msg = NULL; char timestr[256] = {0,}; char callstr[4096] = {0,}; + struct timeval tv = {0,}; + size_t len = 0; + int ret = 0; + va_list ap; glusterfs_ctx_t *ctx = NULL; this = THIS; @@ -479,7 +673,7 @@ _gf_log_nomem (const char *domain, const char *file, "T", /* TRACE */ ""}; - if (!domain || !file || !function) { + if (!domain || !file || !function || !fmt) { fprintf (stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__, __PRETTY_FUNCTION__, __LINE__); @@ -497,28 +691,27 @@ _gf_log_nomem (const char *domain, const char *file, do { void *array[5]; char **callingfn = NULL; - size_t bt_size = 0; + size_t size = 0; - bt_size = backtrace (array, 5); - if (bt_size) - callingfn = backtrace_symbols (&array[2], bt_size-2); + size = backtrace (array, 5); + if (size) + callingfn = backtrace_symbols (&array[2], size-2); if (!callingfn) break; - if (bt_size == 5) + if (size == 5) snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))", callingfn[2], callingfn[1], callingfn[0]); - if (bt_size == 4) + if (size == 4) snprintf (callstr, 4096, "(-->%s (-->%s))", callingfn[1], callingfn[0]); - if (bt_size == 3) + if (size == 3) snprintf (callstr, 4096, "(-->%s)", callingfn[0]); free (callingfn); } while (0); #endif /* HAVE_BACKTRACE */ -#if defined(GF_USE_SYSLOG) if (ctx->log.log_control_file_found) { int priority; @@ -529,30 +722,50 @@ _gf_log_nomem (const char *domain, const char *file, } else { priority = level - 1; } + + va_start (ap, fmt); + vasprintf (&str2, fmt, ap); + va_end (ap); + gf_syslog (GF_ERR_DEV, priority, - "[%s:%d:%s] %s %s: no memory " - "available for size (%"GF_PRI_SIZET")", - basename, line, function, callstr, domain, - size); + "[%s:%d:%s] %s %d-%s: %s", + basename, line, function, + callstr, + ((this->graph) ? this->graph->id:0), domain, + str2); + goto out; } -#endif /* GF_USE_SYSLOG */ + ret = gettimeofday (&tv, NULL); if (-1 == ret) goto out; + va_start (ap, fmt); gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr), ".%"GF_PRI_SUSECONDS, tv.tv_usec); - ret = sprintf (msg, "[%s] %s [%s:%d:%s] %s %s: no memory " - "available for size (%"GF_PRI_SIZET")", - timestr, level_strings[level], - basename, line, function, callstr, - domain, size); + ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %s %d-%s: ", + timestr, level_strings[level], + basename, line, function, callstr, + ((this->graph) ? this->graph->id:0), domain); + if (-1 == ret) { + goto out; + } + + ret = vasprintf (&str2, fmt, ap); if (-1 == ret) { goto out; } + va_end (ap); + + len = strlen (str1); + msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char); + + strcpy (msg, str1); + strcpy (msg + len, str2); + pthread_mutex_lock (&ctx->log.logfile_mutex); { if (ctx->log.logfile) { @@ -571,30 +784,82 @@ _gf_log_nomem (const char *domain, const char *file, } pthread_mutex_unlock (&ctx->log.logfile_mutex); + out: + GF_FREE (msg); + + GF_FREE (str1); + + FREE (str2); + return ret; - } +} int -_gf_log_callingfn (const char *domain, const char *file, const char *function, - int line, gf_loglevel_t level, const char *fmt, ...) +_gf_msg_plain_internal (gf_loglevel_t level, const char *msg) { - const char *basename = NULL; - xlator_t *this = NULL; - char *str1 = NULL; - char *str2 = NULL; - char *msg = NULL; - char timestr[256] = {0,}; - char callstr[4096] = {0,}; - struct timeval tv = {0,}; - size_t len = 0; - int ret = 0; - va_list ap; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + int priority; + + this = THIS; + ctx = this->ctx; + + /* log to the configured logging service */ + switch (ctx->log.logger) { + case gf_logger_syslog: + if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) { + SET_LOG_PRIO (level, priority); + + syslog (priority, "%s", msg); + break; + } + /* NOTE: If syslog control file is absent, which is another + * way to control logging to syslog, then we will fall through + * to the gluster log. The ideal way to do things would be to + * not have the extra control file check */ + case gf_logger_glusterlog: + pthread_mutex_lock (&ctx->log.logfile_mutex); + { + if (ctx->log.logfile) { + fprintf (ctx->log.logfile, "%s\n", msg); + fflush (ctx->log.logfile); + } else { + fprintf (stderr, "%s\n", msg); + fflush (stderr); + } + +#ifdef GF_LINUX_HOST_OS + /* We want only serious logs in 'syslog', not our debug + * and trace logs */ + if (ctx->log.gf_log_syslog && level && + (level <= ctx->log.sys_log_level)) + syslog ((level-1), "%s\n", msg); +#endif + } + pthread_mutex_unlock (&ctx->log.logfile_mutex); + + break; + } + + return 0; +} + +int +_gf_msg_plain (gf_loglevel_t level, const char *fmt, ...) +{ + xlator_t *this = NULL; + int ret = 0; + va_list ap; + char *msg = NULL; glusterfs_ctx_t *ctx = NULL; this = THIS; ctx = this->ctx; + if (!ctx) + goto out; + if (ctx->log.gf_log_xl_log_set) { if (this->loglevel && (level > this->loglevel)) goto out; @@ -602,141 +867,604 @@ _gf_log_callingfn (const char *domain, const char *file, const char *function, if (level > ctx->log.loglevel) goto out; - static char *level_strings[] = {"", /* NONE */ - "M", /* EMERGENCY */ - "A", /* ALERT */ - "C", /* CRITICAL */ - "E", /* ERROR */ - "W", /* WARNING */ - "N", /* NOTICE */ - "I", /* INFO */ - "D", /* DEBUG */ - "T", /* TRACE */ - ""}; + va_start (ap, fmt); + ret = vasprintf (&msg, fmt, ap); + va_end (ap); + if (-1 == ret) { + goto out; + } - if (!domain || !file || !function || !fmt) { - fprintf (stderr, - "logging: %s:%s():%d: invalid argument\n", - __FILE__, __PRETTY_FUNCTION__, __LINE__); - return -1; + ret = _gf_msg_plain_internal (level, msg); + + FREE (msg); + +out: + return ret; +} + +int +_gf_msg_vplain (gf_loglevel_t level, const char *fmt, va_list ap) +{ + xlator_t *this = NULL; + int ret = 0; + char *msg = NULL; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + if (!ctx) + goto out; + + if (ctx->log.gf_log_xl_log_set) { + if (this->loglevel && (level > this->loglevel)) + goto out; } + if (level > ctx->log.loglevel) + goto out; - basename = strrchr (file, '/'); - if (basename) - basename++; - else - basename = file; + ret = vasprintf (&msg, fmt, ap); + if (-1 == ret) { + goto out; + } + + ret = _gf_msg_plain_internal (level, msg); + + FREE (msg); +out: + return ret; +} + +int +_gf_msg_plain_nomem (gf_loglevel_t level, const char *msg) +{ + xlator_t *this = NULL; + int ret = 0; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + if (!ctx) + goto out; + + if (ctx->log.gf_log_xl_log_set) { + if (this->loglevel && (level > this->loglevel)) + goto out; + } + if (level > ctx->log.loglevel) + goto out; + + ret = _gf_msg_plain_internal (level, msg); + +out: + return ret; +} #if HAVE_BACKTRACE - /* Print 'calling function' */ - do { - void *array[5]; - char **callingfn = NULL; - size_t size = 0; +void +_gf_msg_backtrace_nomem (gf_loglevel_t level, int stacksize) +{ + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + void *array[200]; + size_t bt_size = 0; + int fd = -1; - size = backtrace (array, 5); - if (size) - callingfn = backtrace_symbols (&array[2], size-2); - if (!callingfn) - break; + this = THIS; + ctx = this->ctx; - if (size == 5) - snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))", - callingfn[2], callingfn[1], callingfn[0]); - if (size == 4) - snprintf (callstr, 4096, "(-->%s (-->%s))", - callingfn[1], callingfn[0]); - if (size == 3) - snprintf (callstr, 4096, "(-->%s)", callingfn[0]); + if (!ctx) + goto out; - free (callingfn); - } while (0); -#endif /* HAVE_BACKTRACE */ + /* syslog does not have fd support, hence no no-mem variant */ + if (ctx->log.logger != gf_logger_glusterlog) + goto out; -#if defined(GF_USE_SYSLOG) - if (ctx->log.log_control_file_found) + if (ctx->log.gf_log_xl_log_set) { + if (this->loglevel && (level > this->loglevel)) + goto out; + } + if (level > ctx->log.loglevel) + goto out; + + bt_size = backtrace (array, ((stacksize <= 200)? stacksize : 200)); + pthread_mutex_lock (&ctx->log.logfile_mutex); { - int priority; - /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and - other level as is */ - if (GF_LOG_TRACE == level || GF_LOG_NONE == level) { - priority = LOG_DEBUG; - } else { - priority = level - 1; + fd = ctx->log.logfile? + fileno (ctx->log.logfile) : + fileno (stderr); + if (bt_size && (fd != -1)) { + /* print to the file fd, to prevent any + * allocations from backtrace_symbols */ + backtrace_symbols_fd (&array[0], bt_size, fd); } + } + pthread_mutex_unlock (&ctx->log.logfile_mutex); - va_start (ap, fmt); - vasprintf (&str2, fmt, ap); - va_end (ap); +out: + return; +} - gf_syslog (GF_ERR_DEV, priority, - "[%s:%d:%s] %s %d-%s: %s", - basename, line, function, - callstr, - ((this->graph) ? this->graph->id:0), domain, - str2); +int +_gf_msg_backtrace (int stacksize, char *callstr, size_t strsize) +{ + int ret = -1; + int i = 0; + int size = 0; + int savstrsize = strsize; + void *array[200]; + char **callingfn = NULL; + + /* We chop off last 2 anyway, so if request is less than tolerance + * nothing to do */ + if (stacksize < 3) + goto out; + size = backtrace (array, ((stacksize <= 200)? stacksize : 200)); + if ((size - 3) < 0) + goto out; + if (size) + callingfn = backtrace_symbols (&array[2], size - 2); + if (!callingfn) goto out; + + ret = snprintf (callstr, strsize, "("); + PRINT_SIZE_CHECK (ret, out, strsize); + + for ((i = size - 3); i >= 0; i--) { + ret = snprintf (callstr + savstrsize - strsize, strsize, + "-->%s ", callingfn[i]); + PRINT_SIZE_CHECK (ret, out, strsize); } -#endif /* GF_USE_SYSLOG */ + + ret = snprintf (callstr + savstrsize - strsize, strsize, ")"); + PRINT_SIZE_CHECK (ret, out, strsize); +out: + FREE (callingfn); + return ret; +} +#endif /* HAVE_BACKTRACE */ + +int +_gf_msg_nomem (const char *domain, const char *file, + const char *function, int line, gf_loglevel_t level, + size_t size) +{ + const char *basename = NULL; + xlator_t *this = NULL; + struct timeval tv = {0,}; + int ret = 0; + int fd = -1; + char msg[2048] = {0,}; + char timestr[GF_LOG_TIMESTR_SIZE] = {0,}; + glusterfs_ctx_t *ctx = NULL; + int wlen = 0; + int priority; + + this = THIS; + ctx = this->ctx; + + if (!ctx) + goto out; + + if (ctx->log.gf_log_xl_log_set) { + if (this->loglevel && (level > this->loglevel)) + goto out; + } + if (level > ctx->log.loglevel) + goto out; + + if (!domain || !file || !function) { + fprintf (stderr, + "logging: %s:%s():%d: invalid argument\n", + __FILE__, __PRETTY_FUNCTION__, __LINE__); + return -1; + } + + GET_FILE_NAME_TO_LOG (file, basename); + ret = gettimeofday (&tv, NULL); if (-1 == ret) goto out; - va_start (ap, fmt); gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); - snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr), - ".%"GF_PRI_SUSECONDS, tv.tv_usec); - - ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %s %d-%s: ", - timestr, level_strings[level], - basename, line, function, callstr, - ((this->graph) ? this->graph->id:0), domain); + ret = snprintf (timestr + strlen (timestr), + sizeof timestr - strlen (timestr), + ".%"GF_PRI_SUSECONDS, tv.tv_usec); if (-1 == ret) { goto out; } - ret = vasprintf (&str2, fmt, ap); + /* TODO: Currently we print in the enhanced format, with a message ID + * of 0. Need to enhance this to support format as configured */ + ret = snprintf (msg, sizeof msg, "[%s] %s [MSGID: %"PRIu64"]" + " [%s:%d:%s] %s: no memory " + "available for size (%"GF_PRI_SIZET")" + " [call stack follows]\n", + timestr, gf_level_strings[level], (uint64_t) 0, + basename, line, function, domain, size); if (-1 == ret) { goto out; } - va_end (ap); + /* log to the configured logging service */ + switch (ctx->log.logger) { + case gf_logger_syslog: + if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) { + SET_LOG_PRIO (level, priority); - len = strlen (str1); - msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char); + /* if syslog allocates, then this may fail, but we + * cannot do much about it at the moment */ + /* There is no fd for syslog, hence no stack printed */ + syslog (priority, "%s", msg); + break; + } + /* NOTE: If syslog control file is absent, which is another + * way to control logging to syslog, then we will fall through + * to the gluster log. The ideal way to do things would be to + * not have the extra control file check */ + case gf_logger_glusterlog: + pthread_mutex_lock (&ctx->log.logfile_mutex); + { + fd = ctx->log.logfile? fileno (ctx->log.logfile) : + fileno (stderr); + if (fd == -1) { + pthread_mutex_unlock (&ctx->log.logfile_mutex); + goto out; + } - strcpy (msg, str1); - strcpy (msg + len, str2); + wlen = strlen (msg); + + /* write directly to the fd to prevent out of order + * message and stack */ + ret = write (fd, msg, wlen); + if (ret == -1) { + pthread_mutex_unlock (&ctx->log.logfile_mutex); + goto out; + } +#ifdef GF_LINUX_HOST_OS + /* We want only serious log in 'syslog', not our debug + * and trace logs */ + if (ctx->log.gf_log_syslog && level && + (level <= ctx->log.sys_log_level)) + syslog ((level-1), "%s\n", msg); +#endif + } + pthread_mutex_unlock (&ctx->log.logfile_mutex); + +#ifdef HAVE_BACKTRACE + _gf_msg_backtrace_nomem (level, GF_LOG_BACKTRACE_DEPTH); +#endif + + break; + } + +out: + return ret; +} + +static int +gf_log_syslog (const char *domain, const char *file, const char *function, + int32_t line, gf_loglevel_t level, int errnum, + uint64_t msgid, char **appmsgstr, char *callstr) +{ + int priority; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + SET_LOG_PRIO (level, priority); + + /* log with appropriate format */ + if (ctx->log.logformat == gf_logformat_traditional) { + if (!callstr) { + if (errnum) { + syslog (priority, "[%s:%d:%s] %d-%s: %s [%s]", + file, line, function, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr, strerror(errnum)); + } else { + syslog (priority, "[%s:%d:%s] %d-%s: %s", + file, line, function, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr); + } + } else { + if (errnum) { + syslog (priority, "[%s:%d:%s] %s %d-%s:" + " %s [%s]", + file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr, strerror(errnum)); + } else { + syslog (priority, "[%s:%d:%s] %s %d-%s: %s", + file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr); + } + } + } else if (ctx->log.logformat == gf_logformat_withmsgid) { + if (!callstr) { + if (errnum) { + syslog (priority, "[MSGID: %"PRIu64"]" + " [%s:%d:%s] %d-%s: %s [%s]", + msgid, file, line, function, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr, strerror(errnum)); + } else { + syslog (priority, "[MSGID: %"PRIu64"]" + " [%s:%d:%s] %d-%s: %s", + msgid, file, line, function, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr); + } + } else { + if (errnum) { + syslog (priority, "[MSGID: %"PRIu64"]" + " [%s:%d:%s] %s %d-%s: %s [%s]", + msgid, file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr, strerror(errnum)); + } else { + syslog (priority, "[MSGID: %"PRIu64"]" + " [%s:%d:%s] %s %d-%s: %s", + msgid, file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain, *appmsgstr); + } + } + } else if (ctx->log.logformat == gf_logformat_cee) { + /* TODO: Enhance CEE with additional parameters */ + gf_syslog (GF_ERR_DEV, priority, + "[%s:%d:%s] %d-%s: %s", + file, line, function, + ((this->graph) ? this->graph->id:0), + domain, *appmsgstr); + } else { + /* NOTE: should not get here without logging */ + } + + /* TODO: There can be no errors from gf_syslog? */ + return 0; +} + +static int +gf_log_glusterlog (const char *domain, const char *file, const char *function, + int32_t line, gf_loglevel_t level, int errnum, + uint64_t msgid, char **appmsgstr, char *callstr) +{ + char timestr[GF_LOG_TIMESTR_SIZE] = {0,}; + struct timeval tv = {0,}; + char *header = NULL; + char *footer = NULL; + char *msg = NULL; + size_t hlen = 0, flen = 0, mlen = 0; + int ret = 0; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + /* rotate if required */ + gf_log_rotate(ctx); + + /* format the time stanp */ + ret = gettimeofday (&tv, NULL); + if (-1 == ret) + goto out; + gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); + snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr), + ".%"GF_PRI_SUSECONDS, tv.tv_usec); + + /* generate header and footer */ + if (ctx->log.logformat == gf_logformat_traditional) { + if (!callstr) { + ret = gf_asprintf (&header, "[%s] %s [%s:%d:%s]" + " %d-%s: ", + timestr, gf_level_strings[level], + file, line, function, + ((this->graph)?this->graph->id:0), + domain); + } else { + ret = gf_asprintf (&header, "[%s] %s [%s:%d:%s] %s" + " %d-%s: ", + timestr, gf_level_strings[level], + file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain); + } + if (-1 == ret) { + goto err; + } + } else { /* gf_logformat_withmsgid */ + /* CEE log format unsupported in logger_glusterlog, so just + * print enhanced log format */ + if (!callstr) { + ret = gf_asprintf (&header, "[%s] %s [MSGID: %"PRIu64"]" + " [%s:%d:%s] %d-%s: ", + timestr, gf_level_strings[level], + msgid, file, line, function, + ((this->graph)?this->graph->id:0), + domain); + } else { + ret = gf_asprintf (&header, "[%s] %s [MSGID: %"PRIu64"]" + " [%s:%d:%s] %s %d-%s: ", + timestr, gf_level_strings[level], + msgid, file, line, function, callstr, + ((this->graph)?this->graph->id:0), + domain); + } + if (-1 == ret) { + goto err; + } + } + + if (errnum) { + ret = gf_asprintf (&footer, " [%s]",strerror(errnum)); + if (-1 == ret) { + goto err; + } + } + + /* generate the full message to log */ + hlen = strlen (header); + flen = footer? strlen (footer) : 0; + mlen = strlen (*appmsgstr); + msg = GF_MALLOC (hlen + flen + mlen + 1, gf_common_mt_char); + + strcpy (msg, header); + strcpy (msg + hlen, *appmsgstr); + if (footer) + strcpy (msg + hlen + mlen, footer); pthread_mutex_lock (&ctx->log.logfile_mutex); { if (ctx->log.logfile) { fprintf (ctx->log.logfile, "%s\n", msg); + fflush (ctx->log.logfile); } else if (ctx->log.loglevel >= level) { fprintf (stderr, "%s\n", msg); + fflush (stderr); } #ifdef GF_LINUX_HOST_OS - /* We want only serious log in 'syslog', not our debug - and trace logs */ + /* We want only serious logs in 'syslog', not our debug + * and trace logs */ if (ctx->log.gf_log_syslog && level && - (level <= ctx->log.sys_log_level)) + (level <= ctx->log.sys_log_level)) syslog ((level-1), "%s\n", msg); #endif } + /* TODO: Plugin in memory log buffer retention here. For logs not + * flushed during cores, it would be useful to retain some of the last + * few messages in memory */ pthread_mutex_unlock (&ctx->log.logfile_mutex); -out: +err: GF_FREE (msg); + GF_FREE (header); + GF_FREE (footer); - GF_FREE (str1); +out: + return ret; +} - FREE (str2); +static int +_gf_msg_internal (const char *domain, const char *file, const char *function, + int32_t line, gf_loglevel_t level, int errnum, uint64_t msgid, + char **appmsgstr, char *callstr) +{ + const char *basename = NULL; + int ret = -1; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + + this = THIS; + ctx = this->ctx; + + GET_FILE_NAME_TO_LOG (file, basename); + + /* TODO: Plug in repeated message suppression for gluster logs here. + * Comparison of last few messages stored based on, appmsgstr, errnum + * msgid. */ + /* log to the configured logging service */ + switch (ctx->log.logger) { + case gf_logger_syslog: + if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) { + ret = gf_log_syslog (domain, basename, function, line, + level, errnum, msgid, appmsgstr, + callstr); + break; + } + /* NOTE: If syslog control file is absent, which is another + * way to control logging to syslog, then we will fall through + * to the gluster log. The ideal way to do things would be to + * not have the extra control file check */ + case gf_logger_glusterlog: + ret = gf_log_glusterlog (domain, basename, function, line, + level, errnum, msgid, appmsgstr, + callstr); + break; + } + + return ret; +} + +int +_gf_msg (const char *domain, const char *file, const char *function, + int32_t line, gf_loglevel_t level, int errnum, int trace, + uint64_t msgid, const char *fmt, ...) +{ + int ret = 0; + char *msgstr = NULL; + va_list ap; + xlator_t *this = NULL; + glusterfs_ctx_t *ctx = NULL; + char callstr[GF_LOG_BACKTRACE_SIZE] = {0,}; + int passcallstr = 0; + + /* in args check */ + if (!domain || !file || !function || !fmt) { + fprintf (stderr, + "logging: %s:%s():%d: invalid argument\n", + __FILE__, __PRETTY_FUNCTION__, __LINE__); + return -1; + } + + this = THIS; + ctx = this->ctx; + if (ctx == NULL) { + /* messages before context initialization are ignored */ + return -1; + } + + /* check if we should be logging */ + if (ctx->log.gf_log_xl_log_set) { + if (this->loglevel && (level > this->loglevel)) + goto out; + } + if (level > ctx->log.loglevel) + goto out; + +#if HAVE_BACKTRACE + if (trace) { + ret = _gf_msg_backtrace (GF_LOG_BACKTRACE_DEPTH, callstr, + GF_LOG_BACKTRACE_DEPTH); + if (ret >= 0) + passcallstr = 1; + else + ret = 0; + } +#endif /* HAVE_BACKTRACE */ + + /* form the message */ + va_start (ap, fmt); + ret = vasprintf (&msgstr, fmt, ap); + va_end (ap); + + /* log */ + if (ret != -1) + ret = _gf_msg_internal(domain, file, function, line, level, + errnum, msgid, &msgstr, + (passcallstr? callstr : NULL)); + else + /* man (3) vasprintf states on error strp contents + * are undefined, be safe */ + msgstr = NULL; + + FREE (msgstr); + +out: return ret; } +/* TODO: Deprecate (delete) _gf_log, _gf_log_callingfn, + * once messages are changed to use _gf_msgXXX APIs for logging */ int _gf_log (const char *domain, const char *file, const char *function, int line, gf_loglevel_t level, const char *fmt, ...) @@ -744,7 +1472,7 @@ _gf_log (const char *domain, const char *file, const char *function, int line, const char *basename = NULL; FILE *new_logfile = NULL; va_list ap; - char timestr[256] = {0,}; + char timestr[GF_LOG_TIMESTR_SIZE] = {0,}; struct timeval tv = {0,}; char *str1 = NULL; char *str2 = NULL; @@ -790,7 +1518,6 @@ _gf_log (const char *domain, const char *file, const char *function, int line, else basename = file; -#if defined(GF_USE_SYSLOG) if (ctx->log.log_control_file_found) { int priority; @@ -812,7 +1539,6 @@ _gf_log (const char *domain, const char *file, const char *function, int line, ((this->graph) ? this->graph->id:0), domain, str2); goto err; } -#endif /* GF_USE_SYSLOG */ if (ctx->log.logrotate) { ctx->log.logrotate = 0; @@ -839,7 +1565,8 @@ _gf_log (const char *domain, const char *file, const char *function, int line, if (ctx->log.logfile) fclose (ctx->log.logfile); - ctx->log.gf_log_logfile = ctx->log.logfile = new_logfile; + ctx->log.gf_log_logfile = + ctx->log.logfile = new_logfile; } pthread_mutex_unlock (&ctx->log.logfile_mutex); @@ -1033,7 +1760,8 @@ gf_cmd_log (const char *domain, const char *fmt, ...) goto out; va_start (ap, fmt); gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); - snprintf (timestr + strlen (timestr), 256 - strlen (timestr), + snprintf (timestr + strlen (timestr), + GF_LOG_TIMESTR_SIZE - strlen (timestr), ".%"GF_PRI_SUSECONDS, tv.tv_usec); ret = gf_asprintf (&str1, "[%s] %s : ", diff --git a/libglusterfs/src/logging.h b/libglusterfs/src/logging.h index e2b7e664d0f..b6b13fbd02a 100644 --- a/libglusterfs/src/logging.h +++ b/libglusterfs/src/logging.h @@ -61,6 +61,20 @@ typedef enum { GF_LOG_TRACE, /* full trace of operation */ } gf_loglevel_t; +/* format for the logs */ +typedef enum { + gf_logformat_traditional = 0, /* Format as in gluster 3.5 */ + gf_logformat_withmsgid, /* Format enhanced with MsgID, ident, errstr */ + gf_logformat_cee /* log enhanced format in cee */ +} gf_log_format_t; + +/* log infrastructure to log to */ +typedef enum { + gf_logger_glusterlog = 0, /* locations and files as in gluster 3.5 */ + gf_logger_syslog /* log to (r)syslog, based on (r)syslog conf */ + /* NOTE: In the future journald, lumberjack, next new thing here */ +} gf_log_logger_t; + #define DEFAULT_LOG_FILE_DIRECTORY DATADIR "/log/glusterfs" #define DEFAULT_LOG_LEVEL GF_LOG_INFO @@ -76,11 +90,10 @@ typedef struct gf_log_handle_ { FILE *gf_log_logfile; char *cmd_log_filename; FILE *cmdlogfile; -#ifdef GF_USE_SYSLOG - int log_control_file_found; + gf_log_logger_t logger; + gf_log_format_t logformat; char *ident; -#endif /* GF_USE_SYSLOG */ - + int log_control_file_found; } gf_log_handle_t; void gf_log_globals_init (void *ctx); @@ -90,25 +103,117 @@ void gf_log_logrotate (int signum); void gf_log_cleanup (void); +/* Internal interfaces to log messages with message IDs */ +int _gf_msg (const char *domain, const char *file, + const char *function, int32_t line, gf_loglevel_t level, + int errnum, int trace, uint64_t msgid, const char *fmt, ...) + __attribute__ ((__format__ (__printf__, 9, 10))); + +void _gf_msg_backtrace_nomem (gf_loglevel_t level, int stacksize); + +int _gf_msg_plain (gf_loglevel_t level, const char *fmt, ...) + __attribute__ ((__format__ (__printf__, 2, 3))); + +int _gf_msg_plain_nomem (gf_loglevel_t level, const char *msg); + +int _gf_msg_vplain (gf_loglevel_t level, const char *fmt, va_list ap); + +int _gf_msg_nomem (const char *domain, const char *file, + const char *function, int line, gf_loglevel_t level, + size_t size); + int _gf_log (const char *domain, const char *file, const char *function, int32_t line, gf_loglevel_t level, const char *fmt, ...) __attribute__ ((__format__ (__printf__, 6, 7))); + int _gf_log_callingfn (const char *domain, const char *file, const char *function, int32_t line, gf_loglevel_t level, const char *fmt, ...) __attribute__ ((__format__ (__printf__, 6, 7))); -int _gf_log_nomem (const char *domain, const char *file, - const char *function, int line, gf_loglevel_t level, - size_t size); - int _gf_log_eh (const char *function, const char *fmt, ...); +/* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and + * other level as is */ +#define SET_LOG_PRIO(level, priority) do { \ + if (GF_LOG_TRACE == (level) || GF_LOG_NONE == (level)) { \ + priority = LOG_DEBUG; \ + } else { \ + priority = (level) - 1; \ + } \ + } while (0) + +/* extract just the file name from the path */ +#define GET_FILE_NAME_TO_LOG(file, basename) do { \ + basename = strrchr ((file), '/'); \ + if (basename) \ + basename++; \ + else \ + basename = (file); \ + } while (0) + +#define PRINT_SIZE_CHECK(ret, label, strsize) do { \ + if (ret < 0) \ + goto label; \ + if ((strsize - ret) > 0) { \ + strsize -= ret; \ + } else { \ + ret = 0; \ + goto label; \ + } \ + } while (0) + #define FMT_WARN(fmt...) do { if (0) printf (fmt); } while (0) +/* Interface to log messages with message IDs */ +#define gf_msg(dom, levl, errnum, msgid, fmt...) do { \ + _gf_msg (dom, __FILE__, __FUNCTION__, __LINE__, \ + levl, errnum, 0, msgid, ##fmt); \ + } while (0) + +/* no frills, no thrills, just a vanilla message, used to print the graph */ +#define gf_msg_plain(levl, fmt...) do { \ + _gf_msg_plain (levl, ##fmt); \ + } while (0) + +#define gf_msg_plain_nomem(levl, msg) do { \ + _gf_msg_plain_nomem (levl, msg); \ + } while (0) + +#define gf_msg_vplain(levl, fmt, va) do { \ + _gf_msg_vplain (levl, fmt, va); \ + } while (0) + +#define gf_msg_backtrace_nomem(level, stacksize) do { \ + _gf_msg_backtrace_nomem (level, stacksize); \ + } while (0) + +#define gf_msg_callingfn(dom, levl, errnum, msgid, fmt...) do { \ + _gf_msg (dom, __FILE__, __FUNCTION__, __LINE__, \ + levl, errnum, 1, msgid, ##fmt); \ + } while (0) + +/* No malloc or calloc should be called in this function */ +#define gf_msg_nomem(dom, levl, size) do { \ + _gf_msg_nomem (dom, __FILE__, __FUNCTION__, __LINE__, \ + levl, size); \ + } while (0) + +/* Debug or trace messages do not need message IDs as these are more developer + * related. Hence, the following abstractions are provided for the same */ +#define gf_msg_debug(dom, errnum, fmt...) do { \ + _gf_msg (dom, __FILE__, __FUNCTION__, __LINE__, \ + GF_LOG_DEBUG, errnum, 0, 0, ##fmt); \ + } while (0) + +#define gf_msg_trace(dom, errnum, fmt...) do { \ + _gf_msg (dom, __FILE__, __FUNCTION__, __LINE__, \ + GF_LOG_TRACE, errnum, 0, 0, ##fmt); \ + } while (0) + #define gf_log(dom, levl, fmt...) do { \ FMT_WARN (fmt); \ _gf_log (dom, __FILE__, __FUNCTION__, __LINE__, \ @@ -127,13 +232,6 @@ int _gf_log_eh (const char *function, const char *fmt, ...); } while (0) -/* No malloc or calloc should be called in this function */ -#define gf_log_nomem(dom, levl, size) do { \ - _gf_log_nomem (dom, __FILE__, __FUNCTION__, __LINE__, \ - levl, size); \ - } while (0) - - /* Log once in GF_UNIVERSAL_ANSWER times */ #define GF_LOG_OCCASIONALLY(var, args...) if (!(var++%GF_UNIVERSAL_ANSWER)) { \ gf_log (args); \ @@ -143,6 +241,7 @@ void gf_log_disable_syslog (void); void gf_log_enable_syslog (void); gf_loglevel_t gf_log_get_loglevel (void); void gf_log_set_loglevel (gf_loglevel_t level); +void gf_log_flush (void); gf_loglevel_t gf_log_get_xl_loglevel (void *xl); void gf_log_set_xl_loglevel (void *xl, gf_loglevel_t level); diff --git a/libglusterfs/src/mem-pool.c b/libglusterfs/src/mem-pool.c index b92803d4d3d..c5ff58f4f1b 100644 --- a/libglusterfs/src/mem-pool.c +++ b/libglusterfs/src/mem-pool.c @@ -105,7 +105,7 @@ __gf_calloc (size_t nmemb, size_t size, uint32_t type) ptr = calloc (1, tot_size); if (!ptr) { - gf_log_nomem ("", GF_LOG_ALERT, tot_size); + gf_msg_nomem ("", GF_LOG_ALERT, tot_size); return NULL; } gf_mem_set_acct_info (xl, &ptr, req_size, type); @@ -129,7 +129,7 @@ __gf_malloc (size_t size, uint32_t type) ptr = malloc (tot_size); if (!ptr) { - gf_log_nomem ("", GF_LOG_ALERT, tot_size); + gf_msg_nomem ("", GF_LOG_ALERT, tot_size); return NULL; } gf_mem_set_acct_info (xl, &ptr, size, type); @@ -163,7 +163,7 @@ __gf_realloc (void *ptr, size_t size) new_ptr = realloc (orig_ptr, tot_size); if (!new_ptr) { - gf_log_nomem ("", GF_LOG_ALERT, tot_size); + gf_msg_nomem ("", GF_LOG_ALERT, tot_size); return NULL; } diff --git a/libglusterfs/src/mem-pool.h b/libglusterfs/src/mem-pool.h index aa6bf784363..9ffeef4da30 100644 --- a/libglusterfs/src/mem-pool.h +++ b/libglusterfs/src/mem-pool.h @@ -75,7 +75,7 @@ void* __gf_default_malloc (size_t size) ptr = malloc (size); if (!ptr) - gf_log_nomem ("", GF_LOG_ALERT, size); + gf_msg_nomem ("", GF_LOG_ALERT, size); return ptr; } @@ -87,7 +87,7 @@ void* __gf_default_calloc (int cnt, size_t size) ptr = calloc (cnt, size); if (!ptr) - gf_log_nomem ("", GF_LOG_ALERT, (cnt * size)); + gf_msg_nomem ("", GF_LOG_ALERT, (cnt * size)); return ptr; } @@ -99,7 +99,7 @@ void* __gf_default_realloc (void *oldptr, size_t size) ptr = realloc (oldptr, size); if (!ptr) - gf_log_nomem ("", GF_LOG_ALERT, size); + gf_msg_nomem ("", GF_LOG_ALERT, size); return ptr; } diff --git a/libglusterfs/src/template-component-messages.h b/libglusterfs/src/template-component-messages.h new file mode 100644 index 00000000000..c1ea38cf770 --- /dev/null +++ b/libglusterfs/src/template-component-messages.h @@ -0,0 +1,55 @@ +/* + Copyright (c) 2013 Red Hat, Inc. <http://www.redhat.com> + This file is part of GlusterFS. + + This file is licensed to you under your choice of the GNU Lesser + General Public License, version 3 or any later version (LGPLv3 or + later), or the GNU General Public License, version 2 (GPLv2), in all + cases as published by the Free Software Foundation. + */ + +#ifndef _component_MESSAGES_H_ +#define _component_MESSAGES_H_ + +#ifndef _CONFIG_H +#define _CONFIG_H +#include "config.h" +#endif + +#include "glfs-message-id.h" + +/* NOTE: Rules for message additions + * 1) Each instance of a message is _better_ left with a unique message ID, even + * if the message format is the same. Reasoning is that, if the message + * format needs to change in one instance, the other instances are not + * impacted or the new change does not change the ID of the instance being + * modified. + * 2) Addition of a message, + * - Should increment the GLFS_NUM_MESSAGES + * - Append to the list of messages defined, towards the end + * - Retain macro naming as glfs_msg_X (for redability across developers) + * NOTE: Rules for message format modifications + * 3) Check acorss the code if the message ID macro in question is reused + * anywhere. If reused then then the modifications should ensure correctness + * everywhere, or needs a new message ID as (1) above was not adhered to. If + * not used anywhere, proceed with the required modification. + * NOTE: Rules for message deletion + * 4) Check (3) and if used anywhere else, then cannot be deleted. If not used + * anywhere, then can be deleted, but will leave a hole by design, as + * addition rules specify modification to the end of the list and not filling + * holes. + */ + +#define GLFS_COMP_BASE GLFS_MSGID_COMP_<component> +#define GLFS_NUM_MESSAGES 1 +#define GLFS_MSGID_END (GLFS_COMP_BASE + GLFS_NUM_MESSAGES + 1) +/* Messaged with message IDs */ +#define glfs_msg_start_x GLFS_COMP_BASE, "Invalid: Start of messages" +/*------------*/ +#define <component>_msg_1 (GLFS_COMP_BASE + 1), "Test message, replace with"\ + " original when using the template" + +/*------------*/ +#define glfs_msg_end_x GLFS_MSGID_END, "Invalid: End of messages" + +#endif /* !_component_MESSAGES_H_ */
\ No newline at end of file diff --git a/libglusterfs/src/unittest/log_mock.c b/libglusterfs/src/unittest/log_mock.c index 676df7cfdad..fec48bafc19 100644 --- a/libglusterfs/src/unittest/log_mock.c +++ b/libglusterfs/src/unittest/log_mock.c @@ -39,5 +39,12 @@ int _gf_log_nomem (const char *domain, const char *file, return 0; } +int _gf_msg_nomem (const char *domain, const char *file, + const char *function, int line, gf_loglevel_t level, + size_t size) +{ + return 0; +} + void gf_log_globals_init (void *data) {} |