X-Git-Url: https://git.sur5r.net/?a=blobdiff_plain;f=bacula%2Fsrc%2Flib%2Fmessage.c;h=5e90f0fefa34ccbf5d8e9725abcc378a8263887a;hb=7f7447d979d17abff0019fe878cb3794b2600126;hp=bc527a7b79a3975c2e438e964e6c92e13f5dba0c;hpb=977a779389e122f3c226bfff4eb86416cf8cdfbd;p=bacula%2Fbacula diff --git a/bacula/src/lib/message.c b/bacula/src/lib/message.c index bc527a7b79..5e90f0fefa 100644 --- a/bacula/src/lib/message.c +++ b/bacula/src/lib/message.c @@ -1,45 +1,38 @@ /* - Bacula® - The Network Backup Solution - - Copyright (C) 2000-2009 Free Software Foundation Europe e.V. - - The main author of Bacula is Kern Sibbald, with contributions from - many others, a complete list can be found in the file AUTHORS. - This program is Free Software; you can redistribute it and/or - modify it under the terms of version two of the GNU General Public - License as published by the Free Software Foundation and included - in the file LICENSE. - - This program is distributed in the hope that it will be useful, but - WITHOUT ANY WARRANTY; without even the implied warranty of - MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU - General Public License for more details. - - You should have received a copy of the GNU General Public License - along with this program; if not, write to the Free Software - Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA - 02110-1301, USA. - - Bacula® is a registered trademark of Kern Sibbald. - The licensor of Bacula is the Free Software Foundation Europe - (FSFE), Fiduciary Program, Sumatrastrasse 25, 8006 Zürich, - Switzerland, email:ftf@fsfeurope.org. + Bacula(R) - The Network Backup Solution + + Copyright (C) 2000-2017 Kern Sibbald + + The original author of Bacula is Kern Sibbald, with contributions + from many others, a complete list can be found in the file AUTHORS. + + You may use this file and others of this release according to the + license defined in the LICENSE file, which includes the Affero General + Public License, v3.0 ("AGPLv3") and some additional permissions and + terms pursuant to its AGPLv3 Section 7. + + This notice must be preserved when any source code is + conveyed and/or propagated. + + Bacula(R) is a registered trademark of Kern Sibbald. */ /* * Bacula message handling routines * - * Kern Sibbald, April 2000 + * NOTE: don't use any Jmsg or Qmsg calls within this file, + * except in q_msg or j_msg (setup routines), + * otherwise you may get into recursive calls if there are + * errors, and that can lead to looping or deadlocks. * - * Version $Id$ + * Kern Sibbald, April 2000 * */ - #include "bacula.h" #include "jcr.h" -sql_query p_sql_query = NULL; -sql_escape p_sql_escape = NULL; +sql_query_call p_sql_query = NULL; +sql_escape_call p_sql_escape = NULL; #define FULL_LOCATION 1 /* set for file:line in Debug messages */ @@ -47,20 +40,32 @@ sql_escape p_sql_escape = NULL; * This is where we define "Globals" because all the * daemons include this file. */ -const char *working_directory = NULL; /* working directory path stored here */ -int verbose = 0; /* increase User messages */ -int debug_level = 0; /* debug level */ -bool dbg_timestamp = false; /* print timestamp in debug output */ -utime_t daemon_start_time = 0; /* Daemon start time */ +dlist *daemon_msg_queue = NULL; +pthread_mutex_t daemon_msg_queue_mutex = PTHREAD_MUTEX_INITIALIZER; +static bool dequeuing_daemon_msgs = false; +const char *working_directory = NULL; /* working directory path stored here */ +const char *assert_msg = NULL; /* ASSERT2 error message */ const char *version = VERSION " (" BDATE ")"; -char my_name[30]; /* daemon name is stored here */ -char host_name[50]; /* host machine name */ +const char *dist_name = DISTNAME " " DISTVER; char *exepath = (char *)NULL; char *exename = (char *)NULL; -int console_msg_pending = false; +char db_engine_name[50] = {0}; /* Database engine name or type */ char con_fname[500]; /* Console filename */ +char my_name[MAX_NAME_LENGTH] = {0}; /* daemon name is stored here */ +char host_name[50] = {0}; /* host machine name */ +char fail_time[30] = {0}; /* Time of failure */ +int verbose = 0; /* increase User messages */ +int64_t debug_level = 0; /* debug level */ +int64_t debug_level_tags = 0; /* debug tags */ +int32_t debug_flags = 0; /* debug flags */ +int console_msg_pending = false; +utime_t daemon_start_time = 0; /* Daemon start time */ FILE *con_fd = NULL; /* Console file descriptor */ brwlock_t con_lock; /* Console lock structure */ +bool dbg_timestamp = false; /* print timestamp in debug output */ +bool dbg_thread = false; /* add thread_id to details */ +bool prt_kaboom = false; /* Print kaboom output */ +job_code_callback_t message_job_code_callback = NULL; /* Job code callback. Only used by director. */ /* Forward referenced functions */ @@ -69,10 +74,12 @@ void create_jcr_key(); /* Static storage */ +/* Exclude spaces but require .mail at end */ +#define MAIL_REGEX "^[^ ]+\\.mail$" + /* Allow only one thread to tweak d->fd at a time */ static pthread_mutex_t fides_mutex = PTHREAD_MUTEX_INITIALIZER; static MSGS *daemon_msgs; /* global messages */ -static char *catalog_db = NULL; /* database type */ static void (*message_callback)(int type, char *msg) = NULL; static FILE *trace_fd = NULL; #if defined(HAVE_WIN32) @@ -80,12 +87,144 @@ static bool trace = true; #else static bool trace = false; #endif +static int hangup = 0; +static int blowup = 0; /* Constants */ const char *host_os = HOST_OS; const char *distname = DISTNAME; const char *distver = DISTVER; +/* + * Walk back in a string from end looking for a + * path separator. + * This routine is passed the start of the string and + * the end of the string, it returns either the beginning + * of the string or where it found a path separator. + */ +static const char *bstrrpath(const char *start, const char *end) +{ + while ( end > start ) { + end--; + if (IsPathSeparator(*end)) { + break; + } + } + return end; +} + +/* Some message class methods */ +void MSGS::lock() +{ + P(fides_mutex); +} + +void MSGS::unlock() +{ + V(fides_mutex); +} + +/* + * Wait for not in use variable to be clear + */ +void MSGS::wait_not_in_use() /* leaves fides_mutex set */ +{ + lock(); + while (m_in_use || m_closing) { + unlock(); + bmicrosleep(0, 200); /* wait */ + lock(); + } +} + +/* + * Handle message delivery errors + */ +static void delivery_error(const char *fmt,...) +{ + va_list arg_ptr; + int i, len, maxlen; + POOLMEM *pool_buf; + char dt[MAX_TIME_LENGTH]; + int dtlen; + + pool_buf = get_pool_memory(PM_EMSG); + + bstrftime_ny(dt, sizeof(dt), time(NULL)); + dtlen = strlen(dt); + dt[dtlen++] = ' '; + dt[dtlen] = 0; + + i = Mmsg(pool_buf, "%s Message delivery ERROR: ", dt); + + for (;;) { + maxlen = sizeof_pool_memory(pool_buf) - i - 1; + va_start(arg_ptr, fmt); + len = bvsnprintf(pool_buf+i, maxlen, fmt, arg_ptr); + va_end(arg_ptr); + if (len < 0 || len >= (maxlen-5)) { + pool_buf = realloc_pool_memory(pool_buf, maxlen + i + maxlen/2); + continue; + } + break; + } + + fputs(pool_buf, stdout); /* print this here to INSURE that it is printed */ + fflush(stdout); + syslog(LOG_DAEMON|LOG_ERR, "%s", pool_buf); + free_memory(pool_buf); +} + +void set_debug_flags(char *options) +{ + for (char *p = options; *p ; p++) { + switch(*p) { + case '0': /* clear flags */ + debug_flags = 0; + break; + + case 'i': /* used by FD */ + case 'd': /* used by FD */ + break; + + case 't': + dbg_timestamp = true; + break; + + case 'T': + dbg_timestamp = false; + break; + + case 'h': + dbg_thread = true; + break; + + case 'H': + dbg_thread = false; + break; + + case 'c': + /* truncate the trace file */ + if (trace && trace_fd) { + ftruncate(fileno(trace_fd), 0); + } + break; + + case 'l': + /* Turn on/off add_events for P()/V() */ + debug_flags |= DEBUG_MUTEX_EVENT; + break; + + case 'p': + /* Display event stack during lockdump */ + debug_flags |= DEBUG_PRINT_EVENT; + break; + + default: + Dmsg1(000, "Unknown debug flag %c\n", *p); + } + } +} void register_message_callback(void msg_callback(int type, char *msg)) { @@ -125,7 +264,7 @@ void my_name_is(int argc, char *argv[], const char *name) } else { l = argv[0]; #if defined(HAVE_WIN32) - /* On Windows allow c: junk */ + /* On Windows allow c: drive specification */ if (l[1] == ':') { l += 2; } @@ -157,21 +296,21 @@ void my_name_is(int argc, char *argv[], const char *name) } } -const char * -get_db_type(void) -{ - return catalog_db != NULL ? catalog_db : "unknown"; -} - +/* Set special ASSERT2 message where debugger can find it */ void -set_db_type(const char *name) +set_assert_msg(const char *file, int line, const char *msg) { - if (catalog_db != NULL) { - free(catalog_db); - } - catalog_db = bstrdup(name); + char buf[2000]; + bsnprintf(buf, sizeof(buf), "ASSERT at %s:%d-%u ERR=%s", + get_basename(file), line, get_jobid_from_tsd(), msg); + assert_msg = bstrdup(buf); } +void set_db_engine_name(const char *name) +{ + bstrncpy(db_engine_name, name, sizeof(db_engine_name)-1); +} + /* * Initialize message handler for a daemon or a Job * We make a copy of the MSGS resource passed, so it belows @@ -181,7 +320,7 @@ set_db_type(const char *name) * non-NULL -> initialize jcr using Message resource */ void -init_msg(JCR *jcr, MSGS *msg) +init_msg(JCR *jcr, MSGS *msg, job_code_callback_t job_code_callback) { DEST *d, *dnew, *temp_chain = NULL; int i; @@ -194,6 +333,8 @@ init_msg(JCR *jcr, MSGS *msg) set_jcr_in_tsd(INVALID_JCR); } + message_job_code_callback = job_code_callback; + #if !defined(HAVE_WIN32) /* * Make sure we have fd's 0, 1, 2 open @@ -260,8 +401,8 @@ init_msg(JCR *jcr, MSGS *msg) daemon_msgs->dest_chain = temp_chain; memcpy(daemon_msgs->send_msg, msg->send_msg, sizeof(msg->send_msg)); } - Dmsg2(250, "Copy message resource %p to %p\n", msg, temp_chain); + Dmsg2(250, "Copy message resource %p to %p\n", msg, temp_chain); } /* Initialize so that the console (User Agent) can @@ -282,7 +423,7 @@ void init_console_msg(const char *wd) console_msg_pending = 1; } close(fd); - con_fd = fopen(con_fname, "a+b"); + con_fd = bfopen(con_fname, "a+b"); if (!con_fd) { berrno be; Emsg2(M_ERROR, 0, _("Could not open console message file %s: ERR=%s\n"), @@ -386,7 +527,7 @@ static BPIPE *open_mail_pipe(JCR *jcr, POOLMEM *&cmd, DEST *d) BPIPE *bpipe; if (d->mail_cmd) { - cmd = edit_job_codes(jcr, cmd, d->mail_cmd, d->where); + cmd = edit_job_codes(jcr, cmd, d->mail_cmd, d->where, message_job_code_callback); } else { Mmsg(cmd, "/usr/lib/sendmail -F Bacula %s", d->where); } @@ -399,7 +540,7 @@ static BPIPE *open_mail_pipe(JCR *jcr, POOLMEM *&cmd, DEST *d) } } else { berrno be; - Jmsg(jcr, M_ERROR, 0, _("open mail pipe %s failed: ERR=%s\n"), + delivery_error(_("open mail pipe %s failed: ERR=%s\n"), cmd, be.bstrerror()); } return bpipe; @@ -428,10 +569,24 @@ void close_msg(JCR *jcr) if (msgs == NULL) { return; } - P(fides_mutex); + + /* Wait for item to be not in use, then mark closing */ + if (msgs->is_closing()) { + return; + } + msgs->wait_not_in_use(); /* leaves fides_mutex set */ + /* Note get_closing() does not lock because we are already locked */ + if (msgs->get_closing()) { + msgs->unlock(); + return; + } + msgs->set_closing(); + msgs->unlock(); + Dmsg1(850, "===Begin close msg resource at %p\n", msgs); cmd = get_pool_memory(PM_MESSAGE); for (d=msgs->dest_chain; d; ) { + bool success; if (d->fd) { switch (d->dest_code) { case MD_FILE: @@ -448,19 +603,17 @@ void close_msg(JCR *jcr) if (!d->fd) { break; } - if ( - (d->dest_code == MD_MAIL_ON_ERROR && jcr && - (jcr->JobStatus == JS_Terminated || jcr->JobStatus == JS_Warnings)) - || - (d->dest_code == MD_MAIL_ON_SUCCESS && jcr && - jcr->JobStatus == JS_ErrorTerminated) - ) { - goto rem_temp_file; + success = jcr && (jcr->JobStatus == JS_Terminated || jcr->JobStatus == JS_Warnings); + + if (d->dest_code == MD_MAIL_ON_ERROR && success) { + goto rem_temp_file; /* no mail */ + } else if (d->dest_code == MD_MAIL_ON_SUCCESS && !success) { + goto rem_temp_file; /* no mail */ } if (!(bpipe=open_mail_pipe(jcr, cmd, d))) { Pmsg0(000, _("open mail pipe failed.\n")); - goto rem_temp_file; + goto rem_temp_file; /* error get out */ } Dmsg0(850, "Opened mail pipe\n"); len = d->max_len+10; @@ -482,7 +635,7 @@ void close_msg(JCR *jcr) if (msgs != daemon_msgs) { /* read what mail prog returned -- should be nothing */ while (fgets(line, len, bpipe->rfd)) { - Jmsg1(jcr, M_INFO, 0, _("Mail prog: %s"), line); + delivery_error(_("Mail prog: %s"), line); } } @@ -491,18 +644,24 @@ void close_msg(JCR *jcr) berrno be; be.set_errno(stat); Dmsg1(850, "Calling emsg. CMD=%s\n", cmd); - Jmsg2(jcr, M_ERROR, 0, _("Mail program terminated in error.\n" - "CMD=%s\n" - "ERR=%s\n"), cmd, be.bstrerror()); + delivery_error(_("Mail program terminated in error.\n" + "CMD=%s\n" + "ERR=%s\n"), cmd, be.bstrerror()); } free_memory(line); + rem_temp_file: - /* Remove temp file */ - fclose(d->fd); - d->fd = NULL; - unlink(d->mail_filename); - free_pool_memory(d->mail_filename); - d->mail_filename = NULL; + /* Remove temp mail file */ + if (d->fd) { + fclose(d->fd); + d->fd = NULL; + } + /* Exclude spaces in mail_filename */ + if (d->mail_filename) { + safer_unlink(d->mail_filename, MAIL_REGEX); + free_pool_memory(d->mail_filename); + d->mail_filename = NULL; + } Dmsg0(850, "end mail or mail on error\n"); break; default: @@ -512,12 +671,13 @@ rem_temp_file: } d = d->next; /* point to next buffer */ } - V(fides_mutex); free_pool_memory(cmd); Dmsg0(850, "Done walking message chain.\n"); if (jcr) { free_msgs_res(msgs); msgs = NULL; + } else { + msgs->clear_closing(); } Dmsg0(850, "===End close msg resource\n"); } @@ -533,9 +693,11 @@ void free_msgs_res(MSGS *msgs) for (d=msgs->dest_chain; d; ) { if (d->where) { free(d->where); + d->where = NULL; } if (d->mail_cmd) { free(d->mail_cmd); + d->mail_cmd = NULL; } old = d; /* save pointer to release */ d = d->next; /* point to next buffer */ @@ -575,27 +737,45 @@ void term_msg() if (trace_fd) { fclose(trace_fd); trace_fd = NULL; + trace = false; } - if (catalog_db) { - free(catalog_db); - catalog_db = NULL; - } + working_directory = NULL; term_last_jobs_list(); } -static bool open_dest_file(JCR *jcr, DEST *d, const char *mode) +static bool open_dest_file(JCR *jcr, DEST *d, const char *mode) { - d->fd = fopen(d->where, mode); + d->fd = bfopen(d->where, mode); if (!d->fd) { berrno be; - d->fd = stdout; - Qmsg2(jcr, M_ERROR, 0, _("fopen %s failed: ERR=%s\n"), d->where, be.bstrerror()); - d->fd = NULL; + delivery_error(_("fopen %s failed: ERR=%s\n"), d->where, be.bstrerror()); return false; } return true; } +/* Split the output for syslog (it converts \n to ' ' and is + * limited to 1024 characters per syslog message + */ +static void send_to_syslog(int mode, const char *msg) +{ + int len; + char buf[1024]; + const char *p2; + const char *p = msg; + + while (*p && ((p2 = strchr(p, '\n')) != NULL)) { + len = MIN((int)sizeof(buf) - 1, p2 - p + 1); /* Add 1 to keep \n */ + strncpy(buf, p, len); + buf[len] = 0; + syslog(mode, "%s", buf); + p = p2+1; /* skip \n */ + } + if (*p != 0) { /* no \n at the end ? */ + syslog(mode, "%s", p); + } +} + /* * Handle sending the message to the appropriate place */ @@ -608,6 +788,7 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) MSGS *msgs; BPIPE *bpipe; const char *mode; + bool created_jcr = false; Dmsg2(850, "Enter dispatch_msg type=%d msg=%s", type, msg); @@ -637,10 +818,14 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) return; } + /* For serious errors make sure message is printed or logged */ if (type == M_ABORT || type == M_ERROR_TERM) { fputs(dt, stdout); - fputs(msg, stdout); /* print this here to INSURE that it is printed */ + fputs(msg, stdout); fflush(stdout); + if (type == M_ABORT) { + syslog(LOG_DAEMON|LOG_ERR, "%s", msg); + } } @@ -649,33 +834,54 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) if (!jcr) { jcr = get_jcr_from_tsd(); } + if (!jcr) { + jcr = new_jcr(sizeof(JCR), NULL); + created_jcr = true; + } if (jcr) { msgs = jcr->jcr_msgs; } if (msgs == NULL) { msgs = daemon_msgs; } + /* + * If closing this message resource, print and send to syslog, + * then get out. + */ + if (msgs->is_closing()) { + fputs(dt, stdout); + fputs(msg, stdout); + fflush(stdout); + syslog(LOG_DAEMON|LOG_ERR, "%s", msg); + return; + } + + for (d=msgs->dest_chain; d; d=d->next) { if (bit_is_set(type, d->msg_types)) { + bool ok; switch (d->dest_code) { case MD_CATALOG: char ed1[50]; - if (!jcr || !jcr->db) { + if (!jcr || !jcr->db) { break; } if (p_sql_query && p_sql_escape) { POOLMEM *cmd = get_pool_memory(PM_MESSAGE); POOLMEM *esc_msg = get_pool_memory(PM_MESSAGE); - + int len = strlen(msg) + 1; esc_msg = check_pool_memory_size(esc_msg, len*2+1); - p_sql_escape(jcr, jcr->db, esc_msg, msg, len); - - bstrutime(dt, sizeof(dt), mtime); - Mmsg(cmd, "INSERT INTO Log (JobId, Time, LogText) VALUES (%s,'%s','%s')", - edit_int64(jcr->JobId, ed1), dt, esc_msg); - p_sql_query(jcr, cmd); - + ok = p_sql_escape(jcr, jcr->db, esc_msg, msg, len); + if (ok) { + bstrutime(dt, sizeof(dt), mtime); + Mmsg(cmd, "INSERT INTO Log (JobId, Time, LogText) VALUES (%s,'%s','%s')", + edit_int64(jcr->JobId, ed1), dt, esc_msg); + ok = p_sql_query(jcr, cmd); + } + if (!ok) { + delivery_error(_("Message delivery error: Unable to store data in database.\n")); + } free_pool_memory(cmd); free_pool_memory(esc_msg); } @@ -683,7 +889,7 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) case MD_CONSOLE: Dmsg1(850, "CONSOLE for following msg: %s", msg); if (!con_fd) { - con_fd = fopen(con_fname, "a+b"); + con_fd = bfopen(con_fname, "a+b"); Dmsg0(850, "Console file not open.\n"); } if (con_fd) { @@ -711,7 +917,7 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) /* * We really should do an openlog() here. */ - syslog(LOG_DAEMON|LOG_ERR, "%s", msg); + send_to_syslog(LOG_DAEMON|LOG_ERR, msg); break; case MD_OPERATOR: Dmsg1(850, "OPERATOR for following msg: %s\n", msg); @@ -725,7 +931,7 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) if (stat != 0) { berrno be; be.set_errno(stat); - Qmsg2(jcr, M_ERROR, 0, _("Operator mail program terminated in error.\n" + delivery_error(_("Msg delivery error: Operator mail program terminated in error.\n" "CMD=%s\n" "ERR=%s\n"), mcmd, be.bstrerror()); } @@ -736,19 +942,20 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) case MD_MAIL_ON_ERROR: case MD_MAIL_ON_SUCCESS: Dmsg1(850, "MAIL for following msg: %s", msg); - P(fides_mutex); + if (msgs->is_closing()) { + break; + } + msgs->set_in_use(); if (!d->fd) { POOLMEM *name = get_pool_memory(PM_MESSAGE); make_unique_mail_filename(jcr, name, d); - d->fd = fopen(name, "w+b"); + d->fd = bfopen(name, "w+b"); if (!d->fd) { berrno be; - d->fd = stdout; - Qmsg2(jcr, M_ERROR, 0, _("fopen %s failed: ERR=%s\n"), name, + delivery_error(_("Msg delivery error: fopen %s failed: ERR=%s\n"), name, be.bstrerror()); - d->fd = NULL; free_pool_memory(name); - V(fides_mutex); + msgs->clear_in_use(); break; } d->mail_filename = name; @@ -759,7 +966,7 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) d->max_len = len; /* keep max line length */ } fputs(msg, d->fd); - V(fides_mutex); + msgs->clear_in_use(); break; case MD_APPEND: Dmsg1(850, "APPEND for following msg: %s", msg); @@ -769,9 +976,12 @@ void dispatch_message(JCR *jcr, int type, utime_t mtime, char *msg) Dmsg1(850, "FILE for following msg: %s", msg); mode = "w+b"; send_to_file: - P(fides_mutex); + if (msgs->is_closing()) { + break; + } + msgs->set_in_use(); if (!d->fd && !open_dest_file(jcr, d, mode)) { - V(fides_mutex); + msgs->clear_in_use(); break; } fputs(dt, d->fd); @@ -785,13 +995,13 @@ send_to_file: fputs(msg, d->fd); } } - V(fides_mutex); + msgs->clear_in_use(); break; case MD_DIRECTOR: Dmsg1(850, "DIRECTOR for following msg: %s", msg); if (jcr && jcr->dir_bsock && !jcr->dir_bsock->errors) { - jcr->dir_bsock->fsend("Jmsg Job=%s type=%d level=%lld %s", - jcr->Job, type, mtime, msg); + jcr->dir_bsock->fsend("Jmsg JobId=%ld type=%d level=%lld %s", + jcr->JobId, type, mtime, msg); } else { Dmsg1(800, "no jcr for following msg: %s", msg); } @@ -815,31 +1025,59 @@ send_to_file: } } } + if (created_jcr) { + free_jcr(jcr); + } } /********************************************************************* * - * This subroutine returns the filename portion of a Windows - * path. It is used because Microsoft Visual Studio sets __FILE__ - * to the full path. + * This subroutine returns the filename portion of a path. + * It is used because some compilers set __FILE__ + * to the full path. Try to return base + next higher path. */ -inline const char * -get_basename(const char *pathname) +const char *get_basename(const char *pathname) { -#if defined(_MSC_VER) const char *basename; - - if ((basename = strrchr(pathname, '\\')) == NULL) { - basename = pathname; + + if ((basename = bstrrpath(pathname, pathname+strlen(pathname))) == pathname) { + /* empty */ + } else if ((basename = bstrrpath(pathname, basename-1)) == pathname) { + /* empty */ } else { basename++; } - return basename; -#else - return pathname; -#endif +} + +/* + * print or write output to trace file + */ +static void pt_out(char *buf) +{ + /* + * Used the "trace on" command in the console to turn on + * output to the trace file. "trace off" will close the file. + */ + if (trace) { + if (!trace_fd) { + char fn[200]; + bsnprintf(fn, sizeof(fn), "%s/%s.trace", working_directory ? working_directory : "./", my_name); + trace_fd = bfopen(fn, "a+b"); + } + if (trace_fd) { + fputs(buf, trace_fd); + fflush(trace_fd); + return; + } else { + /* Some problem, turn off tracing */ + trace = false; + } + } + /* not tracing */ + fputs(buf, stdout); + fflush(stdout); } /********************************************************************* @@ -851,13 +1089,13 @@ get_basename(const char *pathname) * * If the level is negative, the details of file and line number * are not printed. + * */ void -d_msg(const char *file, int line, int level, const char *fmt,...) +vd_msg(const char *file, int line, int64_t level, const char *fmt, va_list arg_ptr) { char buf[5000]; - int len; - va_list arg_ptr; + int len = 0; /* space used in buf */ bool details = true; utime_t mtime; @@ -866,54 +1104,42 @@ d_msg(const char *file, int line, int level, const char *fmt,...) level = -level; } - if (level <= debug_level) { + if (chk_dbglvl(level)) { if (dbg_timestamp) { mtime = time(NULL); - bstrftimes(buf, sizeof(buf), mtime); + bstrftimes(buf+len, sizeof(buf)-len, mtime); len = strlen(buf); buf[len++] = ' '; - buf[len] = 0; - fputs(buf, stdout); } - + #ifdef FULL_LOCATION if (details) { - len = bsnprintf(buf, sizeof(buf), "%s: %s:%d-%u ", - my_name, get_basename(file), line, get_jobid_from_tsd()); - } else { - len = 0; + if (dbg_thread) { + len += bsnprintf(buf+len, sizeof(buf)-len, "%s[%lld]: %s:%d-%u ", + my_name, bthread_get_thread_id(), + get_basename(file), line, get_jobid_from_tsd()); + } else { + len += bsnprintf(buf+len, sizeof(buf)-len, "%s: %s:%d-%u ", + my_name, get_basename(file), line, get_jobid_from_tsd()); + } } -#else - len = 0; #endif - va_start(arg_ptr, fmt); bvsnprintf(buf+len, sizeof(buf)-len, (char *)fmt, arg_ptr); - va_end(arg_ptr); - /* - * Used the "trace on" command in the console to turn on - * output to the trace file. "trace off" will close the file. - */ - if (trace) { - if (!trace_fd) { - char fn[200]; - bsnprintf(fn, sizeof(fn), "%s/%s.trace", working_directory ? working_directory : "./", my_name); - trace_fd = fopen(fn, "a+b"); - } - if (trace_fd) { - fputs(buf, trace_fd); - fflush(trace_fd); - } else { - /* Some problem, turn off tracing */ - trace = false; - } - } else { /* not tracing */ - fputs(buf, stdout); - fflush(stdout); - } + pt_out(buf); } } +void +d_msg(const char *file, int line, int64_t level, const char *fmt,...) +{ + va_list arg_ptr; + va_start(arg_ptr, fmt); + vd_msg(file, line, level, fmt, arg_ptr); /* without tags */ + va_end(arg_ptr); +} + + /* * Set trace flag on/off. If argument is negative, there is no change */ @@ -934,6 +1160,61 @@ void set_trace(int trace_flag) } } +void set_hangup(int hangup_value) +{ + if (hangup_value != -1) { + hangup = hangup_value; + } +} + +int get_hangup(void) +{ + return hangup; +} + +void set_blowup(int blowup_value) +{ + if (blowup_value != -1) { + blowup = blowup_value; + } +} + +int get_blowup(void) +{ + return blowup; +} + +bool handle_hangup_blowup(JCR *jcr, uint32_t file_count, uint64_t byte_count) +{ + if (hangup == 0 && blowup == 0) { + /* quick check */ + return false; + } + /* Debug code: check if we must hangup or blowup */ + if ((hangup > 0 && (file_count > (uint32_t)hangup)) || + (hangup < 0 && (byte_count/1024 > (uint32_t)-hangup))) { + jcr->setJobStatus(JS_Incomplete); + if (hangup > 0) { + Jmsg1(jcr, M_FATAL, 0, "Debug hangup requested after %d files.\n", hangup); + } else { + Jmsg1(jcr, M_FATAL, 0, "Debug hangup requested after %d Kbytes.\n", -hangup); + } + set_hangup(0); + return true; + } + if ((blowup > 0 && (file_count > (uint32_t)blowup)) || + (blowup < 0 && (byte_count/1024 > (uint32_t)-blowup))) { + if (blowup > 0) { + Jmsg1(jcr, M_ABORT, 0, "Debug blowup requested after %d files.\n", blowup); + } else { + Jmsg1(jcr, M_ABORT, 0, "Debug blowup requested after %d Kbytes.\n", -blowup); + } + /* will never reach this line */ + return true; + } + return false; +} + bool get_trace(void) { return trace; @@ -950,23 +1231,28 @@ void p_msg(const char *file, int line, int level, const char *fmt,...) { char buf[5000]; - int len; + int len = 0; /* space used in buf */ va_list arg_ptr; + if (dbg_timestamp) { + utime_t mtime = time(NULL); + bstrftimes(buf+len, sizeof(buf)-len, mtime); + len = strlen(buf); + buf[len++] = ' '; + } + #ifdef FULL_LOCATION if (level >= 0) { - len = bsnprintf(buf, sizeof(buf), "%s: %s:%d ", my_name, get_basename(file), line); - } else { - len = 0; + len += bsnprintf(buf+len, sizeof(buf)-len, "%s: %s:%d-%u ", + my_name, get_basename(file), line, get_jobid_from_tsd()); } -#else - len = 0; #endif + va_start(arg_ptr, fmt); bvsnprintf(buf+len, sizeof(buf)-len, (char *)fmt, arg_ptr); va_end(arg_ptr); - fputs(buf, stdout); - fflush(stdout); + + pt_out(buf); } @@ -981,13 +1267,15 @@ p_msg(const char *file, int line, int level, const char *fmt,...) * are not printed. */ void -t_msg(const char *file, int line, int level, const char *fmt,...) +t_msg(const char *file, int line, int64_t level, const char *fmt,...) { char buf[5000]; int len; va_list arg_ptr; int details = TRUE; + level = level & ~DT_ALL; /* level should be tag free */ + if (level < 0) { details = FALSE; level = -level; @@ -996,7 +1284,7 @@ t_msg(const char *file, int line, int level, const char *fmt,...) if (level <= debug_level) { if (!trace_fd) { bsnprintf(buf, sizeof(buf), "%s/%s.trace", working_directory ? working_directory : ".", my_name); - trace_fd = fopen(buf, "a+b"); + trace_fd = bfopen(buf, "a+b"); } #ifdef FULL_LOCATION @@ -1074,6 +1362,7 @@ e_msg(const char *file, int line, int type, int level, const char *fmt,...) bvsnprintf(buf+len, sizeof(buf)-len, (char *)fmt, arg_ptr); va_end(arg_ptr); + pt_out(buf); dispatch_message(NULL, type, 0, buf); if (type == M_ABORT) { @@ -1085,6 +1374,23 @@ e_msg(const char *file, int line, int type, int level, const char *fmt,...) } } +/* Check in the msgs resource if a given type is defined */ +bool is_message_type_set(JCR *jcr, int type) +{ + MSGS *msgs = NULL; + if (jcr) { + msgs = jcr->jcr_msgs; + } + if (!msgs) { + msgs = daemon_msgs; /* if no jcr, we use daemon handler */ + } + if (msgs && (type != M_ABORT && type != M_ERROR_TERM) && + !bit_is_set(type, msgs->send_msg)) { + return false; /* no destination */ + } + return true; +} + /* ********************************************************* * * Generate a Job message @@ -1116,11 +1422,24 @@ Jmsg(JCR *jcr, int type, utime_t mtime, const char *fmt,...) return; } + /* The watchdog thread can't use Jmsg directly, we always queued it */ + if (is_watchdog()) { + va_start(arg_ptr, fmt); + bvsnprintf(rbuf, sizeof(rbuf), fmt, arg_ptr); + va_end(arg_ptr); + Qmsg(jcr, type, mtime, "%s", rbuf); + return; + } + msgs = NULL; if (!jcr) { jcr = get_jcr_from_tsd(); } if (jcr) { + if (!jcr->dequeuing_msgs) { /* Avoid recursion */ + /* Dequeue messages to keep the original order */ + dequeue_messages(jcr); + } msgs = jcr->jcr_msgs; JobId = jcr->JobId; } @@ -1146,7 +1465,10 @@ Jmsg(JCR *jcr, int type, utime_t mtime, const char *fmt,...) case M_FATAL: len = bsnprintf(rbuf, sizeof(rbuf), _("%s JobId %u: Fatal error: "), my_name, JobId); if (jcr) { - set_jcr_job_status(jcr, JS_FatalError); + jcr->setJobStatus(JS_FatalError); + } + if (jcr && jcr->JobErrors == 0) { + jcr->JobErrors = 1; } break; case M_ERROR: @@ -1162,7 +1484,7 @@ Jmsg(JCR *jcr, int type, utime_t mtime, const char *fmt,...) } break; case M_SECURITY: - len = bsnprintf(rbuf, sizeof(rbuf), _("%s JobId %u: Security violation: "), + len = bsnprintf(rbuf, sizeof(rbuf), _("%s JobId %u: Security violation: "), my_name, JobId); break; default: @@ -1197,6 +1519,10 @@ void j_msg(const char *file, int line, JCR *jcr, int type, utime_t mtime, const int i, len, maxlen; POOLMEM *pool_buf; + va_start(arg_ptr, fmt); + vd_msg(file, line, 0, fmt, arg_ptr); + va_end(arg_ptr); + pool_buf = get_pool_memory(PM_EMSG); i = Mmsg(pool_buf, "%s:%d ", get_basename(file), line); @@ -1325,8 +1651,6 @@ int Mmsg(POOL_MEM &pool_buf, const char *fmt, ...) } -static pthread_mutex_t msg_queue_mutex = PTHREAD_MUTEX_INITIALIZER; - /* * We queue messages rather than print them directly. This * is generally used in low level routines (msg handler, bnet) @@ -1361,16 +1685,24 @@ void Qmsg(JCR *jcr, int type, utime_t mtime, const char *fmt,...) if (!jcr) { jcr = get_jcr_from_tsd(); } - /* If no jcr or dequeuing send to daemon to avoid recursion */ - if ((jcr && !jcr->msg_queue) || !jcr || jcr->dequeuing) { - /* jcr==NULL => daemon message, safe to send now */ - Jmsg(jcr, item->type, item->mtime, "%s", item->msg); - free(item); + + if (jcr && type==M_FATAL) { + jcr->setJobStatus(JS_FatalError); + } + + /* If no jcr or no queue or dequeuing send to syslog */ + if (!jcr || !jcr->msg_queue || jcr->dequeuing_msgs) { + syslog(LOG_DAEMON|LOG_ERR, "%s", item->msg); + P(daemon_msg_queue_mutex); + if (daemon_msg_queue) { + daemon_msg_queue->append(item); + } + V(daemon_msg_queue_mutex); } else { /* Queue message for later sending */ - P(msg_queue_mutex); + P(jcr->msg_queue_mutex); jcr->msg_queue->append(item); - V(msg_queue_mutex); + V(jcr->msg_queue_mutex); } free_memory(pool_buf); } @@ -1381,19 +1713,48 @@ void Qmsg(JCR *jcr, int type, utime_t mtime, const char *fmt,...) void dequeue_messages(JCR *jcr) { MQUEUE_ITEM *item; - P(msg_queue_mutex); - if (!jcr->msg_queue) { - goto bail_out; + JobId_t JobId; + + /* Avoid bad calls and recursion */ + if (!jcr || jcr->dequeuing_msgs) { + return; + } + + /* Dequeue daemon messages */ + if (daemon_msg_queue && !dequeuing_daemon_msgs) { + P(daemon_msg_queue_mutex); + dequeuing_daemon_msgs = true; + jcr->dequeuing_msgs = true; + JobId = jcr->JobId; + jcr->JobId = 0; /* set daemon JobId == 0 */ + if (jcr->dir_bsock) jcr->dir_bsock->suppress_error_messages(true); + foreach_dlist(item, daemon_msg_queue) { + Jmsg(jcr, item->type, item->mtime, "%s", item->msg); + } + if (jcr->dir_bsock) jcr->dir_bsock->suppress_error_messages(false); + /* Remove messages just sent */ + daemon_msg_queue->destroy(); + jcr->JobId = JobId; /* restore JobId */ + jcr->dequeuing_msgs = false; + dequeuing_daemon_msgs = false; + V(daemon_msg_queue_mutex); + } + + /* Dequeue Job specific messages */ + if (!jcr->msg_queue || jcr->dequeuing_msgs) { + return; } - jcr->dequeuing = true; + P(jcr->msg_queue_mutex); + jcr->dequeuing_msgs = true; + if (jcr->dir_bsock) jcr->dir_bsock->suppress_error_messages(true); foreach_dlist(item, jcr->msg_queue) { Jmsg(jcr, item->type, item->mtime, "%s", item->msg); } + if (jcr->dir_bsock) jcr->dir_bsock->suppress_error_messages(false); + /* Remove messages just sent */ jcr->msg_queue->destroy(); - jcr->dequeuing = false; - -bail_out: - V(msg_queue_mutex); + jcr->dequeuing_msgs = false; + V(jcr->msg_queue_mutex); } @@ -1408,7 +1769,7 @@ void q_msg(const char *file, int line, JCR *jcr, int type, utime_t mtime, const POOLMEM *pool_buf; pool_buf = get_pool_memory(PM_EMSG); - i = Mmsg(pool_buf, "%s:%d ", file, line); + i = Mmsg(pool_buf, "%s:%d ", get_basename(file), line); for (;;) { maxlen = sizeof_pool_memory(pool_buf) - i - 1; @@ -1425,3 +1786,136 @@ void q_msg(const char *file, int line, JCR *jcr, int type, utime_t mtime, const Qmsg(jcr, type, mtime, "%s", pool_buf); free_memory(pool_buf); } + + +/* not all in alphabetical order. New commands are added after existing commands with similar letters + to prevent breakage of existing user scripts. */ +struct debugtags { + const char *tag; /* command */ + int64_t bit; /* bit to set */ + const char *help; /* main purpose */ +}; + +/* setdebug tag=all,-plugin */ +static struct debugtags debug_tags[] = { + { NT_("lock"), DT_LOCK, _("Debug lock information")}, + { NT_("network"), DT_NETWORK, _("Debug network information")}, + { NT_("plugin"), DT_PLUGIN, _("Debug plugin information")}, + { NT_("volume"), DT_VOLUME, _("Debug volume information")}, + { NT_("sql"), DT_SQL, _("Debug SQL queries")}, + { NT_("bvfs"), DT_BVFS, _("Debug BVFS queries")}, + { NT_("memory"), DT_MEMORY, _("Debug memory allocation")}, + { NT_("scheduler"), DT_SCHEDULER,_("Debug scheduler information")}, + { NT_("protocol"), DT_PROTOCOL, _("Debug protocol information")}, + { NT_("snapshot"), DT_SNAPSHOT, _("Debug snapshots")}, + { NT_("asx"), DT_ASX, _("ASX personal's debugging")}, + { NT_("all"), DT_ALL, _("Debug all information")}, + { NULL, 0, NULL} +}; + +#define MAX_TAG (sizeof(debug_tags) / sizeof(struct debugtags)) + +const char *debug_get_tag(uint32_t pos, const char **desc) +{ + if (pos < MAX_TAG) { + if (desc) { + *desc = debug_tags[pos].help; + } + return debug_tags[pos].tag; + } + return NULL; +} + +/* Allow +-, */ +bool debug_find_tag(const char *tagname, bool add, int64_t *current_level) +{ + Dmsg3(010, "add=%d tag=%s level=%lld\n", add, tagname, *current_level); + if (!*tagname) { + /* Nothing in the buffer */ + return true; + } + for (int i=0; debug_tags[i].tag ; i++) { + if (strcasecmp(debug_tags[i].tag, tagname) == 0) { + if (add) { + *current_level |= debug_tags[i].bit; + } else { + *current_level &= ~(debug_tags[i].bit); + } + return true; + } + } + return false; +} + +bool debug_parse_tags(const char *options, int64_t *current_level) +{ + bool operation; /* + => true, - false */ + char *p, *t, tag[256]; + int max = sizeof(tag) - 1; + bool ret=true; + int64_t level= *current_level; + + t = tag; + *tag = 0; + operation = true; /* add by default */ + + if (!options) { + Dmsg0(100, "No options for tags\n"); + return false; + } + + for (p = (char *)options; *p ; p++) { + if (*p == ',' || *p == '+' || *p == '-' || *p == '!') { + /* finish tag keyword */ + *t = 0; + /* handle tag */ + ret &= debug_find_tag(tag, operation, &level); + + if (*p == ',') { + /* reset tag */ + t = tag; + *tag = 0; + operation = true; + + } else { + /* reset tag */ + t = tag; + *tag = 0; + operation = (*p == '+'); + } + + } else if (isalpha(*p) && (t - tag) < max) { + *t++ = *p; + + } else { /* not isalpha or too long */ + Dmsg1(010, "invalid %c\n", *p); + return false; + } + } + + /* At the end, finish the string and look it */ + *t = 0; + if (t > tag) { /* something found */ + /* handle tag */ + ret &= debug_find_tag(tag, operation, &level); + } + + *current_level = level; + return ret; +} + +int generate_daemon_event(JCR *jcr, const char *event) { return 0; } + +void setup_daemon_message_queue() +{ + static MQUEUE_ITEM *item = NULL; + daemon_msg_queue = New(dlist(item, &item->link)); +} + +void free_daemon_message_queue() +{ + P(daemon_msg_queue_mutex); + daemon_msg_queue->destroy(); + free(daemon_msg_queue); + V(daemon_msg_queue_mutex); +}