/*
* Amanda, The Advanced Maryland Automatic Network Disk Archiver
* Copyright (c) 1991-1998 University of Maryland at College Park
* Copyright (c) 2007-2012 Zmanda, Inc. All Rights Reserved.
* Copyright (c) 2013-2016 Carbonite, Inc. All Rights Reserved.
* All Rights Reserved.
*
* Permission to use, copy, modify, distribute, and sell this software and its
* documentation for any purpose is hereby granted without fee, provided that
* the above copyright notice appear in all copies and that both that
* copyright notice and this permission notice appear in supporting
* documentation, and that the name of U.M. not be used in advertising or
* publicity pertaining to distribution of the software without specific,
* written prior permission. U.M. makes no representations about the
* suitability of this software for any purpose. It is provided "as is"
* without express or implied warranty.
*
* U.M. DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING ALL
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS, IN NO EVENT SHALL U.M.
* BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
* WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION
* OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
* CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
*
* Author: James da Silva, Systems Design and Analysis Group
* Computer Science Department
* University of Maryland at College Park
*/
/*
* $Id: debug.c,v 1.40 2006/07/26 11:49:32 martinea Exp $
*
* Logging support
*/
#include "amanda.h"
#include "amutil.h"
#include "clock.h"
#include "timestamp.h"
#include "conffile.h"
#ifdef HAVE_GLIBC_BACKTRACE
#include <execinfo.h>
#endif
/* Minimum file descriptor on which to keep the debug file. This is intended
* to keep the descriptor "out of the way" of other processing. It's not clear
* that this is required any longer, but it doesn't hurt anything.
*/
#define MIN_DB_FD 10
/* information on the current debug file */
static int db_fd = 2; /* file descriptor (default stderr) */
static FILE *db_file = NULL; /* stdio stream */
static char *db_name = NULL; /* unqualified filename */
static char *db_filename = NULL; /* fully qualified pathname */
/* directory containing debug file, including trailing slash */
static char *dbgdir = NULL;
/* time debug log was opened (timestamp of the file) */
static time_t open_time;
/* storage for global variables */
int error_exit_status = 1;
/* static function prototypes */
static char *get_debug_name(time_t t, int n);
static void debug_unlink_old(void);
static void debug_setup_1(char *config, char *subdir);
static void debug_setup_2(char *s, int fd, char *annotation);
static char *msg_timestamp(char timestamp[128]);
static void debug_logging_handler(const gchar *log_domain,
GLogLevelFlags log_level,
const gchar *message,
gpointer user_data);
static void debug_setup_logging(void);
/* By default, do not suppress tracebacks */
static gboolean do_suppress_error_traceback = FALSE;
/* configured amanda_log_handlers */
static GSList *amanda_log_handlers = NULL;
/*
* Generate a debug file name. The name is based on the program name,
* followed by a timestamp, an optional sequence number, and ".debug".
*
* @param t: timestamp
* @param n: sequence number between 1 and 1000; if zero, no sequence number
* is included.
*/
static char *
get_debug_name(
time_t t,
int n)
{
char number[NUM_STR_SIZE];
char *ts;
char *result;
if(n < 0 || n > 1000) {
return NULL;
}
ts = get_timestamp_from_time(t);
if(n == 0) {
number[0] = '\0';
} else {
g_snprintf(number, sizeof(number), "%03d", n - 1);
}
result = g_strjoin(NULL, get_pname(), ".", ts, number, ".debug", NULL);
amfree(ts);
return result;
}
/* Call this to suppress tracebacks on error() or g_critical(). This is used
* when a critical error is indicated in perl, and the traceback will not be
* useful. */
void
suppress_error_traceback(void)
{
do_suppress_error_traceback = 1;
}
/* A GLogFunc to handle g_log calls. This function assumes that user_data
* is either NULL or a pointer to one of the debug_* configuration variables
* in conffile.c, indicating whether logging for this log domain is enabled.
*
* @param log_domain: the log domain, or NULL for general logging
* @param log_level: level, fatality, and recursion flags
* @param message: the message to log
* @param user_pointer: unused
*/
static void
debug_logging_handler(const gchar *log_domain G_GNUC_UNUSED,
GLogLevelFlags log_level,
const gchar *message,
gpointer user_data G_GNUC_UNUSED)
{
GLogLevelFlags maxlevel;
char *levprefix = NULL;
pcontext_t context = get_pcontext();
/* glib allows a message to have multiple levels, so calculate the "worst"
* level */
if (log_level & G_LOG_LEVEL_ERROR) {
maxlevel = G_LOG_LEVEL_ERROR;
levprefix = _("error (fatal): ");
} else if (log_level & G_LOG_LEVEL_CRITICAL) {
maxlevel = G_LOG_LEVEL_CRITICAL;
levprefix = _("critical (fatal): ");
} else if (log_level & G_LOG_LEVEL_WARNING) {
maxlevel = G_LOG_LEVEL_WARNING;
levprefix = _("warning: ");
} else if (log_level & G_LOG_LEVEL_MESSAGE) {
maxlevel = G_LOG_LEVEL_MESSAGE;
levprefix = _("message: ");
} else if (log_level & G_LOG_LEVEL_INFO) {
maxlevel = G_LOG_LEVEL_INFO;
levprefix = _("info: ");
} else {
maxlevel = G_LOG_LEVEL_DEBUG;
levprefix = ""; /* no level displayed for debugging */
}
/* scriptutil context doesn't do any logging except for critical
* and error levels */
if (context != CONTEXT_SCRIPTUTIL) {
/* convert the highest level to a string and dbprintf it */
debug_printf("%s%s\n", levprefix, message);
}
if (amanda_log_handlers) {
GSList *iter = amanda_log_handlers;
while (iter) {
amanda_log_handler_t *hdlr = (amanda_log_handler_t *)iter->data;
hdlr(maxlevel, message);
iter = g_slist_next(iter);
}
} else {
/* call the appropriate handlers, based on the context */
amanda_log_stderr(maxlevel, message);
if (context == CONTEXT_DAEMON)
amanda_log_syslog(maxlevel, message);
}
/* error and critical levels have special handling */
if (log_level & (G_LOG_LEVEL_ERROR|G_LOG_LEVEL_CRITICAL)) {
#ifdef HAVE_GLIBC_BACKTRACE
/* try logging a traceback to the debug log */
if (!do_suppress_error_traceback && db_fd != -1) {
void *stack[32];
int naddrs;
naddrs = backtrace(stack, G_N_ELEMENTS(stack));
backtrace_symbols_fd(stack, naddrs, db_fd);
}
#endif
/* we're done */
if (log_level & G_LOG_LEVEL_CRITICAL)
exit(error_exit_status);
else
abort();
g_assert_not_reached();
}
}
/* Install our handler into the glib log handling system.
*/
static void
debug_setup_logging(void)
{
/* g_error and g_critical should be fatal, although the log handler
* takes care of this anyway */
g_log_set_always_fatal(G_LOG_LEVEL_ERROR | G_LOG_LEVEL_CRITICAL);
/* set up handler (g_log_set_default_handler is new in glib-2.6, and
* hence not useable here) */
g_log_set_handler(NULL, G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
debug_logging_handler, NULL);
}
void
add_amanda_log_handler(amanda_log_handler_t *hdlr)
{
amanda_log_handlers = g_slist_append(amanda_log_handlers, (gpointer)hdlr);
}
void
amanda_log_syslog(GLogLevelFlags log_level, const gchar *message)
{
int priority = LOG_ERR;
switch (log_level) {
case G_LOG_LEVEL_ERROR:
case G_LOG_LEVEL_CRITICAL:
priority = LOG_ERR;
break;
case G_LOG_LEVEL_WARNING:
#ifdef LOG_WARNING
priority = LOG_WARNING;
#endif
break;
default:
return;
}
#ifdef LOG_DAEMON
openlog(get_pname(), LOG_PID, LOG_DAEMON);
#else
openlog(get_pname(), LOG_PID, 0);
#endif
syslog(priority, "%s", message);
closelog();
}
void
amanda_log_stderr(GLogLevelFlags log_level, const gchar *message)
{
switch (log_level) {
case G_LOG_LEVEL_ERROR:
case G_LOG_LEVEL_CRITICAL:
g_fprintf(stderr, "%s: %s\n", get_pname(), message);
break;
default:
return;
}
}
void
amanda_log_null(GLogLevelFlags log_level G_GNUC_UNUSED, const gchar *message G_GNUC_UNUSED)
{
}
/* Set the global dbgdir according to 'config' and 'subdir'
*
* The global open_time is set to the current time, and used to delete
* old files.
*
* @param config: configuration or NULL
* @param subdir: subdirectory (server, client, etc.) or NULL
*/
static void
debug_setup_1(char *config, char *subdir)
{
char *sane_config = NULL;
/*
* Create the debug directory if it does not yet exist.
*/
amfree(dbgdir);
if (config)
sane_config = sanitise_filename(config);
if (sane_config && subdir)
dbgdir = g_strjoin(NULL, AMANDA_DBGDIR, "/", subdir, "/", sane_config,
"/", NULL);
else if (sane_config)
dbgdir = g_strjoin(NULL, AMANDA_DBGDIR, "/", sane_config, "/", NULL);
else if (subdir)
dbgdir = g_strjoin(NULL, AMANDA_DBGDIR, "/", subdir, "/", NULL);
else
dbgdir = g_strconcat(AMANDA_DBGDIR, "/", NULL);
if(mkpdir(dbgdir, 0700, get_client_uid(), get_client_gid()) == -1) {
error(_("create debug directory \"%s\": %s"),
dbgdir, strerror(errno));
/*NOTREACHED*/
}
amfree(sane_config);
time(&open_time);
}
/*
* Clean out old debug files. We also rename files with old style
* names (XXX.debug or XXX.$PID.debug) into the new name format.
* We assume no system has 17 digit PID-s :-) and that there will
* not be a conflict between an old and new name.
*/
static void
debug_unlink_old(void)
{
char *pname;
size_t pname_len;
char *e = NULL;
char *s = NULL;
struct dirent *entry;
int do_rename;
char *test_name;
size_t test_name_len;
size_t d_name_len;
char *dbfilename = NULL;
int i;
DIR *d;
struct stat sbuf;
assert(dbgdir != NULL);
memset(&sbuf, 0, sizeof(sbuf));
if (!config_is_initialized())
return;
pname = get_pname();
pname_len = strlen(pname);
if((d = opendir(dbgdir)) == NULL) {
error(_("open debug directory \"%s\": %s"),
dbgdir, strerror(errno));
/*NOTREACHED*/
}
test_name = get_debug_name(open_time - (getconf_int(CNF_DEBUG_DAYS) * 24 * 60 * 60), 0);
test_name_len = strlen(test_name);
while((entry = readdir(d)) != NULL) {
if(is_dot_or_dotdot(entry->d_name)) {
continue;
}
d_name_len = strlen(entry->d_name);
if(strncmp(entry->d_name, pname, pname_len) != 0
|| entry->d_name[pname_len] != '.'
|| d_name_len < 6
|| !g_str_equal(entry->d_name + d_name_len - 6, ".debug")) {
continue; /* not one of our debug files */
}
g_free(e);
e = g_strconcat(dbgdir, entry->d_name, NULL);
if(d_name_len < test_name_len) {
/*
* Create a "pretend" name based on the last modification
* time. This name will be used to decide if the real name
* should be removed. If not, it will be used to rename the
* real name.
*/
if(stat(e, &sbuf) != 0) {
continue; /* ignore errors */
}
amfree(dbfilename);
dbfilename = get_debug_name((time_t)sbuf.st_mtime, 0);
do_rename = 1;
} else {
g_free(dbfilename);
dbfilename = g_strdup(entry->d_name);
do_rename = 0;
}
if(strcmp(dbfilename, test_name) < 0) {
(void) unlink(e); /* get rid of old file */
continue;
}
if(do_rename) {
i = 0;
while (TRUE) {
if (dbfilename == NULL)
break;
g_free(s);
s = g_strconcat(dbgdir, dbfilename, NULL);
if (rename(e, s) == 0)
break;
if (errno == ENOENT)
break;
g_free(dbfilename);
dbfilename = get_debug_name((time_t)sbuf.st_mtime, ++i);
}
if(dbfilename == NULL) {
error(_("cannot rename old debug file \"%s\""), entry->d_name);
/*NOTREACHED*/
}
}
}
amfree(dbfilename);
amfree(e);
amfree(s);
amfree(test_name);
closedir(d);
}
/* Given an already-opened debug file, set the file's ownership
* appropriately, move its file descriptor above MIN_DB_FD, and
* add an initial log entry to the file.
*
* This function records the file's identity in the globals
* db_filename, db_fd, and db_file. It does *not* set db_name.
* db_file is not set if fd is -1
*
* This function uses the global 'open_time', which is set by
* debug_setup_1.
*
* @param s: the filename of the debug file; string should be malloc'd,
* and should *not* be freed by the caller.
* @param fd: the descriptor connected to the debug file, or -1 if
* no decriptor moving should take place.
* @param annotation: an extra string to include in the initial
* log entry.
*/
static void
debug_setup_2(
char * s,
int fd,
char * annotation)
{
int i;
int fd_close[MIN_DB_FD+1];
amfree(db_filename);
db_filename = s;
s = NULL;
/* If we're root, change the ownership of the debug files. If we're not root,
* this would either be redundant or an error. */
if (geteuid() == 0) {
if (chown(db_filename, get_client_uid(), get_client_gid()) < 0) {
dbprintf(_("chown(%s, %d, %d) failed: %s"),
db_filename, (int)get_client_uid(), (int)get_client_gid(), strerror(errno));
}
}
/*
* Move the file descriptor up high so it stays out of the way
* of other processing, e.g. sendbackup.
*/
if (fd >= 0) {
i = 0;
fd_close[i++] = fd;
while((db_fd = dup(fd)) < MIN_DB_FD) {
fd_close[i++] = db_fd;
}
while(--i >= 0) {
close(fd_close[i]);
}
db_file = fdopen(db_fd, "a");
}
if (annotation) {
/*
* Make the first debug log file entry.
*/
debug_printf(_("pid %ld ruid %ld euid %ld version %s: %s at %s"),
(long)getpid(),
(long)getuid(), (long)geteuid(),
VERSION,
annotation,
ctime(&open_time));
}
}
/* Get current GMT time and return a message timestamp.
* Used for g_printf calls to logs and such. The return value
* is to a static buffer, so it should be used immediately.
*
* @returns: timestamp
*/
static char *
msg_timestamp(char timestamp[128])
{
#ifdef HAVE_CLOCK_GETTIME
struct timespec spec;
struct tm t;
int len;
int xlen;
#else
time_t curtime;
#endif
char *r;
#ifdef HAVE_CLOCK_GETTIME
clock_gettime(CLOCK_REALTIME, &spec);
localtime_r(&spec.tv_sec, &t);
len = strftime(timestamp, 128, "%a %b %d %H:%M:%S", &t);
xlen = 128 - len;
snprintf(timestamp+len, xlen, ".%09ld", spec.tv_nsec);
len = strlen(timestamp);
xlen = 128 - len;
snprintf(timestamp+len, xlen, " %04d", 1900 + t.tm_year);
#else
time(&curtime);
ctime_r(&curtime, timestamp);
#endif
r = strchr(timestamp, '\n');
if (r)
*r = '\0';
return timestamp;
}
/*
* ---- public functions
*/
void
debug_init(void)
{
debug_setup_logging();
/* the scriptutil context does not create a debug log, since such
* processes are invoked many times.
*/
if (get_pcontext() != CONTEXT_SCRIPTUTIL) {
debug_open(get_ptype());
}
}
void
debug_open(char *subdir)
{
int fd = -1;
int i;
char *s = NULL;
mode_t mask;
/* create AMANDA_TMPDIR */
make_amanda_tmpdir();
/* set up logging while we're here */
debug_setup_logging();
/* set 'dbgdir' and clean out old debug files */
debug_setup_1(NULL, subdir);
/*
* Create the new file with a unique sequence number.
*/
mask = (mode_t)umask((mode_t)0037); /* Allow the group read bit through */
/* iteratate through sequence numbers until we find one that
* is not already in use */
for(i = 0; fd < 0; i++) {
amfree(db_name);
if ((db_name = get_debug_name(open_time, i)) == NULL) {
error(_("Cannot create debug file name in %d tries."), i);
/*NOTREACHED*/
}
g_free(s);
s = g_strconcat(dbgdir, db_name, NULL);
if ((fd = open(s, O_WRONLY|O_CREAT|O_EXCL|O_APPEND, 0640)) < 0) {
if (errno != EEXIST) {
error(_("Cannot create debug file \"%s\": %s"),
s, strerror(errno));
/*NOTREACHED*/
}
amfree(s);
}
}
(void)umask(mask); /* Restore mask */
/*
* Finish setup.
*
* Note: we release control of the string 's' points to.
*/
debug_setup_2(s, fd, "start");
}
void
debug_reopen(
char * dbfilename,
char * annotation)
{
char *s = NULL;
int fd;
if (dbfilename == NULL) {
return;
}
/* set 'dbgdir' and clean out old debug files */
debug_setup_1(NULL, NULL);
/*
* Reopen the file.
*/
if (*dbfilename == '/') {
s = g_strdup(dbfilename);
} else {
g_free(s);
s = g_strconcat(dbgdir, dbfilename, NULL);
}
if ((fd = open(s, O_RDWR|O_APPEND)) < 0) {
error(_("cannot reopen debug file %s"), dbfilename);
/*NOTREACHED*/
}
/*
* Finish setup.
*
* Note: we release control of the string 's' points to.
*/
debug_setup_2(s, fd, annotation);
}
void
debug_rename(
char *config,
char *subdir)
{
int fd = -1;
int i;
char *s = NULL;
mode_t mask;
if (!db_filename)
return;
if (get_pcontext() == CONTEXT_SCRIPTUTIL) {
return;
}
/* Remove old log from source directory */
debug_unlink_old();
/* set 'dbgdir' and clean out old debug files */
debug_setup_1(config, subdir);
/* Remove old log from destination directory */
debug_unlink_old();
g_free(s);
s = g_strconcat(dbgdir, db_name, NULL);
if (g_str_equal(db_filename, s)) {
amfree(s);
return;
}
mask = (mode_t)umask((mode_t)0037);
#if defined(__CYGWIN__)
/*
* On cygwin, rename will not overwrite an existing file nor
* will it rename a file that is open for writing...
*
* Rename file directly. Expect failure if file already exists
* or is open by another user.
*/
i = 0;
while (rename(db_filename, s) < 0) {
if (errno != EEXIST) {
/*
* If the failure was not due to the target file name already
* existing then we have bigger issues at hand so we keep
* the existing file.
*/
dbprintf(_("Cannot rename \"%s\" to \"%s\": %s\n"),
db_filename, s, strerror(errno));
g_free(s);
s = g_strdup(db_filename);
i = -1;
break;
}
/*
* Files already exists:
* Continue searching for a unique file name that will work.
*/
amfree(db_name);
if ((db_name = get_debug_name(open_time, i++)) == NULL) {
dbprintf(_("Cannot create unique debug file name"));
break;
}
g_free(s);
s = g_strconcat(dbgdir, db_name, NULL);
}
if (i >= 0) {
/*
* We need to close and reopen the original file handle to
* release control of the original debug file name.
*/
if ((fd = open(s, O_WRONLY|O_APPEND, 0640)) >= 0) {
/*
* We can safely close the the original log file
* since we now have a new working handle.
*/
db_fd = 2;
fclose(db_file);
db_file = NULL;
}
}
#else
/* check if a file with the same name already exists. */
if ((fd = open(s, O_WRONLY|O_CREAT|O_EXCL|O_APPEND, 0640)) < 0) {
for(i = 0; fd < 0; i++) {
amfree(db_name);
if ((db_name = get_debug_name(open_time, i)) == NULL) {
dbprintf(_("Cannot create debug file"));
break;
}
g_free(s);
s = g_strconcat(dbgdir, db_name, NULL);
if ((fd = open(s, O_WRONLY|O_CREAT|O_EXCL|O_APPEND, 0640)) < 0) {
if (errno != EEXIST) {
dbprintf(_("Cannot create debug file: %s"),
strerror(errno));
break;
}
}
}
}
if (fd >= 0) {
close(fd);
if (rename(db_filename, s) == -1) {
dbprintf(_("Cannot rename \"%s\" to \"%s\": %s\n"),
db_filename, s, strerror(errno));
}
fd = -1;
}
#endif
(void)umask(mask); /* Restore mask */
/*
* Finish setup.
*
* Note: we release control of the string 's' points to.
*/
debug_setup_2(s, fd, "rename");
}
void debug_ressource_usage(void);
void
debug_ressource_usage(void)
{
struct rusage usage;
getrusage(RUSAGE_SELF, &usage);
g_debug("ru_utime : %ld", usage.ru_utime.tv_sec);
g_debug("ru_stime : %ld", usage.ru_stime.tv_sec);
g_debug("ru_maxrss : %ld", usage.ru_maxrss );
g_debug("ru_ixrss : %ld", usage.ru_ixrss );
g_debug("ru_idrss : %ld", usage.ru_idrss );
g_debug("ru_isrss : %ld", usage.ru_isrss );
g_debug("ru_minflt : %ld", usage.ru_minflt );
g_debug("ru_majflt : %ld", usage.ru_majflt );
g_debug("ru_nswap : %ld", usage.ru_nswap );
g_debug("ru_inblock : %ld", usage.ru_inblock );
g_debug("ru_oublock : %ld", usage.ru_oublock );
g_debug("ru_msgsnd : %ld", usage.ru_msgsnd );
g_debug("ru_msgrcv : %ld", usage.ru_msgrcv );
g_debug("ru_nsignals: %ld", usage.ru_nsignals);
g_debug("ru_nvcsw : %ld", usage.ru_nvcsw );
g_debug("ru_nivcsw : %ld", usage.ru_nivcsw );
}
void
debug_close(void)
{
time_t curtime;
if (get_pcontext() == CONTEXT_SCRIPTUTIL) {
return;
}
debug_ressource_usage();
debug_unlink_old();
time(&curtime);
debug_printf(_("pid %ld finish time %s"), (long)getpid(), ctime(&curtime));
if(db_file && fclose(db_file) == EOF) {
int save_errno = errno;
db_file = NULL; /* prevent recursion */
g_fprintf(stderr, _("close debug file: %s"), strerror(save_errno));
/*NOTREACHED*/
}
db_fd = 2;
db_file = NULL;
amfree(db_filename);
amfree(db_name);
}
/*
* Format and write a debug message to the process debug file.
*/
void debug_printf(const char *format, ...)
{
va_list argp;
int save_errno;
/*
* It is common in the code to call dbprintf to write out
* syserrno(errno) and then turn around and try to do something else
* with errno (e.g. g_printf() or log()), so we make sure errno goes
* back out with the same value it came in with.
*/
save_errno = errno;
/* handle the default (stderr) if debug_open hasn't been called yet */
if(db_file == NULL && db_fd == 2) {
db_file = stderr;
}
if(db_file != NULL) {
char *prefix;
char *text;
char *text_out;
char timestamp[128];
if (db_file != stderr)
prefix = g_strdup_printf("%s: pid %d: thd-%p: %s:", msg_timestamp(timestamp), (int)getpid(), g_thread_self(), get_pname());
else
prefix = g_strdup_printf("%s:", get_pname());
arglist_start(argp, format);
text = g_strdup_vprintf(format, argp);
arglist_end(argp);
text_out = g_strdup_printf("%s %s", prefix, text);
fprintf(db_file, "%s", text_out);
fflush(db_file);
amfree(prefix);
amfree(text);
amfree(text_out);
}
errno = save_errno;
}
int
debug_fd(void)
{
return db_fd;
}
FILE *
debug_fp(void)
{
return db_file;
}
char *
debug_fn(void)
{
return db_filename;
}
void
debug_dup_stderr_to_debug(void)
{
if(db_fd != -1 && db_fd != STDERR_FILENO)
{
if(dup2(db_fd, STDERR_FILENO) != STDERR_FILENO)
{
error(_("can't redirect stderr to the debug file: %d, %s"), db_fd, strerror(errno));
g_assert_not_reached();
}
}
}