Line data    Source code

       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-atomics.h"
      39             : #include "heimbase.h"
      40             : #include "heimbase-svc.h"
      41             : #include <assert.h>
      42             : #include <stdarg.h>
      43             : #include <vis.h>
      44             : #include <base64.h>
      45             : 
      46             : struct heim_log_facility_internal {
      47             :     int min;
      48             :     int max;
      49             :     heim_log_log_func_t log_func;
      50             :     heim_log_close_func_t close_func;
      51             :     void *data;
      52             : };
      53             : 
      54             : struct heim_log_facility_s {
      55             :     char *program;
      56             :     heim_base_atomic(uint32_t) refs;
      57             :     size_t len;
      58             :     struct heim_log_facility_internal *val;
      59             : };
      60             : 
      61             : typedef struct heim_pcontext_s *heim_pcontext;
      62             : typedef struct heim_pconfig *heim_pconfig;
      63             : struct heim_svc_req_desc_common_s {
      64             :     HEIM_SVC_REQUEST_DESC_COMMON_ELEMENTS;
      65             : };
      66             : 
      67             : static struct heim_log_facility_internal *
      68      553460 : log_realloc(heim_log_facility *f)
      69             : {
      70       13156 :     struct heim_log_facility_internal *fp;
      71      553460 :     fp = realloc(f->val, (f->len + 1) * sizeof(*f->val));
      72      553460 :     if (fp == NULL)
      73           0 :         return NULL;
      74      553460 :     f->len++;
      75      553460 :     f->val = fp;
      76      553460 :     fp += f->len - 1;
      77      553460 :     return fp;
      78             : }
      79             : 
      80             : struct s2i {
      81             :     const char *s;
      82             :     int val;
      83             : };
      84             : 
      85             : #define L(X) { #X, LOG_ ## X }
      86             : 
      87             : static struct s2i syslogvals[] = {
      88             :     L(EMERG),
      89             :     L(ALERT),
      90             :     L(CRIT),
      91             :     L(ERR),
      92             :     L(WARNING),
      93             :     L(NOTICE),
      94             :     L(INFO),
      95             :     L(DEBUG),
      96             : 
      97             :     L(AUTH),
      98             : #ifdef LOG_AUTHPRIV
      99             :     L(AUTHPRIV),
     100             : #endif
     101             : #ifdef LOG_CRON
     102             :     L(CRON),
     103             : #endif
     104             :     L(DAEMON),
     105             : #ifdef LOG_FTP
     106             :     L(FTP),
     107             : #endif
     108             :     L(KERN),
     109             :     L(LPR),
     110             :     L(MAIL),
     111             : #ifdef LOG_NEWS
     112             :     L(NEWS),
     113             : #endif
     114             :     L(SYSLOG),
     115             :     L(USER),
     116             : #ifdef LOG_UUCP
     117             :     L(UUCP),
     118             : #endif
     119             :     L(LOCAL0),
     120             :     L(LOCAL1),
     121             :     L(LOCAL2),
     122             :     L(LOCAL3),
     123             :     L(LOCAL4),
     124             :     L(LOCAL5),
     125             :     L(LOCAL6),
     126             :     L(LOCAL7),
     127             :     { NULL, -1 }
     128             : };
     129             : 
     130             : static int
     131           0 : find_value(const char *s, struct s2i *table)
     132             : {
     133           0 :     while (table->s && strcasecmp(table->s, s) != 0)
     134           0 :         table++;
     135           0 :     return table->val;
     136             : }
     137             : 
     138             : heim_error_code
     139      553465 : heim_initlog(heim_context context,
     140             :              const char *program,
     141             :              heim_log_facility **fac)
     142             : {
     143      553465 :     heim_log_facility *f = calloc(1, sizeof(*f));
     144      553465 :     if (f == NULL)
     145           0 :         return heim_enomem(context);
     146      553465 :     f->refs = 1;
     147      553465 :     f->program = strdup(program);
     148      553465 :     if (f->program == NULL) {
     149           0 :         free(f);
     150           0 :         return heim_enomem(context);
     151             :     }
     152      553465 :     *fac = f;
     153      553465 :     return 0;
     154             : }
     155             : 
     156             : heim_log_facility *
     157           0 : heim_log_ref(heim_log_facility *fac)
     158             : {
     159           0 :     if (fac)
     160           0 :         (void) heim_base_atomic_inc_32(&fac->refs);
     161           0 :     return fac;
     162             : }
     163             : 
     164             : heim_error_code
     165      553460 : heim_addlog_func(heim_context context,
     166             :                  heim_log_facility *fac,
     167             :                  int min,
     168             :                  int max,
     169             :                  heim_log_log_func_t log_func,
     170             :                  heim_log_close_func_t close_func,
     171             :                  void *data)
     172             : {
     173      553460 :     struct heim_log_facility_internal *fp = log_realloc(fac);
     174      553460 :     if (fp == NULL)
     175           0 :         return heim_enomem(context);
     176      553460 :     fp->min = min;
     177      553460 :     fp->max = max;
     178      553460 :     fp->log_func = log_func;
     179      553460 :     fp->close_func = close_func;
     180      553460 :     fp->data = data;
     181      553460 :     return 0;
     182             : }
     183             : 
     184             : 
     185             : struct _heimdal_syslog_data{
     186             :     int priority;
     187             : };
     188             : 
     189             : static void HEIM_CALLCONV
     190           0 : log_syslog(heim_context context, const char *timestr,
     191             :            const char *msg, void *data)
     192             : {
     193           0 :     struct _heimdal_syslog_data *s = data;
     194           0 :     syslog(s->priority, "%s", msg);
     195           0 : }
     196             : 
     197             : static void HEIM_CALLCONV
     198           0 : close_syslog(void *data)
     199             : {
     200           0 :     free(data);
     201           0 :     closelog();
     202           0 : }
     203             : 
     204             : static heim_error_code
     205           0 : open_syslog(heim_context context,
     206             :             heim_log_facility *facility, int min, int max,
     207             :             const char *sev, const char *fac)
     208             : {
     209           0 :     struct _heimdal_syslog_data *sd;
     210           0 :     heim_error_code ret;
     211           0 :     int i;
     212             : 
     213           0 :     if (facility == NULL)
     214           0 :         return EINVAL;
     215           0 :     if ((sd = calloc(1, sizeof(*sd))) == NULL)
     216           0 :         return heim_enomem(context);
     217           0 :     i = find_value(sev, syslogvals);
     218           0 :     if (i == -1)
     219           0 :         i = LOG_ERR;
     220           0 :     sd->priority = i;
     221           0 :     i = find_value(fac, syslogvals);
     222           0 :     if (i == -1)
     223           0 :         i = LOG_AUTH;
     224           0 :     sd->priority |= i;
     225           0 :     roken_openlog(facility->program, LOG_PID | LOG_NDELAY, i);
     226           0 :     ret = heim_addlog_func(context, facility, min, max, log_syslog,
     227             :                            close_syslog, sd);
     228           0 :     if (ret)
     229           0 :         free(sd);
     230             :     else
     231           0 :         sd = NULL;
     232           0 :     return ret;
     233             : }
     234             : 
     235             : struct file_data {
     236             :     char *filename;
     237             :     const char *mode;
     238             :     struct timeval tv;
     239             :     FILE *fd;
     240             :     int disp;
     241             : #define FILEDISP_KEEPOPEN       0x1
     242             : #define FILEDISP_REOPEN         0x2
     243             : #define FILEDISP_IFEXISTS       0x4
     244             : };
     245             : 
     246             : #ifndef O_CLOEXEC
     247             : #define O_CLOEXEC 0
     248             : #endif
     249             : 
     250             : static void HEIM_CALLCONV
     251           0 : log_file(heim_context context, const char *timestr, const char *msg, void *data)
     252             : {
     253           0 :     struct timeval tv;
     254           0 :     struct file_data *f = data;
     255           0 :     FILE *logf = f->fd;
     256           0 :     char *msgclean;
     257           0 :     size_t i = 0;
     258           0 :     size_t j;
     259             : 
     260           0 :     if (f->filename && (logf == NULL || (f->disp & FILEDISP_REOPEN))) {
     261           0 :         int flags = O_WRONLY|O_APPEND;
     262           0 :         int fd;
     263             : 
     264           0 :         if (f->mode[0] == 'e') {
     265           0 :             flags |= O_CLOEXEC;
     266           0 :             i = 1;
     267             :         }
     268           0 :         if (f->mode[i] == 'w')
     269           0 :             flags |= O_TRUNC;
     270           0 :         if (f->mode[i + 1] == '+')
     271           0 :             flags |= O_RDWR;
     272             : 
     273           0 :         if (f->disp & FILEDISP_IFEXISTS) {
     274             :             /* Cache failure for 1s */
     275           0 :             gettimeofday(&tv, NULL);
     276           0 :             if (tv.tv_sec == f->tv.tv_sec)
     277           0 :                 return;
     278             :         } else {
     279           0 :             flags |= O_CREAT;
     280             :         }
     281             : 
     282           0 :         fd = open(f->filename, flags, 0666); /* umask best be set */
     283           0 :         if (fd == -1) {
     284           0 :             if (f->disp & FILEDISP_IFEXISTS)
     285           0 :                 gettimeofday(&f->tv, NULL);
     286           0 :             return;
     287             :         }
     288           0 :         rk_cloexec(fd);
     289           0 :         logf = fdopen(fd, f->mode);
     290             :     }
     291           0 :     if (f->fd == NULL && (f->disp & FILEDISP_KEEPOPEN))
     292           0 :         f->fd = logf;
     293           0 :     if (logf == NULL)
     294           0 :         return;
     295             :     /*
     296             :      * make sure the log doesn't contain special chars:
     297             :      * we used to use strvisx(3) to encode the log, but this is
     298             :      * inconsistent with our syslog(3) code which does not do this.
     299             :      * It also makes it inelegant to write data which has already
     300             :      * been quoted such as what krb5_unparse_principal() gives us.
     301             :      * So, we change here to eat the special characters, instead.
     302             :      */
     303           0 :     if (msg && (msgclean = strdup(msg))) {
     304           0 :         for (i = 0, j = 0; msg[i]; i++)
     305           0 :             if (msg[i] >= 32 || msg[i] == '\t')
     306           0 :                 msgclean[j++] = msg[i];
     307           0 :         fprintf(logf, "%s %s\n", timestr ? timestr : "", msgclean);
     308           0 :         free(msgclean);
     309             :     }
     310           0 :     if (logf != f->fd)
     311           0 :         fclose(logf);
     312             : }
     313             : 
     314             : static void HEIM_CALLCONV
     315           0 : close_file(void *data)
     316             : {
     317           0 :     struct file_data *f = data;
     318           0 :     if (f->fd && f->fd != stdout && f->fd != stderr)
     319           0 :         fclose(f->fd);
     320           0 :     free(f->filename);
     321           0 :     free(data);
     322           0 : }
     323             : 
     324             : static heim_error_code
     325           0 : open_file(heim_context context, heim_log_facility *fac, int min, int max,
     326             :           const char *filename, const char *mode, FILE *f, int disp,
     327             :           int exp_tokens)
     328             : {
     329           0 :     heim_error_code ret = 0;
     330           0 :     struct file_data *fd;
     331             : 
     332           0 :     if ((fd = calloc(1, sizeof(*fd))) == NULL)
     333           0 :         return heim_enomem(context);
     334             : 
     335           0 :     fd->filename = NULL;
     336           0 :     fd->mode = mode;
     337           0 :     fd->fd = f;
     338           0 :     fd->disp = disp;
     339             : 
     340           0 :     if (filename) {
     341           0 :         if (exp_tokens)
     342           0 :             ret = heim_expand_path_tokens(context, filename, 1, &fd->filename, NULL);
     343           0 :         else if ((fd->filename = strdup(filename)) == NULL)
     344           0 :             ret = heim_enomem(context);
     345             :     }
     346           0 :     if (ret == 0)
     347           0 :         ret = heim_addlog_func(context, fac, min, max, log_file, close_file, fd);
     348           0 :     if (ret) {
     349           0 :         free(fd->filename);
     350           0 :         free(fd);
     351           0 :     } else if (disp & FILEDISP_KEEPOPEN) {
     352           0 :         log_file(context, NULL, NULL, fd);
     353           0 :         fd = NULL;
     354             :     }
     355           0 :     return ret;
     356             : }
     357             : 
     358             : heim_error_code
     359           9 : heim_addlog_dest(heim_context context, heim_log_facility *f, const char *orig)
     360             : {
     361           9 :     heim_error_code ret = 0;
     362           9 :     int min = 0, max = 3, n;
     363           0 :     char c;
     364           9 :     const char *p = orig;
     365             : #ifdef _WIN32
     366             :     const char *q;
     367             : #endif
     368             : 
     369           9 :     n = sscanf(p, "%d%c%d/", &min, &c, &max);
     370           9 :     if (n == 2) {
     371           0 :         if (ISPATHSEP(c)) {
     372           0 :             if (min < 0) {
     373           0 :                 max = -min;
     374           0 :                 min = 0;
     375             :             } else {
     376           0 :                 max = min;
     377             :             }
     378             :         }
     379           0 :         if (c == '-')
     380           0 :             max = -1;
     381             :     }
     382           9 :     if (n) {
     383             : #ifdef _WIN32
     384             :         q = strrchr(p, '\\');
     385             :         if (q != NULL)
     386             :             p = q;
     387             :         else
     388             : #endif
     389           0 :             p = strchr(p, '/');
     390           0 :         if (p == NULL) {
     391           0 :             heim_set_error_message(context, EINVAL /*XXX HEIM_ERR_LOG_PARSE*/,
     392           0 :                                    N_("failed to parse \"%s\"", ""), orig);
     393           0 :             return EINVAL /*XXX HEIM_ERR_LOG_PARSE*/;
     394             :         }
     395           0 :         p++;
     396             :     }
     397           9 :     if (strcmp(p, "STDERR") == 0) {
     398           0 :         ret = open_file(context, f, min, max, NULL, "a", stderr,
     399             :                         FILEDISP_KEEPOPEN, 0);
     400           9 :     } else if (strcmp(p, "CONSOLE") == 0) {
     401             :         /* XXX WIN32 */
     402           0 :         ret = open_file(context, f, min, max, "/dev/console", "w", NULL,
     403             :                         FILEDISP_KEEPOPEN, 0);
     404           9 :     } else if (strncmp(p, "EFILE:", 5) == 0) {
     405           0 :         ret = open_file(context, f, min, max, p + sizeof("EFILE:") - 1, "a",
     406             :                         NULL, FILEDISP_IFEXISTS | FILEDISP_REOPEN, 1);
     407           9 :     } else if (strncmp(p, "EFILE=", 5) == 0) {
     408           0 :         ret = open_file(context, f, min, max, p + sizeof("EFILE=") - 1, "a",
     409             :                         NULL, FILEDISP_IFEXISTS | FILEDISP_KEEPOPEN, 1);
     410           9 :     } else if (strncmp(p, "FILE:", sizeof("FILE:") - 1) == 0) {
     411           0 :         ret = open_file(context, f, min, max, p + sizeof("FILE:") - 1, "a",
     412             :                         NULL, FILEDISP_REOPEN, 1);
     413           9 :     } else if (strncmp(p, "FILE=", sizeof("FILE=") - 1) == 0) {
     414           0 :         ret = open_file(context, f, min, max, p + sizeof("FILE=") - 1, "a",
     415             :                         NULL, FILEDISP_KEEPOPEN, 1);
     416           9 :     } else if (strncmp(p, "DEVICE:", sizeof("DEVICE:") - 1) == 0) {
     417           0 :         ret = open_file(context, f, min, max, p + sizeof("DEVICE:") - 1, "a",
     418             :                         NULL, FILEDISP_REOPEN, 0);
     419           9 :     } else if (strncmp(p, "DEVICE=", sizeof("DEVICE=") - 1) == 0) {
     420           0 :         ret = open_file(context, f, min, max, p + sizeof("DEVICE=") - 1, "a",
     421             :                         NULL, FILEDISP_KEEPOPEN, 0);
     422           9 :     } else if (strncmp(p, "SYSLOG", 6) == 0 && (p[6] == '\0' || p[6] == ':')) {
     423           0 :         char severity[128] = "";
     424           0 :         char facility[128] = "";
     425           0 :         p += 6;
     426           0 :         if (*p != '\0')
     427           0 :             p++;
     428           0 :         if (strsep_copy(&p, ":", severity, sizeof(severity)) != -1)
     429           0 :             strsep_copy(&p, ":", facility, sizeof(facility));
     430           0 :         if (*severity == '\0')
     431           0 :             strlcpy(severity, "ERR", sizeof(severity));
     432           0 :         if (*facility == '\0')
     433           0 :             strlcpy(facility, "AUTH", sizeof(facility));
     434           0 :         ret = open_syslog(context, f, min, max, severity, facility);
     435             :     } else {
     436           9 :         ret = EINVAL; /*XXX HEIM_ERR_LOG_PARSE*/
     437           9 :         heim_set_error_message(context, ret,
     438           9 :                                N_("unknown log type: %s", ""), p);
     439             :     }
     440           9 :     return ret;
     441             : }
     442             : 
     443             : heim_error_code
     444           0 : heim_openlog(heim_context context,
     445             :              const char *program,
     446             :              const char **specs,
     447             :              heim_log_facility **fac)
     448             : {
     449           0 :     heim_error_code ret;
     450             : 
     451           0 :     ret = heim_initlog(context, program, fac);
     452           0 :     if (ret)
     453           0 :         return ret;
     454             : 
     455           0 :     if (specs) {
     456             :         size_t i;
     457           0 :         for (i = 0; specs[i] && ret == 0; i++)
     458           0 :             ret = heim_addlog_dest(context, *fac, specs[i]);
     459             :     } else {
     460           0 :         ret = heim_addlog_dest(context, *fac, "SYSLOG");
     461             :     }
     462           0 :     return ret;
     463             : }
     464             : 
     465             : void
     466     5070293 : heim_closelog(heim_context context, heim_log_facility *fac)
     467             : {
     468      120600 :     int i;
     469             : 
     470     5070293 :     if (!fac || heim_base_atomic_dec_32(&fac->refs))
     471     4519021 :         return;
     472     1102539 :     for (i = 0; i < fac->len; i++)
     473      551267 :         (*fac->val[i].close_func)(fac->val[i].data);
     474      551272 :     free(fac->val);
     475      551272 :     free(fac->program);
     476      551272 :     fac->val = NULL;
     477      551272 :     fac->len = 0;
     478      551272 :     fac->program = NULL;
     479      551272 :     free(fac);
     480      551272 :     return;
     481             : }
     482             : 
     483             : static void
     484     2182483 : format_time(heim_context context, time_t t, char *s, size_t len)
     485             : {
     486     2182483 :     struct tm *tm = heim_context_get_log_utc(context) ?
     487     2182483 :         gmtime(&t) : localtime(&t);
     488     2182483 :     if (tm && strftime(s, len, heim_context_get_time_fmt(context), tm))
     489     2105448 :         return;
     490           0 :     snprintf(s, len, "%ld", (long)t);
     491             : }
     492             : 
     493             : #undef __attribute__
     494             : #define __attribute__(X)
     495             : 
     496             : heim_error_code
     497     2182602 : heim_vlog_msg(heim_context context,
     498             :               heim_log_facility *fac,
     499             :               char **reply,
     500             :               int level,
     501             :               const char *fmt,
     502             :               va_list ap)
     503             : __attribute__ ((__format__ (__printf__, 5, 0)))
     504             : {
     505             : 
     506     2182602 :     char *msg = NULL;
     507     2182602 :     const char *actual = NULL;
     508       77035 :     char buf[64];
     509     2182602 :     time_t t = 0;
     510       77035 :     int i;
     511             : 
     512     2182602 :     if (!fac)
     513           0 :         fac = context->log_dest;
     514     4365085 :     for (i = 0; fac && i < fac->len; i++)
     515     2182483 :         if (fac->val[i].min <= level &&
     516     2182483 :             (fac->val[i].max < 0 || fac->val[i].max >= level)) {
     517     2182483 :             if (t == 0) {
     518     2182483 :                 t = time(NULL);
     519     2182483 :                 format_time(context, t, buf, sizeof(buf));
     520             :             }
     521     2182483 :             if (actual == NULL) {
     522     2182483 :                 int ret = vasprintf(&msg, fmt, ap);
     523     2182483 :                 if (ret < 0 || msg == NULL)
     524           0 :                     actual = fmt;
     525             :                 else
     526     2182483 :                     actual = msg;
     527             :             }
     528     2182483 :             (*fac->val[i].log_func)(context, buf, actual, fac->val[i].data);
     529             :         }
     530     2182602 :     if (reply == NULL)
     531     1145534 :         free(msg);
     532             :     else
     533     1037068 :         *reply = msg;
     534     2182602 :     return 0;
     535             : }
     536             : 
     537             : heim_error_code
     538     1145534 : heim_vlog(heim_context context,
     539             :           heim_log_facility *fac,
     540             :           int level,
     541             :           const char *fmt,
     542             :           va_list ap)
     543             : __attribute__ ((__format__ (__printf__, 4, 0)))
     544             : {
     545     1145534 :     return heim_vlog_msg(context, fac, NULL, level, fmt, ap);
     546             : }
     547             : 
     548             : heim_error_code
     549           0 : heim_log_msg(heim_context context,
     550             :              heim_log_facility *fac,
     551             :              int level,
     552             :              char **reply,
     553             :              const char *fmt,
     554             :              ...)
     555             : __attribute__ ((__format__ (__printf__, 5, 6)))
     556             : {
     557           0 :     va_list ap;
     558           0 :     heim_error_code ret;
     559             : 
     560           0 :     va_start(ap, fmt);
     561           0 :     ret = heim_vlog_msg(context, fac, reply, level, fmt, ap);
     562           0 :     va_end(ap);
     563           0 :     return ret;
     564             : }
     565             : 
     566             : 
     567             : heim_error_code
     568     1145415 : heim_log(heim_context context,
     569             :          heim_log_facility *fac,
     570             :          int level,
     571             :          const char *fmt,
     572             :          ...)
     573             : __attribute__ ((__format__ (__printf__, 4, 5)))
     574             : {
     575       40468 :     va_list ap;
     576       40468 :     heim_error_code ret;
     577             : 
     578     1145415 :     va_start(ap, fmt);
     579     1145415 :     ret = heim_vlog(context, fac, level, fmt, ap);
     580     1145415 :     va_end(ap);
     581     1145415 :     return ret;
     582             : }
     583             : 
     584             : void
     585     2993107 : heim_debug(heim_context context,
     586             :            int level,
     587             :            const char *fmt,
     588             :            ...)
     589             : __attribute__ ((__format__ (__printf__, 3, 4)))
     590             : {
     591       66191 :     heim_log_facility *fac;
     592       66191 :     va_list ap;
     593             : 
     594     5920023 :     if (context == NULL ||
     595     2993107 :         (fac = heim_get_debug_dest(context)) == NULL)
     596     2993086 :         return;
     597             : 
     598          21 :     va_start(ap, fmt);
     599          21 :     heim_vlog(context, fac, level, fmt, ap);
     600          21 :     va_end(ap);
     601             : }
     602             : 
     603             : void
     604     2159274 : heim_vdebug(heim_context context,
     605             :             int level,
     606             :             const char *fmt,
     607             :             va_list ap)
     608             : __attribute__ ((__format__ (__printf__, 3, 0)))
     609             : {
     610       56821 :     heim_log_facility *fac;
     611             : 
     612     4261727 :     if (context == NULL ||
     613     2159274 :         (fac = heim_get_debug_dest(context)) == NULL)
     614     2159176 :         return;
     615             : 
     616          98 :     heim_vlog(context, fac, level, fmt, ap);
     617             : }
     618             : 
     619             : heim_error_code
     620      711494 : heim_have_debug(heim_context context, int level)
     621             : {
     622      711494 :     return (context != NULL && heim_get_debug_dest(context) != NULL);
     623             : }
     624             : 
     625             : heim_error_code
     626           0 : heim_add_warn_dest(heim_context context, const char *program,
     627             :                    const char *log_spec)
     628             : {
     629           0 :     heim_log_facility *fac;
     630             : 
     631           0 :     heim_error_code ret;
     632             : 
     633           0 :     if ((fac = heim_get_warn_dest(context)) == NULL) {
     634           0 :         ret = heim_initlog(context, program, &fac);
     635           0 :         if (ret)
     636           0 :             return ret;
     637           0 :         heim_set_warn_dest(context, fac);
     638             :     }
     639             : 
     640           0 :     ret = heim_addlog_dest(context, fac, log_spec);
     641           0 :     if (ret)
     642           0 :         return ret;
     643           0 :     return 0;
     644             : }
     645             : 
     646             : heim_error_code
     647           9 : heim_add_debug_dest(heim_context context, const char *program,
     648             :                     const char *log_spec)
     649             : {
     650           0 :     heim_log_facility *fac;
     651           0 :     heim_error_code ret;
     652             : 
     653           9 :     if ((fac = heim_get_debug_dest(context)) == NULL) {
     654           5 :         ret = heim_initlog(context, program, &fac);
     655           5 :         if (ret)
     656           0 :             return ret;
     657           5 :         heim_set_debug_dest(context, fac);
     658             :     }
     659             : 
     660           9 :     ret = heim_addlog_dest(context, fac, log_spec);
     661           9 :     if (ret)
     662           9 :         return ret;
     663           0 :     return 0;
     664             : }
     665             : 
     666             : struct heim_audit_kv_tuple {
     667             :     heim_string_t key;
     668             :     heim_object_t value;
     669             : };
     670             : 
     671             : static struct heim_audit_kv_tuple zero_tuple;
     672             : 
     673             : static struct heim_audit_kv_tuple
     674      572097 : fmtkv(int flags, const char *k, const char *fmt, va_list ap)
     675             :         __attribute__ ((__format__ (__printf__, 3, 0)))
     676             : {
     677       20478 :     size_t i;
     678       20478 :     ssize_t j;
     679       20478 :     struct heim_audit_kv_tuple kv;
     680       20478 :     char *value;
     681       20478 :     char *value_vis;
     682             : 
     683      572097 :     j = vasprintf(&value, fmt, ap);
     684      572097 :     if (j < 0 || value == NULL)
     685           0 :         return zero_tuple;
     686             : 
     687             :     /* We optionally eat the whitespace. */
     688             : 
     689      572097 :     if (flags & HEIM_SVC_AUDIT_EATWHITE) {
     690     3870319 :         for (i=0, j=0; value[i]; i++)
     691     3670621 :             if (value[i] != ' ' && value[i] != '\t')
     692     3578187 :                 value[j++] = value[i];
     693      199698 :         value[j] = '\0';
     694             :     }
     695             : 
     696      572097 :     if (flags & (HEIM_SVC_AUDIT_VIS | HEIM_SVC_AUDIT_VISLAST)) {
     697       63285 :         int vis_flags = VIS_CSTYLE | VIS_OCTAL | VIS_NL;
     698             : 
     699       63285 :         if (flags & HEIM_SVC_AUDIT_VIS)
     700       61455 :             vis_flags |= VIS_WHITE;
     701       63285 :         value_vis = malloc((j + 1) * 4 + 1);
     702       63285 :         if (value_vis)
     703       63285 :             strvisx(value_vis, value, j, vis_flags);
     704       63285 :         free(value);
     705       63285 :         if (value_vis == NULL)
     706           0 :             return zero_tuple;
     707             :     } else
     708      508812 :         value_vis = value;
     709             : 
     710      572097 :     if (k)
     711      570267 :         kv.key = heim_string_create(k);
     712             :     else
     713        1830 :         kv.key = NULL;
     714      572097 :     kv.value = heim_string_ref_create(value_vis, free);
     715             : 
     716      572097 :     return kv;
     717             : }
     718             : 
     719             : void
     720        1830 : heim_audit_vaddreason(heim_svc_req_desc r, const char *fmt, va_list ap)
     721             :         __attribute__ ((__format__ (__printf__, 2, 0)))
     722             : {
     723           0 :     struct heim_audit_kv_tuple kv;
     724             : 
     725        1830 :     kv = fmtkv(HEIM_SVC_AUDIT_VISLAST, NULL, fmt, ap);
     726        1830 :     if (kv.value == NULL) {
     727           0 :         heim_log(r->hcontext, r->logf, 1, "heim_audit_vaddreason: "
     728             :                  "failed to add reason (out of memory)");
     729           0 :         return;
     730             :     }
     731             : 
     732        1830 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_vaddreason(): "
     733        1830 :              "adding reason %s", heim_string_get_utf8(kv.value));
     734        1830 :     if (r->reason) {
     735           0 :         heim_string_t str2;
     736             : 
     737          12 :         str2 = heim_string_create_with_format("%s: %s",
     738           6 :                                               heim_string_get_utf8(kv.value),
     739             :                                               heim_string_get_utf8(r->reason));
     740           6 :         if (str2) {
     741           6 :             heim_release(kv.value);
     742           6 :             kv.value = str2;
     743             :         }
     744             :     }
     745        1830 :     heim_release(r->reason);
     746        1830 :     r->reason = kv.value;
     747             : }
     748             : 
     749             : void
     750           0 : heim_audit_addreason(heim_svc_req_desc r, const char *fmt, ...)
     751             :         __attribute__ ((__format__ (__printf__, 2, 3)))
     752             : {
     753           0 :     va_list ap;
     754             : 
     755           0 :     va_start(ap, fmt);
     756           0 :     heim_audit_vaddreason(r, fmt, ap);
     757           0 :     va_end(ap);
     758           0 : }
     759             : 
     760             : size_t
     761      570267 : addkv(heim_svc_req_desc r, heim_object_t key, heim_object_t value)
     762             : {
     763       20478 :     size_t index;
     764       20478 :     heim_object_t obj;
     765             : 
     766      570267 :     obj = heim_dict_get_value(r->kv, key);
     767      570267 :     if (obj) {
     768           0 :         if (heim_get_tid(obj) == HEIM_TID_ARRAY) {
     769           0 :             index = heim_array_get_length(obj);
     770           0 :             heim_array_append_value(obj, value);
     771             :         } else {
     772           0 :             heim_array_t array = heim_array_create();
     773             : 
     774           0 :             index = 1;
     775           0 :             heim_array_append_value(array, obj);
     776           0 :             heim_array_append_value(array, value);
     777           0 :             heim_dict_set_value(r->kv, key, array);
     778           0 :             heim_release(array); /* retained by r->kv */
     779             :         }
     780             :     } else {
     781      570267 :         index = 0;
     782      570267 :         heim_dict_set_value(r->kv, key, value);
     783             :     }
     784             : 
     785      570267 :     return index;
     786             : }
     787             : 
     788             : /*
     789             :  * add a key-value token. if the key already exists, the value is
     790             :  * promoted to an array of values.
     791             :  */
     792             : 
     793             : void
     794      570267 : heim_audit_vaddkv(heim_svc_req_desc r, int flags, const char *k,
     795             :                   const char *fmt, va_list ap)
     796             :         __attribute__ ((__format__ (__printf__, 4, 0)))
     797             : {
     798       20478 :     struct heim_audit_kv_tuple kv;
     799       20478 :     size_t index;
     800             : 
     801      570267 :     kv = fmtkv(flags, k, fmt, ap);
     802      570267 :     if (kv.key == NULL || kv.value == NULL) {
     803           0 :         heim_log(r->hcontext, r->logf, 1, "heim_audit_vaddkv: "
     804             :                  "failed to add kv pair (out of memory)");
     805           0 :         heim_release(kv.key);
     806           0 :         heim_release(kv.value);
     807           0 :         return;
     808             :     }
     809             : 
     810      570267 :     index = addkv(r, kv.key, kv.value);
     811             : 
     812      570267 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_vaddkv(): "
     813             :              "kv pair[%zu] %s=%s", index,
     814      549789 :              heim_string_get_utf8(kv.key), heim_string_get_utf8(kv.value));
     815             : 
     816      570267 :     heim_release(kv.key);
     817      570267 :     heim_release(kv.value);
     818             : }
     819             : 
     820             : void
     821      135405 : heim_audit_addkv(heim_svc_req_desc r, int flags, const char *k,
     822             :                  const char *fmt, ...)
     823             :         __attribute__ ((__format__ (__printf__, 4, 5)))
     824             : {
     825        4583 :     va_list ap;
     826             : 
     827      135405 :     va_start(ap, fmt);
     828      135405 :     heim_audit_vaddkv(r, flags, k, fmt, ap);
     829      135405 :     va_end(ap);
     830      135405 : }
     831             : 
     832             : void
     833      104689 : heim_audit_addkv_timediff(heim_svc_req_desc r, const char *k,
     834             :                           const struct timeval *start,
     835             :                           const struct timeval *end)
     836             : {
     837        3413 :     time_t sec;
     838        3413 :     int usec;
     839      104689 :     const char *sign = "";
     840             : 
     841      104689 :     if (end->tv_sec > start->tv_sec ||
     842      103787 :         (end->tv_sec == start->tv_sec && end->tv_usec >= start->tv_usec)) {
     843      104689 :         sec  = end->tv_sec  - start->tv_sec;
     844      104689 :         usec = end->tv_usec - start->tv_usec;
     845             :     } else {
     846           0 :         sec  = start->tv_sec  - end->tv_sec;
     847           0 :         usec = start->tv_usec - end->tv_usec;
     848           0 :         sign = "-";
     849             :     }
     850             : 
     851      104689 :     if (usec < 0) {
     852         894 :         usec += 1000000;
     853         894 :         sec  -= 1;
     854             :     }
     855             : 
     856      104689 :     heim_audit_addkv(r, 0, k, "%s%ld.%06d", sign, (long)sec, usec);
     857      104689 : }
     858             : 
     859             : void
     860           0 : heim_audit_setkv_bool(heim_svc_req_desc r, const char *k, int v)
     861             : {
     862           0 :     heim_string_t key = heim_string_create(k);
     863           0 :     heim_number_t value;
     864             : 
     865           0 :     if (key == NULL)
     866           0 :         return;
     867             : 
     868           0 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_setkv_bool(): "
     869             :              "setting kv pair %s=%s", k, v ? "true" : "false");
     870             : 
     871           0 :     value = heim_bool_create(v);
     872           0 :     heim_dict_set_value(r->kv, key, value);
     873           0 :     heim_release(key);
     874           0 :     heim_release(value);
     875             : }
     876             : 
     877             : void
     878           0 : heim_audit_addkv_number(heim_svc_req_desc r, const char *k, int64_t v)
     879             : {
     880           0 :     heim_string_t key = heim_string_create(k);
     881           0 :     heim_number_t value;
     882             : 
     883           0 :     if (key == NULL)
     884           0 :         return;
     885             : 
     886           0 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_addkv_number(): "
     887             :              "adding kv pair %s=%lld", k, (long long)v);
     888             : 
     889           0 :     value = heim_number_create(v);
     890           0 :     addkv(r, key, value);
     891           0 :     heim_release(key);
     892           0 :     heim_release(value);
     893             : }
     894             : 
     895             : void
     896      467180 : heim_audit_setkv_number(heim_svc_req_desc r, const char *k, int64_t v)
     897             : {
     898      467180 :     heim_string_t key = heim_string_create(k);
     899       16577 :     heim_number_t value;
     900             : 
     901      467180 :     if (key == NULL)
     902           0 :         return;
     903             : 
     904      467180 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_setkv_number(): "
     905             :              "setting kv pair %s=%lld", k, (long long)v);
     906             : 
     907      467180 :     value = heim_number_create(v);
     908      467180 :     heim_dict_set_value(r->kv, key, value);
     909      467180 :     heim_release(key);
     910      467180 :     heim_release(value);
     911             : }
     912             : 
     913             : void
     914           0 : heim_audit_addkv_object(heim_svc_req_desc r, const char *k, heim_object_t value)
     915             : {
     916           0 :     heim_string_t key = heim_string_create(k);
     917           0 :     heim_string_t descr;
     918             : 
     919           0 :     if (key == NULL)
     920           0 :         return;
     921             : 
     922           0 :     descr = heim_json_copy_serialize(value, HEIM_JSON_F_NO_DATA_DICT, NULL);
     923           0 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_addkv_object(): "
     924             :              "adding kv pair %s=%s",
     925           0 :              k, descr ? heim_string_get_utf8(descr) : "<unprintable>");
     926           0 :     addkv(r, key, value);
     927           0 :     heim_release(key);
     928           0 :     heim_release(descr);
     929             : }
     930             : 
     931             : void
     932         679 : heim_audit_setkv_object(heim_svc_req_desc r, const char *k, heim_object_t value)
     933             : {
     934         679 :     heim_string_t key = heim_string_create(k);
     935           0 :     heim_string_t descr;
     936             : 
     937         679 :     if (key == NULL)
     938           0 :         return;
     939             : 
     940         679 :     descr = heim_json_copy_serialize(value, HEIM_JSON_F_NO_DATA_DICT, NULL);
     941         679 :     heim_log(r->hcontext, r->logf, 7, "heim_audit_setkv_object(): "
     942             :              "setting kv pair %s=%s",
     943           0 :              k, descr ? heim_string_get_utf8(descr) : "<unprintable>");
     944         679 :     heim_dict_set_value(r->kv, key, value);
     945         679 :     heim_release(key);
     946         679 :     heim_release(descr);
     947             : }
     948             : 
     949             : heim_object_t
     950      393593 : heim_audit_getkv(heim_svc_req_desc r, const char *k)
     951             : {
     952       13846 :     heim_string_t key;
     953       13846 :     heim_object_t value;
     954             : 
     955      393593 :     key = heim_string_create(k);
     956      393593 :     if (key == NULL)
     957           0 :         return NULL;
     958             : 
     959      393593 :     value = heim_dict_get_value(r->kv, key);
     960      393593 :     heim_release(key);
     961      393593 :     return value;
     962             : }
     963             : 
     964             : struct heim_audit_kv_buf {
     965             :     char buf[1024];
     966             :     size_t pos;
     967             :     heim_object_t iter;
     968             : };
     969             : 
     970             : static void
     971             : audit_trail_iterator(heim_object_t key, heim_object_t value, void *arg);
     972             : 
     973             : static void
     974           0 : audit_trail_iterator_array(heim_object_t value, void *arg, int *stop)
     975             : {
     976           0 :     struct heim_audit_kv_buf *kvb = arg;
     977             : 
     978           0 :     audit_trail_iterator(kvb->iter, value, kvb);
     979           0 : }
     980             : 
     981             : static void
     982      977097 : audit_trail_iterator(heim_object_t key, heim_object_t value, void *arg)
     983             : {
     984      977097 :     struct heim_audit_kv_buf *kvb = arg;
     985       34715 :     char num[32];
     986      977097 :     const char *k = heim_string_get_utf8(key), *v = NULL;
     987      977097 :     char *b64 = NULL;
     988             : 
     989      977097 :     if (k == NULL || *k == '#') /* # keys are hidden */
     990       50659 :         return;
     991             : 
     992      927117 :     switch (heim_get_tid(value)) {
     993      570267 :     case HEIM_TID_STRING:
     994      570267 :         v = heim_string_get_utf8(value);
     995      570267 :         break;
     996      356171 :     case HEIM_TID_NUMBER:
     997      356171 :         snprintf(num, sizeof(num), "%lld", (long long)heim_number_get_long(value));
     998      356171 :         v = num;
     999      356171 :         break;
    1000           0 :     case HEIM_TID_NULL:
    1001           0 :         v = "null";
    1002           0 :         break;
    1003           0 :     case HEIM_TID_BOOL:
    1004           0 :         v = heim_bool_val(value) ? "true" : "false";
    1005           0 :         break;
    1006           0 :     case HEIM_TID_ARRAY:
    1007           0 :         if (kvb->iter)
    1008           0 :             break; /* arrays cannot be nested */
    1009             : 
    1010           0 :         kvb->iter = key;
    1011           0 :         heim_array_iterate_f(value, kvb, audit_trail_iterator_array);
    1012           0 :         kvb->iter = NULL;
    1013           0 :         break;
    1014           0 :     case HEIM_TID_DATA: {
    1015           0 :         const heim_octet_string *data = heim_data_get_data(value);
    1016           0 :         if (rk_base64_encode(data->data, data->length, &b64) >= 0)
    1017           0 :             v = b64;
    1018           0 :         break;
    1019             :     }
    1020         679 :     default:
    1021         679 :         break;
    1022             :     }
    1023             : 
    1024      927117 :     if (v == NULL)
    1025         679 :         return;
    1026             : 
    1027      926438 :     if (kvb->pos < sizeof(kvb->buf) - 1)
    1028      926438 :         kvb->buf[kvb->pos++] = ' ';
    1029     8403448 :     for (; *k && kvb->pos < sizeof(kvb->buf) - 1; kvb->pos++)
    1030     7477010 :         kvb->buf[kvb->pos] = *k++;
    1031      926438 :     if (kvb->pos < sizeof(kvb->buf) - 1)
    1032      926438 :         kvb->buf[kvb->pos++] = '=';
    1033    13715840 :     for (; *v && kvb->pos < sizeof(kvb->buf) - 1; kvb->pos++)
    1034    12789402 :         kvb->buf[kvb->pos] = *v++;
    1035             : 
    1036      926438 :     free(b64);
    1037             : }
    1038             : 
    1039             : void
    1040      104689 : heim_audit_trail(heim_svc_req_desc r, heim_error_code ret, const char *retname)
    1041             : {
    1042        3413 :     const char *retval;
    1043        3413 :     struct heim_audit_kv_buf kvb;
    1044        3413 :     char retvalbuf[30]; /* Enough for UNKNOWN-%d */
    1045             : 
    1046             : #define CASE(x) case x : retval = #x; break
    1047      104689 :     if (retname) {
    1048      100553 :         retval = retname;
    1049         723 :     } else switch (ret ? ret : r->error_code) {
    1050           0 :     CASE(ENOMEM);
    1051           0 :     CASE(ENOENT);
    1052           0 :     CASE(EACCES);
    1053           0 :     case 0:
    1054           0 :         retval = "SUCCESS";
    1055           0 :         break;
    1056         723 :     default:
    1057             :         /* Wish we had a com_err number->symbolic name function */
    1058         723 :         (void) snprintf(retvalbuf, sizeof(retvalbuf), "UNKNOWN-%d",
    1059             :                         ret ? ret : r->error_code);
    1060         723 :         retval = retvalbuf;
    1061         723 :         break;
    1062             :     }
    1063             : 
    1064      104689 :     heim_audit_addkv_timediff(r, "elapsed", &r->tv_start, &r->tv_end);
    1065      104689 :     if (r->e_text && r->kv)
    1066       30716 :         heim_audit_addkv(r, HEIM_SVC_AUDIT_VIS, "e-text", "%s", r->e_text);
    1067             : 
    1068      104689 :     memset(&kvb, 0, sizeof(kvb));
    1069      104689 :     if (r->kv)
    1070      104689 :         heim_dict_iterate_f(r->kv, &kvb, audit_trail_iterator);
    1071      104689 :     kvb.buf[kvb.pos] = '\0';
    1072             : 
    1073      406693 :     heim_log(r->hcontext, r->logf, 3, "%s %s %s %s %s%s%s%s",
    1074             :              r->reqtype, retval, r->from,
    1075      104689 :              r->cname ? r->cname : "<unknown>",
    1076      104689 :              r->sname ? r->sname : "<unknown>",
    1077      104689 :              kvb.buf, r->reason ? " reason=" : "",
    1078      104689 :              r->reason ? heim_string_get_utf8(r->reason) : "");
    1079      104689 : }