kdc: Fix audit_addkv() typos and reason handling

Now we'll put the "reason=..." last in the log lines and we won't escape
spaces -- just newlines and other control characters.  This makes
reading log lines much easier without complicating parsing of log lines
because interior key=value pairs do get whitespace escaped or removed.

kdc/bx509d.c

@@ -442,8 +442,7 @@ bad_reqv(struct bx509_request_desc *r,
         msg = formatted;
         formatted = NULL;
     }
-    _kdc_audit_addkv((kdc_request_t)r, KDC_AUDIT_VIS, "reason", "%s",
+    _kdc_audit_addreason((kdc_request_t)r, "%s", formatted);
-                     formatted);
     _kdc_audit_trail((kdc_request_t)r, code);
     krb5_free_error_message(context, k5msg);
 
@@ -794,6 +793,7 @@ set_req_desc(struct MHD_Connection *connection,
     r->target = r->redir = NULL;
     r->pkix_store = NULL;
     r->freeme1 = NULL;
+    r->reason = NULL;
     r->ccname = NULL;
     r->reply = NULL;
     r->sname = NULL;
@@ -839,6 +839,7 @@ clean_req_desc(struct bx509_request_desc *r)
     if (r->pkix_store)
         (void) unlink(strchr(r->pkix_store, ':') + 1);
     hx509_request_free(&r->req);
+    heim_release(r->reason);
     heim_release(r->kv);
     free(r->pkix_store);
     free(r->freeme1);

kdc/kdc_locl.h

@@ -50,6 +50,7 @@ struct Kx509Request;
 
 #define KDC_AUDIT_EATWHITE	0x1
 #define KDC_AUDIT_VIS		0x2
+#define KDC_AUDIT_VISLAST	0x4
 
 /* KFE == KDC_FIND_ETYPE */
 #define KFE_IS_TGS	0x1
@@ -77,6 +78,7 @@ struct Kx509Request;
     char *sname;						\
     const char *e_text;						\
     char *e_text_buf;						\
+    heim_string_t reason;                                       \
     heim_array_t kv
 
 struct kdc_request_desc {

kdc/kerberos5.c

@@ -1407,7 +1407,8 @@ _log_astgs_req(astgs_request_t r, krb5_enctype setype)
 
     str = rk_strpoolcollect(s);
     if (str)
-	_kdc_audit_addkv((kdc_request_t)r, 0, "etypes", "%s", str);
+        _kdc_audit_addkv((kdc_request_t)r, KDC_AUDIT_EATWHITE, "etypes", "%s",
+                         str);
     free(str);
 
     ret = krb5_enctype_to_string(context, cetype, &cet);
@@ -1461,20 +1462,19 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 
 	/* check client */
 	if (client->flags.locked_out) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Client is locked out");
-			     "Client is locked out");
 	    return KRB5KDC_ERR_POLICY;
 	}
 
 	if (client->flags.invalid) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Client has invalid bit set");
+                                 "Client has invalid bit set");
 	    return KRB5KDC_ERR_POLICY;
 	}
 
 	if (!client->flags.client) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Principal may not act as client");
+                                 "Principal may not act as client");
 	    return KRB5KDC_ERR_POLICY;
 	}
 
@@ -1482,8 +1482,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char starttime_str[100];
 	    krb5_format_time(context, *client->valid_start,
 			     starttime_str, sizeof(starttime_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Client not yet valid "
-			     "Client not yet valid until %s", starttime_str);
+                                 "until %s", starttime_str);
 	    return KRB5KDC_ERR_CLIENT_NOTYET;
 	}
 
@@ -1491,8 +1491,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char endtime_str[100];
 	    krb5_format_time(context, *client->valid_end,
 			     endtime_str, sizeof(endtime_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Client expired at %s",
-			     "Client expired at %s", endtime_str);
+                                 endtime_str);
 	    return  KRB5KDC_ERR_NAME_EXP;
 	}
 
@@ -1505,8 +1505,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char pwend_str[100];
 	    krb5_format_time(context, *client->pw_end,
 			     pwend_str, sizeof(pwend_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Client's key has expired "
-			     "Client's key has expired at %s", pwend_str);
+                                 "at %s", pwend_str);
 	    return KRB5KDC_ERR_KEY_EXPIRED;
 	}
     }
