X-Git-Url: https://mattmccutchen.net/rsync/rsync.git/blobdiff_plain/18c71e96f8f9281f570046095433df38c6785fd6..e145d51ba6d4a90ab86f7f22b1c75be4e62ba916:/log.c diff --git a/log.c b/log.c index a216b6a3..87cd1d77 100644 --- a/log.c +++ b/log.c @@ -1,18 +1,18 @@ /* -*- c-file-style: "linux"; -*- - - Copyright (C) 1998-2001 by Andrew Tridgell + + Copyright (C) 1998-2001 by Andrew Tridgell Copyright (C) 2000-2001 by Martin Pool - + This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation; either version 2 of the License, or (at your option) any later version. - + 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., 675 Mass Ave, Cambridge, MA 02139, USA. @@ -20,35 +20,63 @@ /* Logging and utility functions. + tridge, May 1998 Mapping to human-readable messages added by Martin Pool , Oct 2000. */ #include "rsync.h" +extern int verbose; +extern int dry_run; +extern int am_daemon; +extern int am_server; +extern int am_sender; +extern int local_server; +extern int quiet; +extern int module_id; +extern int msg_fd_out; +extern int protocol_version; +extern int preserve_times; +extern int log_format_has_o_or_i; +extern int daemon_log_format_has_o_or_i; +extern char *auth_user; +extern char *log_format; + +static int log_initialised; static char *logfname; static FILE *logfile; -static int log_error_fd = -1; +struct stats stats; +int log_got_error = 0; struct { int code; char const *name; } const rerr_names[] = { - { RERR_SYNTAX , "syntax or usage error" }, - { RERR_PROTOCOL , "protocol incompatibility" }, - { RERR_FILESELECT , "errors selecting input/output files, dirs" }, - { RERR_UNSUPPORTED , "requested action not supported" }, - { RERR_SOCKETIO , "error in socket IO" }, - { RERR_FILEIO , "error in file IO" }, - { RERR_STREAMIO , "error in rsync protocol data stream" }, - { RERR_MESSAGEIO , "errors with program diagnostics" }, - { RERR_IPC , "error in IPC code" }, - { RERR_SIGNAL , "received SIGUSR1 or SIGINT" }, - { RERR_WAITCHILD , "some error returned by waitpid()" }, - { RERR_MALLOC , "error allocating core memory buffers" }, - { RERR_TIMEOUT , "timeout in data send/receive" }, - { 0, NULL } + { RERR_SYNTAX , "syntax or usage error" }, + { RERR_PROTOCOL , "protocol incompatibility" }, + { RERR_FILESELECT , "errors selecting input/output files, dirs" }, + { RERR_UNSUPPORTED, "requested action not supported" }, + { RERR_STARTCLIENT, "error starting client-server protocol" }, + { RERR_LOG_FAILURE, "daemon unable to append to log-file" }, + { RERR_SOCKETIO , "error in socket IO" }, + { RERR_FILEIO , "error in file IO" }, + { RERR_STREAMIO , "error in rsync protocol data stream" }, + { RERR_MESSAGEIO , "errors with program diagnostics" }, + { RERR_IPC , "error in IPC code" }, + { RERR_SIGNAL , "received SIGUSR1 or SIGINT" }, + { RERR_WAITCHILD , "some error returned by waitpid()" }, + { RERR_MALLOC , "error allocating core memory buffers" }, + { RERR_PARTIAL , "some files could not be transferred" }, + { RERR_VANISHED , "some files vanished before they could be transferred" }, + { RERR_TIMEOUT , "timeout in data send/receive" }, + { RERR_CMD_FAILED , "remote shell failed" }, + { RERR_CMD_KILLED , "remote shell killed" }, + { RERR_CMD_RUN , "remote command could not be run" }, + { RERR_CMD_NOTFOUND,"remote command not found" }, + { RERR_DEL_LIMIT , "the --max-delete limit stopped deletions" }, + { 0, NULL } }; @@ -58,12 +86,12 @@ struct { */ static char const *rerr_name(int code) { - int i; - for (i = 0; rerr_names[i].name; i++) { - if (rerr_names[i].code == code) - return rerr_names[i].name; - } - return NULL; + int i; + for (i = 0; rerr_names[i].name; i++) { + if (rerr_names[i].code == code) + return rerr_names[i].name; + } + return NULL; } @@ -72,7 +100,7 @@ static void logit(int priority, char *buf) if (logfname) { if (!logfile) log_open(); - fprintf(logfile,"%s [%d] %s", + fprintf(logfile,"%s [%d] %s", timestring(time(NULL)), (int)getpid(), buf); fflush(logfile); } else { @@ -82,16 +110,16 @@ static void logit(int priority, char *buf) void log_init(void) { - static int initialised; int options = LOG_PID; time_t t; - if (initialised) return; - initialised = 1; + if (log_initialised) + return; + log_initialised = 1; /* this looks pointless, but it is needed in order for the - C library on some systems to fetch the timezone info - before the chroot */ + * C library on some systems to fetch the timezone info + * before the chroot */ t = time(NULL); localtime(&t); @@ -120,17 +148,22 @@ void log_init(void) #endif } -void log_open() +void log_open(void) { if (logfname && !logfile) { extern int orig_umask; int old_umask = umask(022 | orig_umask); logfile = fopen(logfname, "a"); umask(old_umask); + if (!logfile) { + am_daemon = 0; /* avoid trying to log again */ + rsyserr(FERROR, errno, "fopen() of log-file failed"); + exit_cleanup(RERR_LOG_FAILURE); + } } } -void log_close() +void log_close(void) { if (logfile) { fclose(logfile); @@ -138,76 +171,74 @@ void log_close() } } -/* setup the error file descriptor - used when we are a server - that is receiving files */ -void set_error_fd(int fd) -{ - log_error_fd = fd; -} - /* this is the underlying (unformatted) rsync debugging function. Call - it with FINFO, FERROR or FLOG */ + * it with FINFO, FERROR or FLOG */ void rwrite(enum logcode code, char *buf, int len) { - FILE *f=NULL; - extern int am_daemon; - extern int am_server; - extern int quiet; + FILE *f = NULL; /* recursion can happen with certain fatal conditions */ - if (quiet && code == FINFO) return; + if (quiet && code == FINFO) + return; - if (len < 0) exit_cleanup(RERR_MESSAGEIO); + if (len < 0) + exit_cleanup(RERR_MESSAGEIO); buf[len] = 0; - if (code == FLOG) { - if (am_daemon) logit(LOG_INFO, buf); + if (am_server && msg_fd_out >= 0) { + /* Pass the message to our sibling. */ + send_msg((enum msgcode)code, buf, len); return; } - /* first try to pass it off the our sibling */ - if (am_server && io_error_write(log_error_fd, code, buf, len)) { - return; - } + if (code == FCLIENT) + code = FINFO; + else if (am_daemon) { + static int in_block; + char msg[2048]; + int priority = code == FERROR ? LOG_WARNING : LOG_INFO; - /* if that fails, try to pass it to the other end */ - if (am_server && io_multiplex_write(code, buf, len)) { + if (in_block) + return; + in_block = 1; + if (!log_initialised) + log_init(); + strlcpy(msg, buf, MIN((int)sizeof msg, len + 1)); + logit(priority, msg); + in_block = 0; + + if (code == FLOG || !am_server) + return; + } else if (code == FLOG) return; - } - if (am_daemon) { - static int depth; - int priority = LOG_INFO; - if (code == FERROR) priority = LOG_WARNING; - - if (depth) return; - - depth++; - - log_init(); - logit(priority, buf); - - depth--; - return; + if (am_server) { + /* Pass the message to the non-server side. */ + if (io_multiplex_write((enum msgcode)code, buf, len)) + return; + if (am_daemon) { + /* TODO: can we send the error to the user somehow? */ + return; + } } if (code == FERROR) { + log_got_error = 1; f = stderr; - } + } - if (code == FINFO) { - if (am_server) - f = stderr; - else - f = stdout; - } + if (code == FINFO) + f = am_server ? stderr : stdout; - if (!f) exit_cleanup(RERR_MESSAGEIO); + if (!f) + exit_cleanup(RERR_MESSAGEIO); - if (fwrite(buf, len, 1, f) != 1) exit_cleanup(RERR_MESSAGEIO); + if (fwrite(buf, len, 1, f) != 1) + exit_cleanup(RERR_MESSAGEIO); - if (buf[len-1] == '\r' || buf[len-1] == '\n') fflush(f); + if (buf[len-1] == '\r' || buf[len-1] == '\n') + fflush(f); } @@ -215,15 +246,39 @@ void rwrite(enum logcode code, char *buf, int len) * FLOG. */ void rprintf(enum logcode code, const char *format, ...) { - va_list ap; - char buf[1024]; - int len; + va_list ap; + char buf[MAXPATHLEN+512]; + size_t len; va_start(ap, format); - len = vslprintf(buf, sizeof(buf), format, ap); + len = vsnprintf(buf, sizeof buf, format, ap); va_end(ap); - if (len > sizeof(buf)-1) exit_cleanup(RERR_MESSAGEIO); + /* Deal with buffer overruns. Instead of panicking, just + * truncate the resulting string. (Note that configure ensures + * that we have a vsnprintf() that doesn't ever return -1.) */ + if (len > sizeof buf - 1) { + const char ellipsis[] = "[...]"; + + /* Reset length, and zero-terminate the end of our buffer */ + len = sizeof buf - 1; + buf[len] = '\0'; + + /* Copy the ellipsis to the end of the string, but give + * us one extra character: + * + * v--- null byte at buf[sizeof buf - 1] + * abcdefghij0 + * -> abcd[...]00 <-- now two null bytes at end + * + * If the input format string has a trailing newline, + * we copy it into that extra null; if it doesn't, well, + * all we lose is one byte. */ + strncpy(buf+len-sizeof ellipsis, ellipsis, sizeof ellipsis); + if (format[strlen(format)-1] == '\n') { + buf[len-1] = '\n'; + } + } rwrite(code, buf, len); } @@ -239,28 +294,23 @@ void rprintf(enum logcode code, const char *format, ...) * message catalog we need to call it once before chroot-ing. */ void rsyserr(enum logcode code, int errcode, const char *format, ...) { - va_list ap; - char buf[1024]; - int len, sys_len; - char *sysmsg; + va_list ap; + char buf[MAXPATHLEN+512]; + size_t len; + + strcpy(buf, RSYNC_NAME ": "); + len = (sizeof RSYNC_NAME ": ") - 1; va_start(ap, format); - len = vslprintf(buf, sizeof(buf), format, ap); + len += vsnprintf(buf + len, sizeof buf - len, format, ap); va_end(ap); - if (len > sizeof(buf)-1) exit_cleanup(RERR_MESSAGEIO); - - sysmsg = strerror(errcode); - sys_len = strlen(sysmsg); - if (len + 3 + sys_len > sizeof(buf) - 1) - exit_cleanup(RERR_MESSAGEIO); - - strcpy(buf + len, ": "); - len += 2; - strcpy(buf + len, sysmsg); - len += sys_len; - strcpy(buf + len, "\n"); - len++; + if (len < sizeof buf) { + len += snprintf(buf + len, sizeof buf - len, + ": %s (%d)\n", strerror(errcode), errcode); + } + if (len >= sizeof buf) + exit_cleanup(RERR_MESSAGEIO); rwrite(code, buf, len); } @@ -270,7 +320,6 @@ void rsyserr(enum logcode code, int errcode, const char *format, ...) void rflush(enum logcode code) { FILE *f = NULL; - extern int am_daemon; if (am_daemon) { return; @@ -278,19 +327,18 @@ void rflush(enum logcode code) if (code == FLOG) { return; - } + } if (code == FERROR) { f = stderr; - } + } if (code == FINFO) { - extern int am_server; - if (am_server) + if (am_server) f = stderr; else f = stdout; - } + } if (!f) exit_cleanup(RERR_MESSAGEIO); fflush(f); @@ -299,129 +347,248 @@ void rflush(enum logcode code) /* a generic logging routine for send/recv, with parameter - substitiution */ -static void log_formatted(enum logcode code, - char *format, char *op, struct file_struct *file, - struct stats *initial_stats) + * substitiution */ +static void log_formatted(enum logcode code, char *format, char *op, + struct file_struct *file, struct stats *initial_stats, + int iflags, char *hlink) { - extern int module_id; - extern char *auth_user; - char buf[1024]; - char buf2[1024]; + char buf[MAXPATHLEN+1024], buf2[MAXPATHLEN], fmt[32]; char *p, *s, *n; - int l; - extern struct stats stats; - extern int am_sender; - extern int am_daemon; + size_t len, total; int64 b; - strlcpy(buf, format, sizeof(buf)); + *fmt = '%'; + + /* We expand % codes one by one in place in buf. We don't + * copy in the terminating nul of the inserted strings, but + * rather keep going until we reach the nul of the format. */ + total = strlcpy(buf, format, sizeof buf); - for (s=&buf[0]; - s && (p=strchr(s,'%')); ) { + for (p = buf; (p = strchr(p, '%')) != NULL && p[1]; ) { + s = p++; + n = fmt + 1; + if (*p == '-') + *n++ = *p++; + while (isdigit(*(uchar*)p) && n - fmt < (int)(sizeof fmt) - 8) + *n++ = *p++; + if (!*p) + break; + *n = '\0'; n = NULL; - s = p + 1; - switch (p[1]) { + switch (*p++) { case 'h': if (am_daemon) n = client_name(0); break; case 'a': if (am_daemon) n = client_addr(0); break; - case 'l': - slprintf(buf2,sizeof(buf2),"%.0f", - (double)file->length); + case 'l': + strlcat(fmt, ".0f", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, + (double)file->length); n = buf2; break; - case 'p': - slprintf(buf2,sizeof(buf2),"%d", - (int)getpid()); + case 'p': + strlcat(fmt, "d", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, + (int)getpid()); n = buf2; break; case 'o': n = op; break; - case 'f': - slprintf(buf2, sizeof(buf2), "%s/%s", - file->basedir?file->basedir:"", - f_name(file)); - clean_fname(buf2); - n = buf2; - if (*n == '/') n++; + case 'f': + n = safe_fname(f_name(file)); + if (am_sender && file->dir.root) { + pathjoin(buf2, sizeof buf2, + file->dir.root, n); + /* The buffer from safe_fname() has more + * room than MAXPATHLEN, so this is safe. */ + if (fmt[1]) + strcpy(n, buf2); + else + n = buf2; + } + clean_fname(n, 0); + if (*n == '/') + n++; + break; + case 'n': + n = safe_fname(f_name(file)); + if (S_ISDIR(file->mode)) { + /* The buffer from safe_fname() has more + * room than MAXPATHLEN, so this is safe. */ + strcat(n, "/"); + } + break; + case 'L': + if (hlink && *hlink) { + snprintf(buf2, sizeof buf2, " => %s", + safe_fname(hlink)); + n = buf2; + } else if (S_ISLNK(file->mode) && file->u.link) { + snprintf(buf2, sizeof buf2, " -> %s", + safe_fname(file->u.link)); + n = buf2; + } else + n = ""; break; case 'm': n = lp_name(module_id); break; case 't': n = timestring(time(NULL)); break; case 'P': n = lp_path(module_id); break; case 'u': n = auth_user; break; - case 'b': + case 'b': + strlcat(fmt, ".0f", sizeof fmt); if (am_sender) { - b = stats.total_written - + b = stats.total_written - initial_stats->total_written; } else { - b = stats.total_read - + b = stats.total_read - initial_stats->total_read; } - slprintf(buf2,sizeof(buf2),"%.0f", (double)b); + snprintf(buf2, sizeof buf2, fmt, (double)b); n = buf2; break; - case 'c': + case 'c': + strlcat(fmt, ".0f", sizeof fmt); if (!am_sender) { - b = stats.total_written - + b = stats.total_written - initial_stats->total_written; } else { - b = stats.total_read - + b = stats.total_read - initial_stats->total_read; } - slprintf(buf2,sizeof(buf2),"%.0f", (double)b); + snprintf(buf2, sizeof buf2, fmt, (double)b); n = buf2; break; + case 'i': + if (iflags & ITEM_DELETED) { + n = "*deleting"; + break; + } + n = buf2 + MAXPATHLEN - 32; + n[0] = iflags & ITEM_LOCAL_CHANGE + ? iflags & ITEM_XNAME_FOLLOWS ? 'h' : 'c' + : !(iflags & ITEM_TRANSFER) ? '.' + : !local_server && *op == 's' ? '<' : '>'; + n[1] = S_ISDIR(file->mode) ? 'd' + : IS_DEVICE(file->mode) ? 'D' + : S_ISLNK(file->mode) ? 'L' : 'f'; + n[2] = !(iflags & ITEM_REPORT_CHECKSUM) ? '.' : 'c'; + n[3] = !(iflags & ITEM_REPORT_SIZE) ? '.' : 's'; + n[4] = !(iflags & ITEM_REPORT_TIME) ? '.' + : !preserve_times || IS_DEVICE(file->mode) + || S_ISLNK(file->mode) ? 'T' : 't'; + n[5] = !(iflags & ITEM_REPORT_PERMS) ? '.' : 'p'; + n[6] = !(iflags & ITEM_REPORT_OWNER) ? '.' : 'o'; + n[7] = !(iflags & ITEM_REPORT_GROUP) ? '.' : 'g'; + n[8] = !(iflags & ITEM_REPORT_XATTRS) ? '.' : 'a'; + n[9] = '\0'; + + if (iflags & (ITEM_IS_NEW|ITEM_MISSING_DATA)) { + char ch = iflags & ITEM_IS_NEW ? '+' : '?'; + int i; + for (i = 2; n[i]; i++) + n[i] = ch; + } else if (!(iflags & (ITEM_TRANSFER|ITEM_LOCAL_CHANGE))) { + int i; + for (i = 2; n[i]; i++) { + if (n[i] != '.') + break; + } + if (!n[i]) { + for (i = 2; n[i]; i++) + n[i] = ' '; + } + } + break; } - if (!n) continue; + /* "n" is the string to be inserted in place of this % code. */ + if (!n) + continue; + if (n != buf2 && fmt[1]) { + strlcat(fmt, "s", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, n); + n = buf2; + } + len = strlen(n); - l = strlen(n); + /* Subtract the length of the escape from the string's size. */ + total -= p - s; - if ((l-1) + ((int)(s - &buf[0])) > sizeof(buf)) { - rprintf(FERROR,"buffer overflow expanding %%%c - exiting\n", - p[0]); + if (len + total >= sizeof buf) { + rprintf(FERROR, + "buffer overflow expanding %%%c -- exiting\n", + p[-1]); exit_cleanup(RERR_MESSAGEIO); } - if (l != 2) { - memmove(s+(l-1), s+1, strlen(s+1)+1); - } - memcpy(p, n, l); + /* Shuffle the rest of the string along to make space for n */ + if (len != (size_t)(p - s)) + memmove(s + len, p, total - (s - buf) + 1); + total += len; - s = p+l; + /* Insert the contents of string "n", but NOT its null. */ + if (len) + memcpy(s, n, len); + + /* Skip over inserted string; continue looking */ + p = s + len; } - rprintf(code,"%s\n", buf); + rprintf(code, "%s\n", buf); } -/* log the outgoing transfer of a file */ -void log_send(struct file_struct *file, struct stats *initial_stats) +/* log the transfer of a file */ +void log_item(struct file_struct *file, struct stats *initial_stats, + int iflags, char *hlink) { - extern int module_id; - extern int am_server; - extern char *log_format; + char *s_or_r = am_sender ? "send" : "recv"; if (lp_transfer_logging(module_id)) { - log_formatted(FLOG, lp_log_format(module_id), "send", file, initial_stats); + log_formatted(FLOG, lp_log_format(module_id), s_or_r, + file, initial_stats, iflags, hlink); } else if (log_format && !am_server) { - log_formatted(FINFO, log_format, "send", file, initial_stats); + log_formatted(FINFO, log_format, s_or_r, + file, initial_stats, iflags, hlink); } } -/* log the incoming transfer of a file */ -void log_recv(struct file_struct *file, struct stats *initial_stats) +void maybe_log_item(struct file_struct *file, int iflags, int itemizing, + char *buf) { - extern int module_id; - extern int am_server; - extern char *log_format; + int see_item = itemizing && (iflags || verbose > 1); + if (am_server) { + if (am_daemon && !dry_run && see_item) + log_item(file, &stats, iflags, buf); + } else if (see_item || iflags & ITEM_LOCAL_CHANGE || *buf + || (S_ISDIR(file->mode) && iflags & SIGNIFICANT_ITEM_FLAGS)) + log_item(file, &stats, iflags, buf); +} - if (lp_transfer_logging(module_id)) { - log_formatted(FLOG, lp_log_format(module_id), "recv", file, initial_stats); - } else if (log_format && !am_server) { - log_formatted(FINFO, log_format, "recv", file, initial_stats); +void log_delete(char *fname, int mode) +{ + static struct file_struct file; + int len = strlen(fname); + char *fmt; + + file.mode = mode; + file.basename = fname; + + if (!verbose && !log_format) + ; + else if (am_server && protocol_version >= 29 && len < MAXPATHLEN) { + if (S_ISDIR(mode)) + len++; /* directories include trailing null */ + send_msg(MSG_DELETED, fname, len); + } else { + fmt = log_format_has_o_or_i ? log_format : "deleting %n"; + log_formatted(FCLIENT, fmt, "del.", &file, &stats, + ITEM_DELETED, NULL); } -} + if (!am_daemon || dry_run || !lp_transfer_logging(module_id)) + return; + fmt = daemon_log_format_has_o_or_i ? lp_log_format(module_id) : "deleting %n"; + log_formatted(FLOG, fmt, "del.", &file, &stats, ITEM_DELETED, NULL); +} /* @@ -433,37 +600,24 @@ void log_recv(struct file_struct *file, struct stats *initial_stats) void log_exit(int code, const char *file, int line) { if (code == 0) { - extern struct stats stats; - rprintf(FLOG,"wrote %.0f bytes read %.0f bytes total size %.0f\n", + rprintf(FLOG,"sent %.0f bytes received %.0f bytes total size %.0f\n", (double)stats.total_written, (double)stats.total_read, (double)stats.total_size); } else { - const char *name; - - name = rerr_name(code); - if (!name) - name = "unexplained error"; - - rprintf(FLOG,"transfer interrupted: %s (code %d) at %s(%d)\n", - name, code, file, line); + const char *name; + + name = rerr_name(code); + if (!name) + name = "unexplained error"; + + /* VANISHED is not an error, only a warning */ + if (code == RERR_VANISHED) { + rprintf(FINFO, "rsync warning: %s (code %d) at %s(%d)\n", + name, code, file, line); + } else { + rprintf(FERROR, "rsync error: %s (code %d) at %s(%d)\n", + name, code, file, line); + } } } - - - - -/* log the incoming transfer of a file for interactive use, this - will be called at the end where the client was run - - it i called when a file starts to be transferred -*/ -void log_transfer(struct file_struct *file, const char *fname) -{ - extern int verbose; - - if (!verbose) return; - - rprintf(FINFO,"%s\n", fname); -} -