third_party/heimdal/lib/base/log.c

   1 /*
   2  * Copyright (c) 1997-2020 Kungliga Tekniska Högskolan
   3  * (Royal Institute of Technology, Stockholm, Sweden).
   4  * All rights reserved.
   5  *
   6  * Portions Copyright (c) 2009 Apple Inc. All rights reserved.
   7  *
   8  * Redistribution and use in source and binary forms, with or without
   9  * modification, are permitted provided that the following conditions
  10  * are met:
  11  *
  12  * 1. Redistributions of source code must retain the above copyright
  13  *    notice, this list of conditions and the following disclaimer.
  14  *
  15  * 2. Redistributions in binary form must reproduce the above copyright
  16  *    notice, this list of conditions and the following disclaimer in the
  17  *    documentation and/or other materials provided with the distribution.
  18  *
  19  * 3. Neither the name of the Institute nor the names of its contributors
  20  *    may be used to endorse or promote products derived from this software
  21  *    without specific prior written permission.
  22  *
  23  * THIS SOFTWARE IS PROVIDED BY THE INSTITUTE AND CONTRIBUTORS ``AS IS'' AND
  24  * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
  25  * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
  26  * ARE DISCLAIMED.  IN NO EVENT SHALL THE INSTITUTE OR CONTRIBUTORS BE LIABLE
  27  * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
  28  * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
  29  * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
  30  * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
  31  * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
  32  * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  33  * SUCH DAMAGE.
  34  */
  35
  36 #include "baselocl.h"
  37 #include "heim_threads.h"
  38 #include "heimbase.h"
  39 #include "heimbase-svc.h"
  40 #include <assert.h>
  41 #include <stdarg.h>
  42 #include <vis.h>
  43
  44 struct heim_log_facility_internal {
  45     int min;
  46     int max;
  47     heim_log_log_func_t log_func;
  48     heim_log_close_func_t close_func;
  49     void *data;
  50 };
  51
  52 struct heim_log_facility_s {
  53     char *program;
  54     size_t refs;
  55     size_t len;
  56     struct heim_log_facility_internal *val;
  57 };
  58
  59 typedef struct heim_pcontext_s *heim_pcontext;
  60 typedef struct heim_pconfig *heim_pconfig;
  61 struct heim_svc_req_desc_common_s {
  62     HEIM_SVC_REQUEST_DESC_COMMON_ELEMENTS;
  63 };
  64
  65 static struct heim_log_facility_internal *
  66 log_realloc(heim_log_facility *f)
  67 {
  68     struct heim_log_facility_internal *fp;
  69     fp = realloc(f->val, (f->len + 1) * sizeof(*f->val));
  70     if (fp == NULL)
  71         return NULL;
  72     f->len++;
  73     f->val = fp;
  74     fp += f->len - 1;
  75     return fp;
  76 }
  77
  78 struct s2i {
  79     const char *s;
  80     int val;
  81 };
  82
  83 #define L(X) { #X, LOG_ ## X }
  84
  85 static struct s2i syslogvals[] = {
  86     L(EMERG),
  87     L(ALERT),
  88     L(CRIT),
  89     L(ERR),
  90     L(WARNING),
  91     L(NOTICE),
  92     L(INFO),
  93     L(DEBUG),
  94
  95     L(AUTH),
  96 #ifdef LOG_AUTHPRIV
  97     L(AUTHPRIV),
  98 #endif
  99 #ifdef LOG_CRON
 100     L(CRON),
 101 #endif
 102     L(DAEMON),
 103 #ifdef LOG_FTP
 104     L(FTP),
 105 #endif
 106     L(KERN),
 107     L(LPR),
 108     L(MAIL),
 109 #ifdef LOG_NEWS
 110     L(NEWS),
 111 #endif
 112     L(SYSLOG),
 113     L(USER),
 114 #ifdef LOG_UUCP
 115     L(UUCP),
 116 #endif
 117     L(LOCAL0),
 118     L(LOCAL1),
 119     L(LOCAL2),
 120     L(LOCAL3),
 121     L(LOCAL4),
 122     L(LOCAL5),
 123     L(LOCAL6),
 124     L(LOCAL7),
 125     { NULL, -1 }
 126 };
 127
 128 static int
 129 find_value(const char *s, struct s2i *table)
 130 {
 131     while (table->s && strcasecmp(table->s, s) != 0)
 132         table++;
 133     return table->val;
 134 }
 135
 136 heim_error_code
 137 heim_initlog(heim_context context,
 138              const char *program,
 139              heim_log_facility **fac)
 140 {
 141     heim_log_facility *f = calloc(1, sizeof(*f));
 142     if (f == NULL)
 143         return heim_enomem(context);
 144     f->refs = 1;
 145     f->program = strdup(program);
 146     if (f->program == NULL) {
 147         free(f);
 148         return heim_enomem(context);
 149     }
 150     *fac = f;
 151     return 0;
 152 }
 153
 154 heim_log_facility *
 155 heim_log_ref(heim_log_facility *fac)
 156 {
 157     if (fac)
 158         fac->refs++;
 159     return fac;
 160 }
 161
 162 heim_error_code
 163 heim_addlog_func(heim_context context,
 164                  heim_log_facility *fac,
 165                  int min,
 166                  int max,
 167                  heim_log_log_func_t log_func,
 168                  heim_log_close_func_t close_func,
 169                  void *data)
 170 {
 171     struct heim_log_facility_internal *fp = log_realloc(fac);
 172     if (fp == NULL)
 173         return heim_enomem(context);
 174     fp->min = min;
 175     fp->max = max;
 176     fp->log_func = log_func;
 177     fp->close_func = close_func;
 178     fp->data = data;
 179     return 0;
 180 }
 181
 182
 183 struct _heimdal_syslog_data{
 184     int priority;
 185 };
 186
 187 static void HEIM_CALLCONV
 188 log_syslog(heim_context context, const char *timestr,
 189            const char *msg, void *data)
 190 {
 191     struct _heimdal_syslog_data *s = data;
 192     syslog(s->priority, "%s", msg);
 193 }
 194
 195 static void HEIM_CALLCONV
 196 close_syslog(void *data)
 197 {
 198     free(data);
 199     closelog();
 200 }
 201
 202 static heim_error_code
 203 open_syslog(heim_context context,
 204             heim_log_facility *facility, int min, int max,
 205             const char *sev, const char *fac)
 206 {
 207     struct _heimdal_syslog_data *sd = malloc(sizeof(*sd));
 208     int i;
 209
 210     if (sd == NULL)
 211         return heim_enomem(context);
 212     i = find_value(sev, syslogvals);
 213     if (i == -1)
 214         i = LOG_ERR;
 215     sd->priority = i;
 216     i = find_value(fac, syslogvals);
 217     if (i == -1)
 218         i = LOG_AUTH;
 219     sd->priority |= i;
 220     roken_openlog(facility->program, LOG_PID | LOG_NDELAY, i);
 221     return heim_addlog_func(context, facility, min, max,
 222                             log_syslog, close_syslog, sd);
 223 }
 224
 225 struct file_data {
 226     char *filename;
 227     const char *mode;
 228     struct timeval tv;
 229     FILE *fd;
 230     int disp;
 231 #define FILEDISP_KEEPOPEN       0x1
 232 #define FILEDISP_REOPEN         0x2
 233 #define FILEDISP_IFEXISTS       0x4
 234 };
 235
 236 #ifndef O_CLOEXEC
 237 #define O_CLOEXEC 0
 238 #endif
 239
 240 static void HEIM_CALLCONV
 241 log_file(heim_context context, const char *timestr, const char *msg, void *data)
 242 {
 243     struct timeval tv;
 244     struct file_data *f = data;
 245     FILE *logf = f->fd;
 246     char *msgclean;
 247     size_t i = 0;
 248     size_t j;
 249
 250     if (logf == NULL || (f->disp & FILEDISP_REOPEN)) {
 251         int flags = O_WRONLY|O_APPEND;
 252         int fd;
 253
 254         if (f->mode[0] == 'e') {
 255             flags |= O_CLOEXEC;
 256             i = 1;
 257         }
 258         if (f->mode[i] == 'w')
 259             flags |= O_TRUNC;
 260         if (f->mode[i + 1] == '+')
 261             flags |= O_RDWR;
 262
 263         if (f->disp & FILEDISP_IFEXISTS) {
 264             /* Cache failure for 1s */
 265             gettimeofday(&tv, NULL);
 266             if (tv.tv_sec == f->tv.tv_sec)
 267                 return;
 268         } else {
 269             flags |= O_CREAT;
 270         }
 271
 272         fd = open(f->filename, flags, 0666); /* umask best be set */
 273         if (fd == -1) {
 274             if (f->disp & FILEDISP_IFEXISTS)
 275                 gettimeofday(&f->tv, NULL);
 276             return;
 277         }
 278         rk_cloexec(fd);
 279         logf = fdopen(fd, f->mode);
 280     }
 281     if (f->fd == NULL && (f->disp & FILEDISP_KEEPOPEN))
 282         f->fd = logf;
 283     if (logf == NULL)
 284         return;
 285     /*
 286      * make sure the log doesn't contain special chars:
 287      * we used to use strvisx(3) to encode the log, but this is
 288      * inconsistent with our syslog(3) code which does not do this.
 289      * It also makes it inelegant to write data which has already
 290      * been quoted such as what krb5_unparse_principal() gives us.
 291      * So, we change here to eat the special characters, instead.
 292      */
 293     if (msg && (msgclean = strdup(msg))) {
 294         for (i = 0, j = 0; msg[i]; i++)
 295             if (msg[i] >= 32 || msg[i] == '\t')
 296                 msgclean[j++] = msg[i];
 297         fprintf(logf, "%s %s\n", timestr ? timestr : "", msgclean);
 298         free(msgclean);
 299     }
 300     if (logf != f->fd)
 301         fclose(logf);
 302 }
 303
 304 static void HEIM_CALLCONV
 305 close_file(void *data)
 306 {
 307     struct file_data *f = data;
 308     if (f->fd && f->fd != stdout && f->fd != stderr)
 309         fclose(f->fd);
 310     free(f->filename);
 311     free(data);
 312 }
 313
 314 static heim_error_code
 315 open_file(heim_context context, heim_log_facility *fac, int min, int max,
 316           const char *filename, const char *mode, FILE *f, int disp,
 317           int exp_tokens)
 318 {
 319     heim_error_code ret = 0;
 320     struct file_data *fd;
 321
 322     if ((fd = calloc(1, sizeof(*fd))) == NULL)
 323         return heim_enomem(context);
 324
 325     fd->filename = NULL;
 326     fd->mode = mode;
 327     fd->fd = f;
 328     fd->disp = disp;
 329
 330     if (filename) {
 331         if (exp_tokens)
 332             ret = heim_expand_path_tokens(context, filename, 1, &fd->filename, NULL);
 333         else if ((fd->filename = strdup(filename)) == NULL)
 334             ret = heim_enomem(context);
 335     }
 336     if (ret == 0)
 337         ret = heim_addlog_func(context, fac, min, max, log_file, close_file, fd);
 338     if (ret) {
 339         free(fd->filename);
 340         free(fd);
 341     }
 342     if (disp & FILEDISP_KEEPOPEN)
 343         log_file(context, NULL, NULL, fd);
 344     return ret;
 345 }
 346
 347 heim_error_code
 348 heim_addlog_dest(heim_context context, heim_log_facility *f, const char *orig)
 349 {
 350     heim_error_code ret = 0;
 351     int min = 0, max = 3, n;
 352     char c;
 353     const char *p = orig;
 354 #ifdef _WIN32
 355     const char *q;
 356 #endif
 357
 358     n = sscanf(p, "%d%c%d/", &min, &c, &max);
 359     if (n == 2) {
 360         if (ISPATHSEP(c)) {
 361             if (min < 0) {
 362                 max = -min;
 363                 min = 0;
 364             } else {
 365                 max = min;
 366             }
 367         }
 368         if (c == '-')
 369             max = -1;
 370     }
 371     if (n) {
 372 #ifdef _WIN32
 373         q = strrchr(p, '\\');
 374         if (q != NULL)
 375             p = q;
 376         else
 377 #endif
 378             p = strchr(p, '/');
 379         if (p == NULL) {
 380             heim_set_error_message(context, EINVAL /*XXX HEIM_ERR_LOG_PARSE*/,
 381                                    N_("failed to parse \"%s\"", ""), orig);
 382             return EINVAL /*XXX HEIM_ERR_LOG_PARSE*/;
 383         }
 384         p++;
 385     }
 386     if (strcmp(p, "STDERR") == 0) {
 387         ret = open_file(context, f, min, max, NULL, NULL, stderr,
 388                         FILEDISP_KEEPOPEN, 0);
 389     } else if (strcmp(p, "CONSOLE") == 0) {
 390         /* XXX WIN32 */
 391         ret = open_file(context, f, min, max, "/dev/console", "w", NULL,
 392                         FILEDISP_KEEPOPEN, 0);
 393     } else if (strncmp(p, "EFILE:", 5) == 0) {
 394         ret = open_file(context, f, min, max, p + sizeof("EFILE:") - 1, "a",
 395                         NULL, FILEDISP_IFEXISTS | FILEDISP_REOPEN, 1);
 396     } else if (strncmp(p, "EFILE=", 5) == 0) {
 397         ret = open_file(context, f, min, max, p + sizeof("EFILE=") - 1, "a",
 398                         NULL, FILEDISP_IFEXISTS | FILEDISP_KEEPOPEN, 1);
 399     } else if (strncmp(p, "FILE:", sizeof("FILE:") - 1) == 0) {
 400         ret = open_file(context, f, min, max, p + sizeof("FILE:") - 1, "a",
 401                         NULL, FILEDISP_REOPEN, 1);
 402     } else if (strncmp(p, "FILE=", sizeof("FILE=") - 1) == 0) {
 403         ret = open_file(context, f, min, max, p + sizeof("FILE=") - 1, "a",
 404                         NULL, FILEDISP_KEEPOPEN, 1);
 405     } else if (strncmp(p, "DEVICE:", sizeof("DEVICE:") - 1) == 0) {
 406         ret = open_file(context, f, min, max, p + sizeof("DEVICE:") - 1, "a",
 407                         NULL, FILEDISP_REOPEN, 0);
 408     } else if (strncmp(p, "DEVICE=", sizeof("DEVICE=") - 1) == 0) {
 409         ret = open_file(context, f, min, max, p + sizeof("DEVICE=") - 1, "a",
 410                         NULL, FILEDISP_KEEPOPEN, 0);
 411     } else if (strncmp(p, "SYSLOG", 6) == 0 && (p[6] == '\0' || p[6] == ':')) {
 412         char severity[128] = "";
 413         char facility[128] = "";
 414         p += 6;
 415         if (*p != '\0')
 416             p++;
 417         if (strsep_copy(&p, ":", severity, sizeof(severity)) != -1)
 418             strsep_copy(&p, ":", facility, sizeof(facility));
 419         if (*severity == '\0')
 420             strlcpy(severity, "ERR", sizeof(severity));
 421         if (*facility == '\0')
 422             strlcpy(facility, "AUTH", sizeof(facility));
 423         ret = open_syslog(context, f, min, max, severity, facility);
 424     } else {
 425         ret = EINVAL; /*XXX HEIM_ERR_LOG_PARSE*/
 426         heim_set_error_message(context, ret,
 427                                N_("unknown log type: %s", ""), p);
 428     }
 429     return ret;
 430 }
 431
 432 heim_error_code
 433 heim_openlog(heim_context context,
 434              const char *program,
 435              const char **specs,
 436              heim_log_facility **fac)
 437 {
 438     heim_error_code ret;
 439
 440     ret = heim_initlog(context, program, fac);
 441     if (ret)
 442         return ret;
 443
 444     if (specs) {
 445         size_t i;
 446         for (i = 0; specs[i] && ret == 0; i++)
 447             ret = heim_addlog_dest(context, *fac, specs[i]);
 448     } else {
 449         ret = heim_addlog_dest(context, *fac, "SYSLOG");
 450     }
 451     return ret;
 452 }
 453
 454 void
 455 heim_closelog(heim_context context, heim_log_facility *fac)
 456 {
 457     int i;
 458
 459     if (!fac || --(fac->refs))
 460         return;
 461     for (i = 0; i < fac->len; i++)
 462         (*fac->val[i].close_func)(fac->val[i].data);
 463     free(fac->val);
 464     free(fac->program);
 465     fac->val = NULL;
 466     fac->len = 0;
 467     fac->program = NULL;
 468     free(fac);
 469     return;
 470 }
 471
 472 static void
 473 format_time(heim_context context, time_t t, char *s, size_t len)
 474 {
 475     struct tm *tm = heim_context_get_log_utc(context) ?
 476         gmtime(&t) : localtime(&t);
 477     if (tm && strftime(s, len, heim_context_get_time_fmt(context), tm))
 478         return;
 479     snprintf(s, len, "%ld", (long)t);
 480 }
 481
 482 #undef __attribute__
 483 #define __attribute__(X)
 484
 485 heim_error_code
 486 heim_vlog_msg(heim_context context,
 487               heim_log_facility *fac,
 488               char **reply,
 489               int level,
 490               const char *fmt,
 491               va_list ap)
 492 __attribute__ ((__format__ (__printf__, 5, 0)))
 493 {
 494
 495     char *msg = NULL;
 496     const char *actual = NULL;
 497     char buf[64];
 498     time_t t = 0;
 499     int i;
 500
 501     if (!fac)
 502         fac = context->log_dest;
 503     for (i = 0; fac && i < fac->len; i++)
 504         if (fac->val[i].min <= level &&
 505             (fac->val[i].max < 0 || fac->val[i].max >= level)) {
 506             if (t == 0) {
 507                 t = time(NULL);
 508                 format_time(context, t, buf, sizeof(buf));
 509             }
 510             if (actual == NULL) {
 511                 int ret = vasprintf(&msg, fmt, ap);
 512                 if (ret < 0 || msg == NULL)
 513                     actual = fmt;
 514                 else
 515                     actual = msg;
 516             }
 517             (*fac->val[i].log_func)(context, buf, actual, fac->val[i].data);
 518         }
 519     if (reply == NULL)
 520         free(msg);
 521     else
 522         *reply = msg;
 523     return 0;
 524 }
 525
 526 heim_error_code
 527 heim_vlog(heim_context context,
 528           heim_log_facility *fac,
 529           int level,
 530           const char *fmt,
 531           va_list ap)
 532 __attribute__ ((__format__ (__printf__, 4, 0)))
 533 {
 534     return heim_vlog_msg(context, fac, NULL, level, fmt, ap);
 535 }
 536
 537 heim_error_code
 538 heim_log_msg(heim_context context,
 539              heim_log_facility *fac,
 540              int level,
 541              char **reply,
 542              const char *fmt,
 543              ...)
 544 __attribute__ ((__format__ (__printf__, 5, 6)))
 545 {
 546     va_list ap;
 547     heim_error_code ret;
 548
 549     va_start(ap, fmt);
 550     ret = heim_vlog_msg(context, fac, reply, level, fmt, ap);
 551     va_end(ap);
 552     return ret;
 553 }
 554
 555
 556 heim_error_code
 557 heim_log(heim_context context,
 558          heim_log_facility *fac,
 559          int level,
 560          const char *fmt,
 561          ...)
 562 __attribute__ ((__format__ (__printf__, 4, 5)))
 563 {
 564     va_list ap;
 565     heim_error_code ret;
 566
 567     va_start(ap, fmt);
 568     ret = heim_vlog(context, fac, level, fmt, ap);
 569     va_end(ap);
 570     return ret;
 571 }
 572
 573 void
 574 heim_debug(heim_context context,
 575            int level,
 576            const char *fmt,
 577            ...)
 578 __attribute__ ((__format__ (__printf__, 3, 4)))
 579 {
 580     heim_log_facility *fac;
 581     va_list ap;
 582
 583     if (context == NULL ||
 584         (fac = heim_get_debug_dest(context)) == NULL)
 585         return;
 586
 587     va_start(ap, fmt);
 588     heim_vlog(context, fac, level, fmt, ap);
 589     va_end(ap);
 590 }
 591
 592 void
 593 heim_vdebug(heim_context context,
 594             int level,
 595             const char *fmt,
 596             va_list ap)
 597 __attribute__ ((__format__ (__printf__, 3, 0)))
 598 {
 599     heim_log_facility *fac;
 600
 601     if (context == NULL ||
 602         (fac = heim_get_debug_dest(context)) == NULL)
 603         return;
 604
 605     heim_vlog(context, fac, level, fmt, ap);
 606 }
 607
 608 heim_error_code
 609 heim_have_debug(heim_context context, int level)
 610 {
 611     heim_log_facility *fac;
 612
 613     return (context != NULL &&
 614         (fac = heim_get_debug_dest(context)) != NULL);
 615 }
 616
 617 heim_error_code
 618 heim_add_warn_dest(heim_context context, const char *program,
 619                    const char *log_spec)
 620 {
 621     heim_log_facility *fac;
 622
 623     heim_error_code ret;
 624
 625     if ((fac = heim_get_warn_dest(context)) == NULL) {
 626         ret = heim_initlog(context, program, &fac);
 627         if (ret)
 628             return ret;
 629         heim_set_warn_dest(context, fac);
 630     }
 631
 632     ret = heim_addlog_dest(context, fac, log_spec);
 633     if (ret)
 634         return ret;
 635     return 0;
 636 }
 637
 638 heim_error_code
 639 heim_add_debug_dest(heim_context context, const char *program,
 640                     const char *log_spec)
 641 {
 642     heim_log_facility *fac;
 643     heim_error_code ret;
 644
 645     if ((fac = heim_get_debug_dest(context)) == NULL) {
 646         ret = heim_initlog(context, program, &fac);
 647         if (ret)
 648             return ret;
 649         heim_set_debug_dest(context, fac);
 650     }
 651
 652     ret = heim_addlog_dest(context, fac, log_spec);
 653     if (ret)
 654         return ret;
 655     return 0;
 656 }
 657
 658 static heim_string_t
 659 fmtkv(int flags, const char *k, const char *fmt, va_list ap)
 660         __attribute__ ((__format__ (__printf__, 3, 0)))
 661 {
 662     heim_string_t str;
 663     size_t i;
 664     ssize_t j;
 665     char *buf1;
 666     char *buf2;
 667     char *buf3;
 668     int ret = vasprintf(&buf1, fmt, ap);
 669     if (ret < 0 || !buf1)
 670         return NULL;;
 671
 672     j = asprintf(&buf2, "%s=%s", k, buf1);
 673     free(buf1);
 674     if (j < 0 || !buf2)
 675         return NULL;;
 676
 677     /* We optionally eat the whitespace. */
 678
 679     if (flags & HEIM_SVC_AUDIT_EATWHITE) {
 680         for (i=0, j=0; buf2[i]; i++)
 681             if (buf2[i] != ' ' && buf2[i] != '\t')
 682                 buf2[j++] = buf2[i];
 683         buf2[j] = '\0';
 684     }
 685
 686     if (flags & (HEIM_SVC_AUDIT_VIS | HEIM_SVC_AUDIT_VISLAST)) {
 687         int vis_flags = VIS_CSTYLE | VIS_OCTAL | VIS_NL;
 688
 689         if (flags & HEIM_SVC_AUDIT_VIS)
 690             vis_flags |= VIS_WHITE;
 691         buf3 = malloc((j + 1) * 4 + 1);
 692         if (buf3)
 693             strvisx(buf3, buf2, j, vis_flags);
 694         free(buf2);
 695         if (buf3 == NULL)
 696             return NULL;
 697     } else
 698         buf3 = buf2;
 699
 700     str = heim_string_create(buf3);
 701     free(buf3);
 702     return str;
 703 }
 704
 705 void
 706 heim_audit_vaddreason(heim_svc_req_desc r, const char *fmt, va_list ap)
 707         __attribute__ ((__format__ (__printf__, 2, 0)))
 708 {
 709     heim_string_t str;
 710
 711     str = fmtkv(HEIM_SVC_AUDIT_VISLAST, "reason", fmt, ap);
 712     if (!str) {
 713         heim_log(r->hcontext, r->logf, 1, "heim_audit_vaddreason: "
 714                  "failed to add reason (out of memory)");
 715         return;
 716     }
 717
 718     heim_log(r->hcontext, r->logf, 7, "heim_audit_vaddreason(): "
 719              "adding reason %s", heim_string_get_utf8(str));
 720     if (r->reason) {
 721         heim_string_t str2;
 722
 723         str2 = heim_string_create_with_format("%s: %s",
 724                                               heim_string_get_utf8(str),
 725                                               heim_string_get_utf8(r->reason));
 726         if (str2) {
 727             heim_release(str);
 728             str = str2;
 729         }
 730     }
 731     heim_release(r->reason);
 732     r->reason = str;
 733 }
 734
 735 void
 736 heim_audit_addreason(heim_svc_req_desc r, const char *fmt, ...)
 737         __attribute__ ((__format__ (__printf__, 2, 3)))
 738 {
 739     va_list ap;
 740
 741     va_start(ap, fmt);
 742     heim_audit_vaddreason(r, fmt, ap);
 743     va_end(ap);
 744 }
 745
 746 /*
 747  * append_token adds a token which is optionally a kv-pair and it
 748  * also optionally eats the whitespace.  If k == NULL, then it's
 749  * not a kv-pair.
 750  */
 751
 752 void
 753 heim_audit_vaddkv(heim_svc_req_desc r, int flags, const char *k,
 754                   const char *fmt, va_list ap)
 755         __attribute__ ((__format__ (__printf__, 4, 0)))
 756 {
 757     heim_string_t str;
 758
 759     str = fmtkv(flags, k, fmt, ap);
 760     if (!str) {
 761         heim_log(r->hcontext, r->logf, 1, "heim_audit_vaddkv: "
 762                  "failed to add kv pair (out of memory)");
 763         return;
 764     }
 765
 766     heim_log(r->hcontext, r->logf, 7, "heim_audit_vaddkv(): "
 767              "adding kv pair %s", heim_string_get_utf8(str));
 768     heim_array_append_value(r->kv, str);
 769     heim_release(str);
 770 }
 771
 772 void
 773 heim_audit_addkv(heim_svc_req_desc r, int flags, const char *k,
 774                  const char *fmt, ...)
 775         __attribute__ ((__format__ (__printf__, 4, 5)))
 776 {
 777     va_list ap;
 778
 779     va_start(ap, fmt);
 780     heim_audit_vaddkv(r, flags, k, fmt, ap);
 781     va_end(ap);
 782 }
 783
 784 void
 785 heim_audit_addkv_timediff(heim_svc_req_desc r, const char *k,
 786                           const struct timeval *start,
 787                           const struct timeval *end)
 788 {
 789     time_t sec;
 790     int usec;
 791     const char *sign = "";
 792
 793     if (end->tv_sec > start->tv_sec ||
 794         (end->tv_sec == start->tv_sec && end->tv_usec >= start->tv_usec)) {
 795         sec  = end->tv_sec  - start->tv_sec;
 796         usec = end->tv_usec - start->tv_usec;
 797     } else {
 798         sec  = start->tv_sec  - end->tv_sec;
 799         usec = start->tv_usec - end->tv_usec;
 800         sign = "-";
 801     }
 802
 803     if (usec < 0) {
 804         usec += 1000000;
 805         sec  -= 1;
 806     }
 807
 808     heim_audit_addkv(r, 0, k, "%s%ld.%06d", sign, sec, usec);
 809 }
 810
 811 void
 812 heim_audit_trail(heim_svc_req_desc r, heim_error_code ret, const char *retname)
 813 {
 814     const char *retval;
 815     char kvbuf[1024];
 816     char retvalbuf[30]; /* Enough for UNKNOWN-%d */
 817     size_t nelem;
 818     size_t i, j;
 819
 820 #define CASE(x) case x : retval = #x; break
 821     if (retname) {
 822         retval = retname;
 823     } else switch (ret ? ret : r->ret) {
 824     CASE(ENOMEM);
 825     CASE(ENOENT);
 826     CASE(EACCES);
 827     case 0:
 828         retval = "SUCCESS";
 829         break;
 830     default:
 831         /* Wish we had a com_err number->symbolic name function */
 832         (void) snprintf(retvalbuf, sizeof(retvalbuf), "UNKNOWN-%d", ret);
 833         retval = retvalbuf;
 834         break;
 835     }
 836
 837     heim_audit_addkv_timediff(r, "elapsed", &r->tv_start, &r->tv_end);
 838     if (r->e_text && r->kv)
 839         heim_audit_addkv(r, HEIM_SVC_AUDIT_VIS, "e-text", "%s", r->e_text);
 840
 841     nelem = r->kv ? heim_array_get_length(r->kv) : 0;
 842     for (i=0, j=0; i < nelem; i++) {
 843         heim_string_t s;
 844         const char *kvpair;
 845
 846         /* We know these are strings... */
 847         s = heim_array_get_value(r->kv, i);
 848         kvpair = heim_string_get_utf8(s);
 849
 850         if (j < sizeof(kvbuf) - 1)
 851             kvbuf[j++] = ' ';
 852         for (; *kvpair && j < sizeof(kvbuf) - 1; j++)
 853             kvbuf[j] = *kvpair++;
 854     }
 855     kvbuf[j] = '\0';
 856
 857     heim_log(r->hcontext, r->logf, 3, "%s %s %s %s %s%s%s%s",
 858              r->reqtype, retval, r->from,
 859              r->cname ? r->cname : "<unknown>",
 860              r->sname ? r->sname : "<unknown>",
 861              kvbuf, r->reason ? " " : "",
 862              r->reason ? heim_string_get_utf8(r->reason) : "");
 863 }