--- embedaddon/rsync/log.c 2012/02/17 15:09:30 1.1.1.1 +++ embedaddon/rsync/log.c 2021/03/17 00:32:36 1.1.1.4 @@ -3,7 +3,7 @@ * * Copyright (C) 1998-2001 Andrew Tridgell * Copyright (C) 2000-2001 Martin Pool - * Copyright (C) 2003-2009 Wayne Davison + * Copyright (C) 2003-2020 Wayne Davison * * 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 @@ -20,9 +20,9 @@ */ #include "rsync.h" -#include "ifuncs.h" +#include "itypes.h" +#include "inums.h" -extern int verbose; extern int dry_run; extern int am_daemon; extern int am_server; @@ -31,16 +31,20 @@ extern int am_generator; extern int local_server; extern int quiet; extern int module_id; -extern int msg_fd_out; extern int allow_8bit_chars; extern int protocol_version; +extern int always_checksum; extern int preserve_times; -extern int progress_is_active; +extern int msgs2stderr; +extern int xfersum_type; +extern int checksum_type; extern int stdout_format_has_i; extern int stdout_format_has_o_or_i; extern int logfile_format_has_i; extern int logfile_format_has_o_or_i; extern int receiver_symlink_times; +extern int64 total_data_written; +extern int64 total_data_read; extern mode_t orig_umask; extern char *auth_user; extern char *stdout_format; @@ -55,6 +59,8 @@ extern iconv_t ic_recv; extern char curr_dir[MAXPATHLEN]; extern char *full_module_path; extern unsigned int module_dirlen; +extern char sender_file_sum[MAX_DIGEST_LEN]; +extern const char undetermined_hostname[]; static int log_initialised; static int logfile_was_closed; @@ -62,10 +68,15 @@ static FILE *logfile_fp; struct stats stats; int got_xfer_error = 0; +int output_needs_newline = 0; +int send_msgs_to_gen = 0; +static int64 initial_data_written; +static int64 initial_data_read; + struct { - int code; - char const *name; + int code; + char const *name; } const rerr_names[] = { { RERR_SYNTAX , "syntax or usage error" }, { RERR_PROTOCOL , "protocol incompatibility" }, @@ -81,17 +92,18 @@ struct { { RERR_TERMINATED , "sibling process terminated abnormally" }, { RERR_SIGNAL1 , "received SIGUSR1" }, { RERR_SIGNAL , "received SIGINT, SIGTERM, or SIGHUP" }, + { RERR_WECRASHED , "rsync caught a CRASH-causing signal" }, { RERR_WAITCHILD , "waitpid() failed" }, { RERR_MALLOC , "error allocating core memory buffers" }, { RERR_PARTIAL , "some files/attrs were not transferred (see previous errors)" }, { RERR_VANISHED , "some files vanished before they could be transferred" }, + { RERR_DEL_LIMIT , "the --max-delete limit stopped deletions" }, { RERR_TIMEOUT , "timeout in data send/receive" }, { RERR_CONTIMEOUT , "timeout waiting for daemon connection" }, { 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 } }; @@ -113,8 +125,7 @@ static void logit(int priority, const char *buf) if (logfile_was_closed) logfile_reopen(); if (logfile_fp) { - fprintf(logfile_fp, "%s [%d] %s", - timestring(time(NULL)), (int)getpid(), buf); + fprintf(logfile_fp, "%s [%d] %s", timestring(time(NULL)), (int)getpid(), buf); fflush(logfile_fp); } else { syslog(priority, "%s", buf); @@ -123,21 +134,16 @@ static void logit(int priority, const char *buf) 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(module_id)); + openlog(lp_syslog_tag(module_id), options, lp_syslog_facility(module_id)); #else - openlog("rsyncd", options); + openlog(lp_syslog_tag(module_id), options); #endif #ifndef LOG_NDELAY @@ -157,14 +163,16 @@ static void logfile_open(void) rsyserr(FERROR, fopen_errno, "failed to open log-file %s", logfile_name); rprintf(FINFO, "Ignoring \"log file\" setting.\n"); + logfile_name = ""; } } void log_init(int restart) { if (log_initialised) { - if (!restart) + if (!restart) /* Note: a restart only happens with am_daemon */ return; + assert(logfile_name); /* all am_daemon procs got at least an empty string */ if (strcmp(logfile_name, lp_log_file(module_id)) != 0) { if (logfile_fp) { fclose(logfile_fp); @@ -174,7 +182,8 @@ void log_init(int restart) logfile_name = NULL; } else if (*logfile_name) return; /* unchanged, non-empty "log file" names */ - else if (lp_syslog_facility(-1) != lp_syslog_facility(module_id)) + else if (lp_syslog_facility(-1) != lp_syslog_facility(module_id) + || strcmp(lp_syslog_tag(-1), lp_syslog_tag(module_id)) != 0) closelog(); else return; /* unchanged syslog settings */ @@ -196,6 +205,7 @@ void log_init(int restart) syslog_init(); } +/* Note that this close & reopen idiom intentionally ignores syslog logging. */ void logfile_close(void) { if (logfile_fp) { @@ -213,25 +223,26 @@ void logfile_reopen(void) } } -static void filtered_fwrite(FILE *f, const char *buf, int len, int use_isprint) +static void filtered_fwrite(FILE *f, const char *in_buf, int in_len, int use_isprint, char end_char) { - const char *s, *end = buf + len; - for (s = buf; s < end; s++) { - if ((s < end - 4 - && *s == '\\' && s[1] == '#' - && isDigit(s + 2) - && isDigit(s + 3) - && isDigit(s + 4)) - || (*s != '\t' - && ((use_isprint && !isPrint(s)) - || *(uchar*)s < ' '))) { - if (s != buf && fwrite(buf, s - buf, 1, f) != 1) + char outbuf[1024], *ob = outbuf; + const char *end = in_buf + in_len; + while (in_buf < end) { + if (ob - outbuf >= (int)sizeof outbuf - 10) { + if (fwrite(outbuf, ob - outbuf, 1, f) != 1) exit_cleanup(RERR_MESSAGEIO); - fprintf(f, "\\#%03o", *(uchar*)s); - buf = s + 1; + ob = outbuf; } + if ((in_buf < end - 4 && *in_buf == '\\' && in_buf[1] == '#' + && isDigit(in_buf + 2) && isDigit(in_buf + 3) && isDigit(in_buf + 4)) + || (*in_buf != '\t' && ((use_isprint && !isPrint(in_buf)) || *(uchar*)in_buf < ' '))) + ob += snprintf(ob, 6, "\\#%03o", *(uchar*)in_buf++); + else + *ob++ = *in_buf++; } - if (buf != end && fwrite(buf, end - buf, 1, f) != 1) + if (end_char) /* The "- 10" above means that there is always room for one more char here. */ + *ob++ = end_char; + if (ob != outbuf && fwrite(outbuf, ob - outbuf, 1, f) != 1) exit_cleanup(RERR_MESSAGEIO); } @@ -240,8 +251,8 @@ static void filtered_fwrite(FILE *f, const char *buf, * can happen with certain fatal conditions. */ void rwrite(enum logcode code, const char *buf, int len, int is_utf8) { - int trailing_CR_or_NL; - FILE *f = NULL; + char trailing_CR_or_NL; + FILE *f = msgs2stderr == 1 ? stderr : stdout; #ifdef ICONV_OPTION iconv_t ic = is_utf8 && ic_recv != (iconv_t)-1 ? ic_recv : ic_chck; #else @@ -253,7 +264,15 @@ void rwrite(enum logcode code, const char *buf, int le if (len < 0) exit_cleanup(RERR_MESSAGEIO); - if (am_server && msg_fd_out >= 0) { + if (msgs2stderr == 1) { + /* A normal daemon can get msgs2stderr set if the socket is busted, so we + * change the message destination into an FLOG message in order to try to + * get some info about an abnormal-exit into the log file. An rsh daemon + * can have this set via user request, so we'll leave the code alone so + * that the msg gets logged and then sent to stderr after that. */ + if (am_daemon > 0 && code != FCLIENT) + code = FLOG; + } else if (send_msgs_to_gen) { assert(!is_utf8); /* Pass the message to our sibling in native charset. */ send_msg((enum msgcode)code, buf, len, 0); @@ -288,10 +307,28 @@ void rwrite(enum logcode code, const char *buf, int le } else if (code == FLOG) return; - if (quiet && code == FINFO) - return; + switch (code) { + case FERROR_XFER: + got_xfer_error = 1; + /* FALL THROUGH */ + case FERROR: + case FWARNING: + f = stderr; + break; + case FINFO: + if (quiet) + return; + break; + /*case FLOG:*/ + /*case FCLIENT:*/ + /*case FERROR_UTF8:*/ + /*case FERROR_SOCKET:*/ + default: + fprintf(stderr, "Bad logcode in rwrite(): %d [%s]\n", (int)code, who_am_i()); + exit_cleanup(RERR_MESSAGEIO); + } - if (am_server) { + if (am_server && msgs2stderr != 1 && (msgs2stderr != 2 || f != stderr)) { enum msgcode msg = (enum msgcode)code; if (protocol_version < 30) { if (msg == MSG_ERROR) @@ -302,35 +339,26 @@ void rwrite(enum logcode code, const char *buf, int le /* Pass the message to the non-server side. */ if (send_msg(msg, buf, len, !is_utf8)) return; - if (am_daemon) { + if (am_daemon > 0) { /* TODO: can we send the error to the user somehow? */ return; } - } - - switch (code) { - case FERROR_XFER: - got_xfer_error = 1; - /* FALL THROUGH */ - case FERROR: - case FWARNING: f = stderr; - break; - case FINFO: - f = am_server ? stderr : stdout; - break; - default: - exit_cleanup(RERR_MESSAGEIO); } - if (progress_is_active && !am_server) { + if (output_needs_newline) { fputc('\n', f); - progress_is_active = 0; + output_needs_newline = 0; } - trailing_CR_or_NL = len && (buf[len-1] == '\n' || buf[len-1] == '\r') - ? buf[--len] : 0; + trailing_CR_or_NL = len && (buf[len-1] == '\n' || buf[len-1] == '\r') ? buf[--len] : '\0'; + if (len && buf[0] == '\r') { + fputc('\r', f); + buf++; + len--; + } + #ifdef ICONV_CONST if (ic != (iconv_t)-1) { xbuf outbuf, inbuf; @@ -338,27 +366,39 @@ void rwrite(enum logcode code, const char *buf, int le int ierrno; INIT_CONST_XBUF(outbuf, convbuf); - INIT_XBUF(inbuf, (char*)buf, len, -1); + INIT_XBUF(inbuf, (char*)buf, len, (size_t)-1); while (inbuf.len) { - iconvbufs(ic, &inbuf, &outbuf, 0); + iconvbufs(ic, &inbuf, &outbuf, inbuf.pos ? 0 : ICB_INIT); ierrno = errno; if (outbuf.len) { - filtered_fwrite(f, convbuf, outbuf.len, 0); + char trailing = inbuf.len ? '\0' : trailing_CR_or_NL; + filtered_fwrite(f, convbuf, outbuf.len, 0, trailing); + if (trailing) { + trailing_CR_or_NL = '\0'; + fflush(f); + } outbuf.len = 0; } - if (!ierrno || ierrno == E2BIG) - continue; - fprintf(f, "\\#%03o", CVAL(inbuf.buf, inbuf.pos++)); - inbuf.len--; + /* Log one byte of illegal/incomplete sequence and continue with + * the next character. Check that the buffer is non-empty for the + * sake of robustness. */ + if ((ierrno == EILSEQ || ierrno == EINVAL) && inbuf.len) { + fprintf(f, "\\#%03o", CVAL(inbuf.buf, inbuf.pos++)); + inbuf.len--; + } } + + if (trailing_CR_or_NL) { + fputc(trailing_CR_or_NL, f); + fflush(f); + } } else #endif - filtered_fwrite(f, buf, len, !allow_8bit_chars); - - if (trailing_CR_or_NL) { - fputc(trailing_CR_or_NL, f); - fflush(f); + { + filtered_fwrite(f, buf, len, !allow_8bit_chars, trailing_CR_or_NL); + if (trailing_CR_or_NL) + fflush(f); } } @@ -417,8 +457,7 @@ void rsyserr(enum logcode code, int errcode, const cha char buf[BIGPATHBUFLEN]; size_t len; - strlcpy(buf, RSYNC_NAME ": ", sizeof buf); - len = (sizeof RSYNC_NAME ": ") - 1; + len = snprintf(buf, sizeof buf, RSYNC_NAME ": [%s] ", who_am_i()); va_start(ap, format); len += vsnprintf(buf + len, sizeof buf - len, format, ap); @@ -436,12 +475,12 @@ void rsyserr(enum logcode code, int errcode, const cha void rflush(enum logcode code) { - FILE *f = NULL; + FILE *f; if (am_daemon || code == FLOG) return; - if (code == FINFO && !am_server) + if (!am_server && (code == FINFO || code == FCLIENT)) f = stdout; else f = stderr; @@ -449,10 +488,15 @@ void rflush(enum logcode code) fflush(f); } +void remember_initial_stats(void) +{ + initial_data_read = total_data_read; + initial_data_written = total_data_written; +} + /* A generic logging routine for send/recv, with parameter substitiution. */ static void log_formatted(enum logcode code, const char *format, const char *op, - struct file_struct *file, const char *fname, - struct stats *initial_stats, int iflags, + struct file_struct *file, const char *fname, int iflags, const char *hlink) { char buf[MAXPATHLEN+1024], buf2[MAXPATHLEN], fmt[32]; @@ -475,30 +519,45 @@ static void log_formatted(enum logcode code, const cha buf[total] = '\0'; for (p = buf; (p = strchr(p, '%')) != NULL; ) { + int humanize = 0; s = p++; c = fmt + 1; + while (*p == '\'') { + humanize++; + p++; + } if (*p == '-') *c++ = *p++; while (isDigit(p) && c - fmt < (int)(sizeof fmt) - 8) *c++ = *p++; + while (*p == '\'') { + humanize++; + p++; + } if (!*p) break; *c = '\0'; n = NULL; + /* Note for %h and %a: it doesn't matter what fd we pass to + * client_{name,addr} because rsync_module will already have + * forced the answer to be cached (assuming, of course, for %h + * that lp_reverse_lookup(module_id) is true). */ switch (*p) { case 'h': - if (am_daemon) - n = client_name(0); + if (am_daemon) { + n = lp_reverse_lookup(module_id) + ? client_name(0) : undetermined_hostname; + } break; case 'a': if (am_daemon) n = client_addr(0); break; case 'l': - strlcat(fmt, ".0f", sizeof fmt); + strlcat(fmt, "s", sizeof fmt); snprintf(buf2, sizeof buf2, fmt, - (double)F_LENGTH(file)); + do_big_num(F_LENGTH(file), humanize, NULL)); n = buf2; break; case 'U': @@ -518,9 +577,8 @@ static void log_formatted(enum logcode code, const cha } break; case 'p': - strlcat(fmt, "ld", sizeof fmt); - snprintf(buf2, sizeof buf2, fmt, - (long)getpid()); + strlcat(fmt, "d", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, (int)getpid()); n = buf2; break; case 'M': @@ -607,28 +665,33 @@ static void log_formatted(enum logcode code, const cha n = auth_user; break; case 'b': - if (am_sender) { - b = stats.total_written - - initial_stats->total_written; - } else { - b = stats.total_read - - initial_stats->total_read; - } - strlcat(fmt, ".0f", sizeof fmt); - snprintf(buf2, sizeof buf2, fmt, (double)b); + case 'c': + if (!(iflags & ITEM_TRANSFER)) + b = 0; + else if ((!!am_sender) ^ (*p == 'c')) + b = total_data_written - initial_data_written; + else + b = total_data_read - initial_data_read; + strlcat(fmt, "s", sizeof fmt); + snprintf(buf2, sizeof buf2, fmt, + do_big_num(b, humanize, NULL)); n = buf2; break; - case 'c': - if (!am_sender) { - b = stats.total_written - - initial_stats->total_written; - } else { - b = stats.total_read - - initial_stats->total_read; + case 'C': + n = NULL; + if (S_ISREG(file->mode)) { + if (always_checksum) + n = sum_as_hex(checksum_type, F_SUM(file), 1); + else if (iflags & ITEM_TRANSFER) + n = sum_as_hex(xfersum_type, sender_file_sum, 0); } - strlcat(fmt, ".0f", sizeof fmt); - snprintf(buf2, sizeof buf2, fmt, (double)b); - n = buf2; + if (!n) { + int sum_len = csum_len_for_type(always_checksum ? checksum_type : xfersum_type, + always_checksum); + memset(buf2, ' ', sum_len*2); + buf2[sum_len*2] = '\0'; + n = buf2; + } break; case 'i': if (iflags & ITEM_DELETED) { @@ -637,7 +700,7 @@ static void log_formatted(enum logcode code, const cha } n = c = buf2 + MAXPATHLEN - 32; c[0] = iflags & ITEM_LOCAL_CHANGE - ? iflags & ITEM_XNAME_FOLLOWS ? 'h' : 'c' + ? iflags & ITEM_XNAME_FOLLOWS ? 'h' : 'c' : !(iflags & ITEM_TRANSFER) ? '.' : !local_server && *op == 's' ? '<' : '>'; if (S_ISLNK(file->mode)) { @@ -658,10 +721,13 @@ static void log_formatted(enum logcode code, const cha c[5] = !(iflags & ITEM_REPORT_PERMS) ? '.' : 'p'; c[6] = !(iflags & ITEM_REPORT_OWNER) ? '.' : 'o'; c[7] = !(iflags & ITEM_REPORT_GROUP) ? '.' : 'g'; - c[8] = !(iflags & ITEM_REPORT_ATIME) ? '.' : 'u'; + c[8] = !(iflags & (ITEM_REPORT_ATIME|ITEM_REPORT_CRTIME)) ? '.' + : BITS_SET(iflags, ITEM_REPORT_ATIME|ITEM_REPORT_CRTIME) ? 'b' + : iflags & ITEM_REPORT_ATIME ? 'u' : 'n'; c[9] = !(iflags & ITEM_REPORT_ACL) ? '.' : 'a'; c[10] = !(iflags & ITEM_REPORT_XATTR) ? '.' : 'x'; - c[11] = '\0'; + c[11] = !(iflags & ITEM_REPORT_FFLAGS) ? '.' : 'f'; + c[12] = '\0'; if (iflags & (ITEM_IS_NEW|ITEM_MISSING_DATA)) { char ch = iflags & ITEM_IS_NEW ? '+' : '?'; @@ -728,10 +794,12 @@ int log_format_has(const char *format, char esc) return 0; for (p = format; (p = strchr(p, '%')) != NULL; ) { - if (*++p == '-') + for (p++; *p == '\''; p++) {} /*SHARED ITERATOR*/ + if (*p == '-') p++; while (isDigit(p)) p++; + while (*p == '\'') p++; if (!*p) break; if (*p == esc) @@ -743,36 +811,30 @@ int log_format_has(const char *format, char esc) /* Log the transfer of a file. If the code is FCLIENT, the output just goes * to stdout. If it is FLOG, it just goes to the log file. Otherwise we * output to both. */ -void log_item(enum logcode code, struct file_struct *file, - struct stats *initial_stats, int iflags, const char *hlink) +void log_item(enum logcode code, struct file_struct *file, int iflags, const char *hlink) { const char *s_or_r = am_sender ? "send" : "recv"; - if (code != FLOG && stdout_format && !am_server) { - log_formatted(FCLIENT, stdout_format, s_or_r, - file, NULL, initial_stats, iflags, hlink); - } - if (code != FCLIENT && logfile_format && *logfile_format) { - log_formatted(FLOG, logfile_format, s_or_r, - file, NULL, initial_stats, iflags, hlink); - } + if (code != FLOG && stdout_format && !am_server) + log_formatted(FCLIENT, stdout_format, s_or_r, file, NULL, iflags, hlink); + if (code != FCLIENT && logfile_format && *logfile_format) + log_formatted(FLOG, logfile_format, s_or_r, file, NULL, iflags, hlink); } -void maybe_log_item(struct file_struct *file, int iflags, int itemizing, - const char *buf) +void maybe_log_item(struct file_struct *file, int iflags, int itemizing, const char *buf) { int significant_flags = iflags & SIGNIFICANT_ITEM_FLAGS; int see_item = itemizing && (significant_flags || *buf - || stdout_format_has_i > 1 || (verbose > 1 && stdout_format_has_i)); + || stdout_format_has_i > 1 || (INFO_GTE(NAME, 2) && stdout_format_has_i)); int local_change = iflags & ITEM_LOCAL_CHANGE && significant_flags; if (am_server) { if (logfile_name && !dry_run && see_item && (significant_flags || logfile_format_has_i)) - log_item(FLOG, file, &stats, iflags, buf); + log_item(FLOG, file, iflags, buf); } else if (see_item || local_change || *buf || (S_ISDIR(file->mode) && significant_flags)) { enum logcode code = significant_flags || logfile_format_has_i ? FINFO : FCLIENT; - log_item(code, file, &stats, iflags, buf); + log_item(code, file, iflags, buf); } } @@ -781,29 +843,28 @@ void log_delete(const char *fname, int mode) static struct { union file_extras ex[4]; /* just in case... */ struct file_struct file; - } x; + } x; /* Zero-initialized due to static declaration. */ int len = strlen(fname); const char *fmt; x.file.mode = mode; - if (!verbose && !stdout_format) - ; - else if (am_server && protocol_version >= 29 && len < MAXPATHLEN) { + if (am_server && protocol_version >= 29 && len < MAXPATHLEN) { if (S_ISDIR(mode)) len++; /* directories include trailing null */ send_msg(MSG_DELETED, fname, len, am_generator); - } else { + } else if (!INFO_GTE(DEL, 1) && !stdout_format) + ; + else { fmt = stdout_format_has_o_or_i ? stdout_format : "deleting %n"; - log_formatted(FCLIENT, fmt, "del.", &x.file, fname, &stats, - ITEM_DELETED, NULL); + log_formatted(FCLIENT, fmt, "del.", &x.file, fname, ITEM_DELETED, NULL); } if (!logfile_name || dry_run || !logfile_format) return; fmt = logfile_format_has_o_or_i ? logfile_format : "deleting %n"; - log_formatted(FLOG, fmt, "del.", &x.file, fname, &stats, ITEM_DELETED, NULL); + log_formatted(FLOG, fmt, "del.", &x.file, fname, ITEM_DELETED, NULL); } /* @@ -814,12 +875,15 @@ void log_delete(const char *fname, int mode) */ void log_exit(int code, const char *file, int line) { - if (code == 0) { - 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 if (am_server != 2) { + /* The receiving side's stats are split between 2 procs until the + * end of the run, so only the sender can output non-final info. */ + if (code == 0 || am_sender) { + rprintf(FLOG,"sent %s bytes received %s bytes total size %s\n", + big_num(stats.total_written), + big_num(stats.total_read), + big_num(stats.total_size)); + } + if (code != 0 && am_server != 2) { const char *name; name = rerr_name(code); @@ -829,10 +893,10 @@ void log_exit(int code, const char *file, int line) /* VANISHED is not an error, only a warning */ if (code == RERR_VANISHED) { rprintf(FWARNING, "rsync warning: %s (code %d) at %s(%d) [%s=%s]\n", - name, code, file, line, who_am_i(), RSYNC_VERSION); + name, code, src_file(file), line, who_am_i(), rsync_version()); } else { rprintf(FERROR, "rsync error: %s (code %d) at %s(%d) [%s=%s]\n", - name, code, file, line, who_am_i(), RSYNC_VERSION); + name, code, src_file(file), line, who_am_i(), rsync_version()); } } }