X-Git-Url: https://mattmccutchen.net/rsync/rsync.git/blobdiff_plain/19bc826d8b16a750d5826998d739692928a45103..6cbde57d8810d9889b650c49456fa843f76257c7:/log.c diff --git a/log.c b/log.c index 70aa96df..41d847f8 100644 --- a/log.c +++ b/log.c @@ -27,19 +27,25 @@ */ #include "rsync.h" -extern int itemize_changes; +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_i; +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 int logfile_was_closed; static char *logfname; static FILE *logfile; struct stats stats; @@ -60,16 +66,20 @@ struct { { 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_CRASHED , "sibling process crashed" }, + { RERR_TERMINATED , "sibling process terminated abnormally" }, + { RERR_SIGNAL1 , "received SIGUSR1" }, + { RERR_SIGNAL , "received SIGINT, SIGTERM, or SIGHUP" }, + { RERR_WAITCHILD , "waitpid() failed" }, { 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_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 } }; @@ -88,34 +98,12 @@ static char const *rerr_name(int code) return NULL; } -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_FILESELECT); - } - } -} - -void log_close(void) -{ - if (logfile) { - fclose(logfile); - logfile = NULL; - } -} static void logit(int priority, char *buf) { - if (logfname) { - if (!logfile) - log_open(); + if (logfile_was_closed) + logfile_reopen(); + if (logfile) { fprintf(logfile,"%s [%d] %s", timestring(time(NULL)), (int)getpid(), buf); fflush(logfile); @@ -124,9 +112,48 @@ static void logit(int priority, char *buf) } } -void log_init(void) +static void syslog_init() { + static int been_here = 0; int options = LOG_PID; + + if (been_here) + return; + been_here = 1; + +#ifdef LOG_NDELAY + options |= LOG_NDELAY; +#endif + +#ifdef LOG_DAEMON + openlog("rsyncd", options, lp_syslog_facility()); +#else + openlog("rsyncd", options); +#endif + +#ifndef LOG_NDELAY + logit(LOG_INFO, "rsyncd started\n"); +#endif +} + +static void logfile_open(void) +{ + extern int orig_umask; + int old_umask = umask(022 | orig_umask); + logfile = fopen(logfname, "a"); + umask(old_umask); + if (!logfile) { + int fopen_errno = errno; + /* Rsync falls back to using syslog on failure. */ + syslog_init(); + rsyserr(FERROR, fopen_errno, + "failed to open log-file %s", logfname); + rprintf(FINFO, "Ignoring \"log file\" setting.\n"); + } +} + +void log_init(void) +{ time_t t; if (log_initialised) @@ -141,27 +168,27 @@ void log_init(void) /* optionally use a log file instead of syslog */ logfname = lp_log_file(); - if (logfname) { - if (*logfname) { - log_open(); - return; - } - logfname = NULL; - } - -#ifdef LOG_NDELAY - options |= LOG_NDELAY; -#endif + if (logfname && *logfname) + logfile_open(); + else + syslog_init(); +} -#ifdef LOG_DAEMON - openlog("rsyncd", options, lp_syslog_facility()); -#else - openlog("rsyncd", options); -#endif +void logfile_close(void) +{ + if (logfile) { + logfile_was_closed = 1; + fclose(logfile); + logfile = NULL; + } +} -#ifndef LOG_NDELAY - logit(LOG_INFO,"rsyncd started\n"); -#endif +void logfile_reopen(void) +{ + if (logfile_was_closed) { + logfile_was_closed = 0; + logfile_open(); + } } /* this is the underlying (unformatted) rsync debugging function. Call @@ -185,7 +212,9 @@ void rwrite(enum logcode code, char *buf, int len) return; } - if (am_daemon) { + if (code == FCLIENT) + code = FINFO; + else if (am_daemon) { static int in_block; char msg[2048]; int priority = code == FERROR ? LOG_WARNING : LOG_INFO; @@ -231,14 +260,14 @@ void rwrite(enum logcode code, char *buf, int len) if (buf[len-1] == '\r' || buf[len-1] == '\n') fflush(f); } - + /* This is the rsync debugging function. Call it with FINFO, FERROR or * FLOG. */ void rprintf(enum logcode code, const char *format, ...) { va_list ap; - char buf[MAXPATHLEN+512]; + char buf[BIGPATHBUFLEN]; size_t len; va_start(ap, format); @@ -249,7 +278,7 @@ void rprintf(enum logcode code, const char *format, ...) * 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[] = "[...]"; + static const char ellipsis[] = "[...]"; /* Reset length, and zero-terminate the end of our buffer */ len = sizeof buf - 1; @@ -265,7 +294,7 @@ void rprintf(enum logcode code, const char *format, ...) * 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); + memcpy(buf+len-sizeof ellipsis, ellipsis, sizeof ellipsis); if (format[strlen(format)-1] == '\n') { buf[len-1] = '\n'; } @@ -286,7 +315,7 @@ void rprintf(enum logcode code, const char *format, ...) void rsyserr(enum logcode code, int errcode, const char *format, ...) { va_list ap; - char buf[MAXPATHLEN+512]; + char buf[BIGPATHBUFLEN]; size_t len; strcpy(buf, RSYNC_NAME ": "); @@ -311,7 +340,7 @@ void rsyserr(enum logcode code, int errcode, const char *format, ...) void rflush(enum logcode code) { FILE *f = NULL; - + if (am_daemon) { return; } @@ -339,66 +368,113 @@ 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, int iflags) +static void log_formatted(enum logcode code, char *format, char *op, + struct file_struct *file, struct stats *initial_stats, + int iflags, char *hlink) { - char buf[MAXPATHLEN+1024]; - char buf2[MAXPATHLEN]; - char *p, *n; + char buf[MAXPATHLEN+1024], buf2[MAXPATHLEN], fmt[32]; + char *p, *s, *n; size_t len, total; int64 b; + *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. */ + * copy in the terminating null of the inserted strings, but + * rather keep going until we reach the null of the format. */ total = strlcpy(buf, format, sizeof buf); - - for (p = buf; (p = strchr(p, '%')) != NULL && p[1]; ) { + if (total > MAXPATHLEN) { + rprintf(FERROR, "log-format string is WAY too long!\n"); + exit_cleanup(RERR_MESSAGEIO); + } + buf[total++] = '\n'; + buf[total] = '\0'; + + for (p = buf; (p = strchr(p, '%')) != NULL; ) { + 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; - switch (p[1]) { - case 'h': if (am_daemon) n = client_name(0); break; - case 'a': if (am_daemon) n = client_addr(0); break; + switch (*p) { + case 'h': + if (am_daemon) + n = client_name(0); + break; + case 'a': + if (am_daemon) + n = client_addr(0); + break; case 'l': - snprintf(buf2, sizeof buf2, "%.0f", + strlcat(fmt, ".0f", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, (double)file->length); n = buf2; break; case 'p': - snprintf(buf2, sizeof buf2, "%d", - (int)getpid()); + strlcat(fmt, "ld", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, + (long)getpid()); n = buf2; break; - case 'o': n = op; break; + case 'o': + n = op; + break; case 'f': - pathjoin(buf2, sizeof buf2, - am_sender && file->dir.root ? file->dir.root : "", - safe_fname(f_name(file))); - clean_fname(buf2, 0); - n = buf2; - if (*n == '/') n++; + n = f_name(file); + if (am_sender && file->dir.root) { + pathjoin(buf2, sizeof buf2, + file->dir.root, n); + clean_fname(buf2, 0); + if (fmt[1]) + strlcpy(n, buf2, MAXPATHLEN); + else + n = buf2; + } else + clean_fname(n, 0); + if (*n == '/') + n++; break; case 'n': - n = (char*)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, "/"); - } + n = f_name(file); + if (S_ISDIR(file->mode)) + strlcat(n, "/", MAXPATHLEN); break; case 'L': - if (S_ISLNK(file->mode) && file->u.link) { - snprintf(buf2, sizeof buf2, " -> %s", - safe_fname(file->u.link)); - n = buf2; - } else + if (hlink && *hlink) { + n = hlink; + strcpy(buf2, " => "); + } else if (S_ISLNK(file->mode) && file->u.link) { + n = file->u.link; + strcpy(buf2, " -> "); + } else { n = ""; + if (!fmt[1]) + break; + strcpy(buf2, " "); + } + strlcat(fmt, "s", sizeof fmt); + snprintf(buf2 + 4, sizeof buf2 - 4, fmt, n); + n = buf2; + 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 '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': if (am_sender) { b = stats.total_written - @@ -407,7 +483,8 @@ static void log_formatted(enum logcode code, b = stats.total_read - initial_stats->total_read; } - snprintf(buf2, sizeof buf2, "%.0f", (double)b); + strlcat(fmt, ".0f", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, (double)b); n = buf2; break; case 'c': @@ -418,17 +495,20 @@ static void log_formatted(enum logcode code, b = stats.total_read - initial_stats->total_read; } - snprintf(buf2, sizeof buf2, "%.0f", (double)b); + strlcat(fmt, ".0f", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, (double)b); n = buf2; break; case 'i': if (iflags & ITEM_DELETED) { - n = "deleting"; + n = "*deleting"; break; } - n = buf2; - n[0] = !(iflags & ITEM_UPDATING) ? '.' - : *op == 's' ? '>' : '<'; + 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'; @@ -440,14 +520,16 @@ static void log_formatted(enum logcode code, n[5] = !(iflags & ITEM_REPORT_PERMS) ? '.' : 'p'; n[6] = !(iflags & ITEM_REPORT_OWNER) ? '.' : 'o'; n[7] = !(iflags & ITEM_REPORT_GROUP) ? '.' : 'g'; - n[8] = '\0'; + 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_UPDATING)) { + } else if (n[0] == '.' || n[0] == 'h' + || (n[0] == 'c' && n[1] == 'f')) { int i; for (i = 2; n[i]; i++) { if (n[i] != '.') @@ -456,23 +538,25 @@ static void log_formatted(enum logcode code, if (!n[i]) { for (i = 2; n[i]; i++) n[i] = ' '; - n[0] = '='; } } break; } - /* n is the string to be inserted in place of this % - * code; len is its length not including the trailing - * NUL */ - if (!n) { - p += 2; + /* "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); - if (len + total - 2 >= sizeof buf) { + /* Subtract the length of the escape from the string's size. */ + total -= p - s + 1; + + if (len + total >= (size_t)sizeof buf) { rprintf(FERROR, "buffer overflow expanding %%%c -- exiting\n", p[0]); @@ -480,70 +564,99 @@ static void log_formatted(enum logcode code, } /* Shuffle the rest of the string along to make space for n */ - if (len != 2) - memmove(p + len, p + 2, total - (p + 2 - buf) + 1); - total += len - 2; + if (len != (size_t)(p - s + 1)) + memmove(s + len, p + 1, total - (s - buf) + 1); + total += len; - /* Insert the contents of string "n", but NOT its nul. */ + /* Insert the contents of string "n", but NOT its null. */ if (len) - memcpy(p, n, len); + memcpy(s, n, len); /* Skip over inserted string; continue looking */ - p += len; + p = s + len; } - rprintf(code, "%s\n", buf); + rwrite(code, buf, total); } -/* log the outgoing transfer of a file */ -void log_send(struct file_struct *file, struct stats *initial_stats, int iflags) +/* Return 1 if the format escape is in the log-format string (e.g. look for + * the 'b' in the "%9b" format escape). */ +int log_format_has(const char *format, char esc) { - if (lp_transfer_logging(module_id)) { - log_formatted(FLOG, lp_log_format(module_id), "send", - file, initial_stats, iflags); - } else if (log_format && !am_server) { - log_formatted(FINFO, log_format, "send", - file, initial_stats, iflags); + const char *p; + + if (!format) + return 0; + + for (p = format; (p = strchr(p, '%')) != NULL; ) { + if (*++p == '-') + p++; + while (isdigit(*(uchar*)p)) + p++; + if (!*p) + break; + if (*p == esc) + return 1; } + return 0; } -/* log the incoming transfer of a file */ -void log_recv(struct file_struct *file, struct stats *initial_stats, int iflags) +/* log the transfer of a file */ +void log_item(struct file_struct *file, struct stats *initial_stats, + int iflags, char *hlink) { + char *s_or_r = am_sender ? "send" : "recv"; + if (lp_transfer_logging(module_id)) { - log_formatted(FLOG, lp_log_format(module_id), "recv", - file, initial_stats, iflags); + 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, "recv", - file, initial_stats, iflags); + log_formatted(FINFO, log_format, s_or_r, + file, initial_stats, iflags, hlink); } } +void maybe_log_item(struct file_struct *file, int iflags, int itemizing, + char *buf) +{ + int significant_flags = iflags & SIGNIFICANT_ITEM_FLAGS; + int see_item = itemizing && (significant_flags || *buf + || (verbose > 1 && log_format_has_i)); + int local_change = iflags & ITEM_LOCAL_CHANGE && significant_flags; + if (am_server) { + if (am_daemon && !dry_run && see_item) + log_item(file, &stats, iflags, buf); + } else if (see_item || local_change || *buf + || (S_ISDIR(file->mode) && significant_flags)) + log_item(file, &stats, iflags, buf); +} void log_delete(char *fname, int mode) { static struct file_struct file; int len = strlen(fname); - enum logcode code; char *fmt; file.mode = mode; file.basename = fname; - if (am_server && protocol_version >= 29 && len < MAXPATHLEN) { + 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); - if (!am_daemon) - return; - fmt = lp_log_format(module_id); - code = FLOG; } else { - fmt = log_format && itemize_changes ? log_format : "%i %n"; - code = FINFO; + fmt = log_format_has_o_or_i ? log_format : "deleting %n"; + log_formatted(FCLIENT, fmt, "del.", &file, &stats, + ITEM_DELETED, NULL); } - log_formatted(code, fmt, "del.", &file, &stats, ITEM_DELETED); + 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); } @@ -556,7 +669,7 @@ void log_delete(char *fname, int mode) void log_exit(int code, const char *file, int line) { if (code == 0) { - 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);