log.c

   1 /* -*- c-file-style: "linux"; -*-
   2
   3    Copyright (C) 1998-2001 by Andrew Tridgell <tridge@samba.org>
   4    Copyright (C) 2000-2001 by Martin Pool <mbp@samba.org>
   5
   6    This program is free software; you can redistribute it and/or modify
   7    it under the terms of the GNU General Public License as published by
   8    the Free Software Foundation; either version 2 of the License, or
   9    (at your option) any later version.
  10
  11    This program is distributed in the hope that it will be useful,
  12    but WITHOUT ANY WARRANTY; without even the implied warranty of
  13    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14    GNU General Public License for more details.
  15
  16    You should have received a copy of the GNU General Public License
  17    along with this program; if not, write to the Free Software
  18    Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA.
  19 */
  20
  21 /*
  22   Logging and utility functions.
  23   tridge, May 1998
  24
  25   Mapping to human-readable messages added by Martin Pool
  26   <mbp@samba.org>, Oct 2000.
  27   */
  28 #include "rsync.h"
  29
  30 static char *logfname;
  31 static FILE *logfile;
  32 static int log_error_fd = -1;
  33
  34 int log_got_error=0;
  35
  36 struct {
  37         int code;
  38         char const *name;
  39 } const rerr_names[] = {
  40         { RERR_SYNTAX     , "syntax or usage error" },
  41         { RERR_PROTOCOL   , "protocol incompatibility" },
  42         { RERR_FILESELECT , "errors selecting input/output files, dirs" },
  43         { RERR_UNSUPPORTED , "requested action not supported" },
  44         { RERR_SOCKETIO   , "error in socket IO" },
  45         { RERR_FILEIO     , "error in file IO" },
  46         { RERR_STREAMIO   , "error in rsync protocol data stream" },
  47         { RERR_MESSAGEIO  , "errors with program diagnostics" },
  48         { RERR_IPC        , "error in IPC code" },
  49         { RERR_SIGNAL     , "received SIGUSR1 or SIGINT" },
  50         { RERR_WAITCHILD  , "some error returned by waitpid()" },
  51         { RERR_MALLOC     , "error allocating core memory buffers" },
  52         { RERR_TIMEOUT    , "timeout in data send/receive" },
  53         { 0, NULL }
  54 };
  55
  56
  57
  58 /*
  59  * Map from rsync error code to name, or return NULL.
  60  */
  61 static char const *rerr_name(int code)
  62 {
  63         int i;
  64         for (i = 0; rerr_names[i].name; i++) {
  65                 if (rerr_names[i].code == code)
  66                         return rerr_names[i].name;
  67         }
  68         return NULL;
  69 }
  70
  71 struct err_list {
  72         struct err_list *next;
  73         char *buf;
  74         int len;
  75         int written; /* how many bytes we have written so far */
  76 };
  77
  78 static struct err_list *err_list_head;
  79 static struct err_list *err_list_tail;
  80
  81 /* add an error message to the pending error list */
  82 static void err_list_add(int code, char *buf, int len)
  83 {
  84         struct err_list *el;
  85         el = (struct err_list *)malloc(sizeof(*el));
  86         if (!el) exit_cleanup(RERR_MALLOC);
  87         el->next = NULL;
  88         el->buf = malloc(len+4);
  89         if (!el->buf) exit_cleanup(RERR_MALLOC);
  90         memcpy(el->buf+4, buf, len);
  91         SIVAL(el->buf, 0, ((code+MPLEX_BASE)<<24) | len);
  92         el->len = len+4;
  93         el->written = 0;
  94         if (err_list_tail) {
  95                 err_list_tail->next = el;
  96         } else {
  97                 err_list_head = el;
  98         }
  99         err_list_tail = el;
 100 }
 101
 102
 103 /* try to push errors off the error list onto the wire */
 104 void err_list_push(void)
 105 {
 106         if (log_error_fd == -1) return;
 107
 108         while (err_list_head) {
 109                 struct err_list *el = err_list_head;
 110                 int n = write(log_error_fd, el->buf+el->written, el->len - el->written);
 111                 /* don't check for an error if the best way of handling the error is
 112                    to ignore it */
 113                 if (n == -1) break;
 114                 if (n > 0) {
 115                         el->written += n;
 116                 }
 117                 if (el->written == el->len) {
 118                         free(el->buf);
 119                         err_list_head = el->next;
 120                         if (!err_list_head) err_list_tail = NULL;
 121                         free(el);
 122                 }
 123         }
 124 }
 125
 126
 127 static void logit(int priority, char *buf)
 128 {
 129         if (logfname) {
 130                 if (!logfile)
 131                         log_open();
 132                 fprintf(logfile,"%s [%d] %s",
 133                         timestring(time(NULL)), (int)getpid(), buf);
 134                 fflush(logfile);
 135         } else {
 136                 syslog(priority, "%s", buf);
 137         }
 138 }
 139
 140 void log_init(void)
 141 {
 142         static int initialised;
 143         int options = LOG_PID;
 144         time_t t;
 145
 146         if (initialised) return;
 147         initialised = 1;
 148
 149         /* this looks pointless, but it is needed in order for the
 150            C library on some systems to fetch the timezone info
 151            before the chroot */
 152         t = time(NULL);
 153         localtime(&t);
 154
 155         /* optionally use a log file instead of syslog */
 156         logfname = lp_log_file();
 157         if (logfname) {
 158                 if (*logfname) {
 159                         log_open();
 160                         return;
 161                 }
 162                 logfname = NULL;
 163         }
 164
 165 #ifdef LOG_NDELAY
 166         options |= LOG_NDELAY;
 167 #endif
 168
 169 #ifdef LOG_DAEMON
 170         openlog("rsyncd", options, lp_syslog_facility());
 171 #else
 172         openlog("rsyncd", options);
 173 #endif
 174
 175 #ifndef LOG_NDELAY
 176         logit(LOG_INFO,"rsyncd started\n");
 177 #endif
 178 }
 179
 180 void log_open()
 181 {
 182         if (logfname && !logfile) {
 183                 extern int orig_umask;
 184                 int old_umask = umask(022 | orig_umask);
 185                 logfile = fopen(logfname, "a");
 186                 umask(old_umask);
 187         }
 188 }
 189
 190 void log_close()
 191 {
 192         if (logfile) {
 193                 fclose(logfile);
 194                 logfile = NULL;
 195         }
 196 }
 197
 198 /* setup the error file descriptor - used when we are a server
 199    that is receiving files */
 200 void set_error_fd(int fd)
 201 {
 202         log_error_fd = fd;
 203         set_nonblocking(log_error_fd);
 204 }
 205
 206 /* this is the underlying (unformatted) rsync debugging function. Call
 207    it with FINFO, FERROR or FLOG */
 208 void rwrite(enum logcode code, char *buf, int len)
 209 {
 210         FILE *f=NULL;
 211         extern int am_daemon;
 212         extern int am_server;
 213         extern int quiet;
 214         /* recursion can happen with certain fatal conditions */
 215
 216         if (quiet && code == FINFO) return;
 217
 218         if (len < 0) exit_cleanup(RERR_MESSAGEIO);
 219
 220         buf[len] = 0;
 221
 222         if (code == FLOG) {
 223                 if (am_daemon) logit(LOG_INFO, buf);
 224                 return;
 225         }
 226
 227         /* first try to pass it off to our sibling */
 228         if (am_server && log_error_fd != -1) {
 229                 err_list_add(code, buf, len);
 230                 err_list_push();
 231                 return;
 232         }
 233
 234         /* if that fails, try to pass it to the other end */
 235         if (am_server && io_multiplex_write(code, buf, len)) {
 236                 return;
 237         }
 238
 239         if (am_daemon) {
 240                 static int depth;
 241                 int priority = LOG_INFO;
 242                 if (code == FERROR) priority = LOG_WARNING;
 243
 244                 if (depth) return;
 245
 246                 depth++;
 247
 248                 log_init();
 249                 logit(priority, buf);
 250
 251                 depth--;
 252                 return;
 253         }
 254
 255         if (code == FERROR) {
 256                 log_got_error = 1;
 257                 f = stderr;
 258         }
 259
 260         if (code == FINFO) {
 261                 if (am_server)
 262                         f = stderr;
 263                 else
 264                         f = stdout;
 265         }
 266
 267         if (!f) exit_cleanup(RERR_MESSAGEIO);
 268
 269         if (fwrite(buf, len, 1, f) != 1) exit_cleanup(RERR_MESSAGEIO);
 270
 271         if (buf[len-1] == '\r' || buf[len-1] == '\n') fflush(f);
 272 }
 273
 274
 275 /* This is the rsync debugging function. Call it with FINFO, FERROR or
 276  * FLOG. */
 277 void rprintf(enum logcode code, const char *format, ...)
 278 {
 279         va_list ap;
 280         char buf[1024];
 281         int len;
 282
 283         va_start(ap, format);
 284         len = vslprintf(buf, sizeof(buf), format, ap);
 285         va_end(ap);
 286
 287         if (len > sizeof(buf)-1) exit_cleanup(RERR_MESSAGEIO);
 288
 289         rwrite(code, buf, len);
 290 }
 291
 292
 293 /* This is like rprintf, but it also tries to print some
 294  * representation of the error code.  Normally errcode = errno.
 295  *
 296  * Unlike rprintf, this always adds a newline and there should not be
 297  * one in the format string.
 298  *
 299  * Note that since strerror might involve dynamically loading a
 300  * message catalog we need to call it once before chroot-ing. */
 301 void rsyserr(enum logcode code, int errcode, const char *format, ...)
 302 {
 303         va_list ap;
 304         char buf[1024];
 305         int len, sys_len;
 306         char *sysmsg;
 307
 308         va_start(ap, format);
 309         len = vslprintf(buf, sizeof(buf), format, ap);
 310         va_end(ap);
 311
 312         if (len > sizeof(buf)-1) exit_cleanup(RERR_MESSAGEIO);
 313
 314         sysmsg = strerror(errcode);
 315         sys_len = strlen(sysmsg);
 316         if (len + 3 + sys_len > sizeof(buf) - 1)
 317                 exit_cleanup(RERR_MESSAGEIO);
 318
 319         strcpy(buf + len, ": ");
 320         len += 2;
 321         strcpy(buf + len, sysmsg);
 322         len += sys_len;
 323         strcpy(buf + len, "\n");
 324         len++;
 325
 326         rwrite(code, buf, len);
 327 }
 328
 329
 330
 331 void rflush(enum logcode code)
 332 {
 333         FILE *f = NULL;
 334         extern int am_daemon;
 335
 336         if (am_daemon) {
 337                 return;
 338         }
 339
 340         if (code == FLOG) {
 341                 return;
 342         }
 343
 344         if (code == FERROR) {
 345                 f = stderr;
 346         }
 347
 348         if (code == FINFO) {
 349                 extern int am_server;
 350                 if (am_server)
 351                         f = stderr;
 352                 else
 353                         f = stdout;
 354         }
 355
 356         if (!f) exit_cleanup(RERR_MESSAGEIO);
 357         fflush(f);
 358 }
 359
 360
 361
 362 /* a generic logging routine for send/recv, with parameter
 363    substitiution */
 364 static void log_formatted(enum logcode code,
 365                           char *format, char *op, struct file_struct *file,
 366                           struct stats *initial_stats)
 367 {
 368         extern int module_id;
 369         extern char *auth_user;
 370         char buf[1024];
 371         char buf2[1024];
 372         char *p, *s, *n;
 373         int l;
 374         extern struct stats stats;
 375         extern int am_sender;
 376         extern int am_daemon;
 377         int64 b;
 378
 379         strlcpy(buf, format, sizeof(buf));
 380
 381         for (s=&buf[0];
 382              s && (p=strchr(s,'%')); ) {
 383                 n = NULL;
 384                 s = p + 1;
 385
 386                 switch (p[1]) {
 387                 case 'h': if (am_daemon) n = client_name(0); break;
 388                 case 'a': if (am_daemon) n = client_addr(0); break;
 389                 case 'l':
 390                         slprintf(buf2,sizeof(buf2),"%.0f",
 391                                  (double)file->length);
 392                         n = buf2;
 393                         break;
 394                 case 'p':
 395                         slprintf(buf2,sizeof(buf2),"%d",
 396                                  (int)getpid());
 397                         n = buf2;
 398                         break;
 399                 case 'o': n = op; break;
 400                 case 'f':
 401                         slprintf(buf2, sizeof(buf2), "%s/%s",
 402                                  file->basedir?file->basedir:"",
 403                                  f_name(file));
 404                         clean_fname(buf2);
 405                         n = buf2;
 406                         if (*n == '/') n++;
 407                         break;
 408                 case 'm': n = lp_name(module_id); break;
 409                 case 't': n = timestring(time(NULL)); break;
 410                 case 'P': n = lp_path(module_id); break;
 411                 case 'u': n = auth_user; break;
 412                 case 'b':
 413                         if (am_sender) {
 414                                 b = stats.total_written -
 415                                         initial_stats->total_written;
 416                         } else {
 417                                 b = stats.total_read -
 418                                         initial_stats->total_read;
 419                         }
 420                         slprintf(buf2,sizeof(buf2),"%.0f", (double)b);
 421                         n = buf2;
 422                         break;
 423                 case 'c':
 424                         if (!am_sender) {
 425                                 b = stats.total_written -
 426                                         initial_stats->total_written;
 427                         } else {
 428                                 b = stats.total_read -
 429                                         initial_stats->total_read;
 430                         }
 431                         slprintf(buf2,sizeof(buf2),"%.0f", (double)b);
 432                         n = buf2;
 433                         break;
 434                 }
 435
 436                 if (!n) continue;
 437
 438                 l = strlen(n);
 439
 440                 if ((l-1) + ((int)(s - &buf[0])) > sizeof(buf)) {
 441                         rprintf(FERROR,"buffer overflow expanding %%%c - exiting\n",
 442                                 p[0]);
 443                         exit_cleanup(RERR_MESSAGEIO);
 444                 }
 445
 446                 if (l != 2) {
 447                         memmove(s+(l-1), s+1, strlen(s+1)+1);
 448                 }
 449                 memcpy(p, n, l);
 450
 451                 s = p+l;
 452         }
 453
 454         rprintf(code,"%s\n", buf);
 455 }
 456
 457 /* log the outgoing transfer of a file */
 458 void log_send(struct file_struct *file, struct stats *initial_stats)
 459 {
 460         extern int module_id;
 461         extern int am_server;
 462         extern char *log_format;
 463
 464         if (lp_transfer_logging(module_id)) {
 465                 log_formatted(FLOG, lp_log_format(module_id), "send", file, initial_stats);
 466         } else if (log_format && !am_server) {
 467                 log_formatted(FINFO, log_format, "send", file, initial_stats);
 468         }
 469 }
 470
 471 /* log the incoming transfer of a file */
 472 void log_recv(struct file_struct *file, struct stats *initial_stats)
 473 {
 474         extern int module_id;
 475         extern int am_server;
 476         extern char *log_format;
 477
 478         if (lp_transfer_logging(module_id)) {
 479                 log_formatted(FLOG, lp_log_format(module_id), "recv", file, initial_stats);
 480         } else if (log_format && !am_server) {
 481                 log_formatted(FINFO, log_format, "recv", file, initial_stats);
 482         }
 483 }
 484
 485
 486
 487
 488 /*
 489  * Called when the transfer is interrupted for some reason.
 490  *
 491  * Code is one of the RERR_* codes from errcode.h, or terminating
 492  * successfully.
 493  */
 494 void log_exit(int code, const char *file, int line)
 495 {
 496         if (code == 0) {
 497                 extern struct stats stats;
 498                 rprintf(FLOG,"wrote %.0f bytes  read %.0f bytes  total size %.0f\n",
 499                         (double)stats.total_written,
 500                         (double)stats.total_read,
 501                         (double)stats.total_size);
 502         } else {
 503                 const char *name;
 504
 505                 name = rerr_name(code);
 506                 if (!name)
 507                         name = "unexplained error";
 508
 509                 rprintf(FLOG,"transfer interrupted: %s (code %d) at %s(%d)\n",
 510                         name, code, file, line);
 511         }
 512 }
 513
 514
 515
 516
 517 /* log the incoming transfer of a file for interactive use, this
 518    will be called at the end where the client was run
 519
 520    it i called when a file starts to be transferred
 521 */
 522 void log_transfer(struct file_struct *file, const char *fname)
 523 {
 524         extern int verbose;
 525
 526         if (!verbose) return;
 527
 528         rprintf(FINFO,"%s\n", fname);
 529 }
 530