@@ -1517,24 +1517,23 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	hdb_entry *server = &server_ex->entry;
 
 	if (server->flags.locked_out) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Server locked out");
-			     "Server locked out");
 	    return KRB5KDC_ERR_POLICY;
 	}
 	if (server->flags.invalid) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Server has invalid flag set");
+                                 "Server has invalid flag set");
 	    return KRB5KDC_ERR_POLICY;
 	}
 	if (!server->flags.server) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Principal may not act as server");
+                                 "Principal may not act as server");
 	    return KRB5KDC_ERR_POLICY;
 	}
 
 	if (!is_as_req && server->flags.initial) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "AS-REQ is required for server");
+                                 "AS-REQ is required for server");
 	    return KRB5KDC_ERR_POLICY;
 	}
 
@@ -1542,8 +1541,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char starttime_str[100];
 	    krb5_format_time(context, *server->valid_start,
 			     starttime_str, sizeof(starttime_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Server not yet valid "
-			     "Server not yet valid until %s", starttime_str);
+                                 "until %s", starttime_str);
 	    return KRB5KDC_ERR_SERVICE_NOTYET;
 	}
 
@@ -1551,8 +1550,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char endtime_str[100];
 	    krb5_format_time(context, *server->valid_end,
 			     endtime_str, sizeof(endtime_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Server expired at %s",
-			     "Server expired at %s", endtime_str);
+                                 endtime_str);
 	    return KRB5KDC_ERR_SERVICE_EXP;
 	}
 
@@ -1560,8 +1559,8 @@ kdc_check_flags(astgs_request_t r, krb5_boolean is_as_req)
 	    char pwend_str[100];
 	    krb5_format_time(context, *server->pw_end,
 			     pwend_str, sizeof(pwend_str), TRUE);
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r, "Server's key has expired "
-			     "Server's key has expired at %s", pwend_str);
+                                 "at %s", pwend_str);
 	    return KRB5KDC_ERR_KEY_EXPIRED;
 	}
     }
