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