@@ -1623,8 +1622,8 @@ krb5_error_code
 _kdc_check_anon_policy(astgs_request_t r)
 {
     if (!r->config->allow_anonymous) {
-	_kdc_audit_addkv((kdc_request_t)r, 0, "reason", "anonymous tickets "
+	_kdc_audit_addreason((kdc_request_t)r,
-			 "denied by local policy");
+                             "Anonymous tickets denied by local policy");
 	return KRB5KDC_ERR_POLICY;
     }
 
@@ -1951,7 +1950,8 @@ _kdc_as_rep(astgs_request_t r)
 	    i = 0;
 	    pa = _kdc_find_padata(req, &i, pat[n].type);
 	    if (pa) {
-		_kdc_audit_addkv((kdc_request_t)r, 0, "pa", "%s", pat[n].name);
+                _kdc_audit_addkv((kdc_request_t)r, KDC_AUDIT_VIS, "pa", "%s",
+                                 pat[n].name);
 		ret = pat[n].validate(r, pa);
 		if (ret != 0) {
 		    krb5_error_code  ret2;

kdc/krb5tgs.c

@@ -398,35 +398,35 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
 
     if(f.validate){
 	if (!tgt->flags.invalid || tgt->starttime == NULL) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request to validate ticket");
+                                 "Bad request to validate ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	if(*tgt->starttime > kdc_time){
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Early request to validate ticket");
+                                 "Early request to validate ticket");
 	    return KRB5KRB_AP_ERR_TKT_NYV;
 	}
 	/* XXX  tkt = tgt */
 	et->flags.invalid = 0;
     } else if (tgt->flags.invalid) {
-	_kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	_kdc_audit_addreason((kdc_request_t)r,
-			 "Ticket-granting ticket has INVALID flag set");
+                             "Ticket-granting ticket has INVALID flag set");
 	return KRB5KRB_AP_ERR_TKT_INVALID;
     }
 
     if(f.forwardable){
 	if (!tgt->flags.forwardable) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request for forwardable ticket");
+                                 "Bad request for forwardable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.forwardable = 1;
     }
     if(f.forwarded){
 	if (!tgt->flags.forwardable) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Request to forward non-forwardable ticket");
+                                 "Request to forward non-forwardable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.forwarded = 1;
@@ -437,16 +437,16 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
 
     if(f.proxiable){
 	if (!tgt->flags.proxiable) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request for proxiable ticket");
+                                 "Bad request for proxiable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.proxiable = 1;
     }
     if(f.proxy){
 	if (!tgt->flags.proxiable) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Request to proxy non-proxiable ticket");
+                                 "Request to proxy non-proxiable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.proxy = 1;
@@ -457,16 +457,16 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
 
     if(f.allow_postdate){
 	if (!tgt->flags.may_postdate) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request for post-datable ticket");
+                                 "Bad request for post-datable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.may_postdate = 1;
     }
     if(f.postdated){
 	if (!tgt->flags.may_postdate) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request for postdated ticket");
+                                 "Bad request for postdated ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	if(b->from)
@@ -474,15 +474,15 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
 	et->flags.postdated = 1;
 	et->flags.invalid = 1;
     } else if (b->from && *b->from > kdc_time + context->max_skew) {
-	_kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	_kdc_audit_addreason((kdc_request_t)r,
-			 "Ticket cannot be postdated");
+                             "Ticket cannot be postdated");
 	return KRB5KDC_ERR_CANNOT_POSTDATE;
     }
 
     if(f.renewable){
 	if (!tgt->flags.renewable || tgt->renew_till == NULL) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Bad request for renewable ticket");
+                                 "Bad request for renewable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	et->flags.renewable = 1;
@@ -493,8 +493,8 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
     if(f.renew){
 	time_t old_life;
 	if (!tgt->flags.renewable || tgt->renew_till == NULL) {
-	    _kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	    _kdc_audit_addreason((kdc_request_t)r,
-			     "Request to renew non-renewable ticket");
+                                 "Request to renew non-renewable ticket");
 	    return KRB5KDC_ERR_BADOPTION;
 	}
 	old_life = tgt->endtime;
@@ -513,8 +513,8 @@ check_tgs_flags(astgs_request_t r, KDC_REQ_BODY *b,
      */
     if (tgt->flags.anonymous &&
 	!_kdc_is_anonymous(context, tgt_name)) {
-	_kdc_audit_addkv((kdc_request_t)r, 0, "reason",
+	_kdc_audit_addreason((kdc_request_t)r,
-			 "Anonymous ticket flag set without "
+                             "Anonymous ticket flag set without "
 			 "anonymous principal");
 	return KRB5KDC_ERR_BADOPTION;
     }
@@ -2357,7 +2357,7 @@ server_lookup:
 	    goto out;
 	}
 
-	_kdc_audit_addkv((kdc_request_t)priv, 0, "impersonatee", "%s", tpn);
+        _kdc_audit_addkv((kdc_request_t)priv, 0, "impersonatee", "%s", tpn);
 	kdc_log(context, config, 4, "constrained delegation for %s "
 		"from %s (%s) to %s", tpn, cpn, dpn, spn);
     }

kdc/libkdc-exports.def

@@ -17,4 +17,5 @@ EXPORTS
 	krb5_kdc_update_time
 	krb5_kdc_pk_initialize
 	_kdc_audit_addkv
+	_kdc_audit_addreason
 	_kdc_audit_trail

kdc/process.c

@@ -42,6 +42,71 @@
 #undef  __attribute__
 #define __attribute__(x)
 
+static heim_string_t
+fmtkv(int flags, const char *k, const char *fmt, va_list ap)
+        __attribute__ ((__format__ (__printf__, 3, 0)))
+{
+    heim_string_t str;
+    size_t i,j;
+    char *buf1;
+    char *buf2;
+    char *buf3;
+
+    vasprintf(&buf1, fmt, ap);
+    if (!buf1)
+	return NULL;;
+
+    j = asprintf(&buf2, "%s=%s", k, buf1);
+    free(buf1);
+    if (!buf2)
+	return NULL;;
+
+    /* We optionally eat the whitespace. */
+
+    if (flags & KDC_AUDIT_EATWHITE) {
+	for (i=0, j=0; buf2[i]; i++)
+	    if (buf2[i] != ' ' && buf2[i] != '\t')
+		buf2[j++] = buf2[i];
+	buf2[j] = '\0';
+    }
+
+    if (flags & (KDC_AUDIT_VIS | KDC_AUDIT_VISLAST)) {
+        int vis_flags = VIS_CSTYLE | VIS_OCTAL | VIS_NL;
+
+        if (flags & KDC_AUDIT_VIS)
+            vis_flags |= VIS_WHITE;
+	buf3 = malloc((j + 1) * 4 + 1);
+	strvisx(buf3, buf2, j, vis_flags);
+	free(buf2);
+    } else
+	buf3 = buf2;
+
+    str = heim_string_create(buf3);
+    free(buf3);
+    return str;
+}
+
+void
+_kdc_audit_addreason(kdc_request_t r, const char *fmt, ...)
+	__attribute__ ((__format__ (__printf__, 2, 3)))
+{
+    va_list ap;
+    heim_string_t str;
+
+    va_start(ap, fmt);
+    str = fmtkv(KDC_AUDIT_VISLAST, "reason", fmt, ap);
+    va_end(ap);
+    if (!str) {
+	kdc_log(r->context, r->config, 1, "failed to add reason");
+        return;
+    }
+
+    kdc_log(r->context, r->config, 7, "_kdc_audit_addkv(): adding "
+            "kv pair %s", heim_string_get_utf8(str));
+    heim_release(r->reason);
+    r->reason = str;
+}
+
 /*
  * append_token adds a token which is optionally a kv-pair and it
  * also optionally eats the whitespace.  If k == NULL, then it's
@@ -55,48 +120,17 @@ _kdc_audit_addkv(kdc_request_t r, int flags, const char *k,
 {
     va_list ap;
     heim_string_t str;
-    size_t i,j;
-    char *buf1;
-    char *buf2;
-    char *buf3;
 
     va_start(ap, fmt);
-    vasprintf(&buf1, fmt, ap);
+    str = fmtkv(flags, k, fmt, ap);
     va_end(ap);
-    if (!buf1)
+    if (!str) {
-	return;
+	kdc_log(r->context, r->config, 1, "failed to add kv pair");
-
+        return;
-    j = asprintf(&buf2, "%s=%s", k, buf1);
-    free(buf1);
-    if (!buf2)
-	return;
-
-    /* We optionally eat the whitespace. */
-
-    if (flags | KDC_AUDIT_EATWHITE) {
-	for (i=0, j=0; buf2[i]; i++)
-	    if (buf2[i] != ' ' && buf2[i] != '\t')
-		buf2[j++] = buf2[i];
-	buf2[j] = '\0';
     }
 
-    if (flags | KDC_AUDIT_VIS) {
-	buf3 = malloc((j + 1) * 4 + 1);
-	strvisx(buf3, buf2, j, VIS_OCTAL);
-	free(buf2);
-    } else
-	buf3 = buf2;
-
     kdc_log(r->context, r->config, 7, "_kdc_audit_addkv(): adding "
-	    "kv pair %s", buf3);
+            "kv pair %s", heim_string_get_utf8(str));
-
-    str = heim_string_create(buf3);
-    free(buf3);
-    if (!str) {
-	kdc_log(r->context, r->config, 7, "failed to add kv pair");
-	return;
-    }
-
     heim_array_append_value(r->kv, str);
     heim_release(str);
 }
@@ -205,11 +239,12 @@ _kdc_audit_trail(kdc_request_t r, krb5_error_code ret)
     }
     kvbuf[j] = '\0';
 
-    kdc_log(r->context, r->config, 3, "%s %s %s %s %s%s",
+    kdc_log(r->context, r->config, 3, "%s %s %s %s %s%s%s%s",
 	    r->reqtype, retval, r->from,
             r->cname ? r->cname : "<unknown>",
 	    r->sname ? r->sname : "<unknown>",
-            kvbuf);
+            kvbuf, r->reason ? " " : "",
+            r->reason ? heim_string_get_utf8(r->reason) : "");
 }
 
 void
@@ -403,12 +438,14 @@ process_request(krb5_context context,
 		free(r->e_text_buf);
 	    }
 
+            heim_release(r->reason);
             heim_release(r->kv);
             free(r);
 	    return ret;
 	}
     }
 
+    heim_release(r->reason);
     heim_release(r->kv);
     free(r);
     return -1;

kdc/version-script.map

@@ -21,6 +21,7 @@ HEIMDAL_KDC_1.0 {
 		krb5_kdc_update_time;
 		krb5_kdc_pk_initialize;
 		_kdc_audit_addkv;
+		_kdc_audit_addreason;
 		_kdc_audit_trail;
 
 		# needed for digest-service