krb5 commit: ipropd_svc.c DPRINT improvements

[Greg Hudson]

https://github.com/krb5/krb5/commit/cea0b28045b262b1098f17f17f78b2efbf89a6c1
commit cea0b28045b262b1098f17f17f78b2efbf89a6c1
Author: Nicolas Williams <nico at cryptonector.com>
Date:   Mon Sep 24 15:56:42 2012 -0500

    ipropd_svc.c DPRINT improvements
    
    Make DPRINT a varargs macro and add some new debug prints.

 src/kadmin/server/ipropd_svc.c |   47 ++++++++++++++++++++++++++++-----------
 1 files changed, 34 insertions(+), 13 deletions(-)

diff --git a/src/kadmin/server/ipropd_svc.c b/src/kadmin/server/ipropd_svc.c
index 19c1bac..ffbd02a 100644
--- a/src/kadmin/server/ipropd_svc.c
+++ b/src/kadmin/server/ipropd_svc.c
@@ -57,7 +57,13 @@ static char *reply_unknown_str	= "<UNKNOWN_CODE>";
 #ifdef	DPRINT
 #undef	DPRINT
 #endif
-#define	DPRINT(i) if (nofork) printf i
+#define	DPRINT(i, ...)		    \
+    do {				  \
+	if (nofork) {		     \
+	    fprintf(stderr, __VA_ARGS__); \
+	    fflush(stderr);	       \
+	}				 \
+    } while (0)
 
 
 static void
@@ -138,8 +144,8 @@ iprop_get_updates_1_svc(kdb_last_t *arg, struct svc_req *rqstp)
     /* default return code */
     ret.ret = UPDATE_ERROR;
 
-    DPRINT(("%s: start, last_sno=%lu\n", whoami,
-	    (unsigned long) arg->last_sno));
+    DPRINT("%s: start, last_sno=%lu\n", whoami,
+	    (unsigned long)arg->last_sno);
 
     if (!handle) {
 	krb5_klog_syslog(LOG_ERR,
@@ -169,8 +175,8 @@ iprop_get_updates_1_svc(kdb_last_t *arg, struct svc_req *rqstp)
 	}
     }
 
-    DPRINT(("%s: clprinc=`%s'\n\tsvcprinc=`%s'\n",
-	    whoami, client_name, service_name));
+    DPRINT("%s: clprinc=`%s'\n\tsvcprinc=`%s'\n", whoami, client_name,
+	   service_name);
 
     if (!kadm5int_acl_check(handle->context,
 			    rqst2name(rqstp),
@@ -179,6 +185,9 @@ iprop_get_updates_1_svc(kdb_last_t *arg, struct svc_req *rqstp)
 			    NULL)) {
 	ret.ret = UPDATE_PERM_DENIED;
 
+	DPRINT("%s: PERMISSION DENIED: clprinc=`%s'\n\tsvcprinc=`%s'\n",
+		whoami, client_name, service_name);
+
 	krb5_klog_syslog(LOG_NOTICE, LOG_UNAUTH, whoami,
 			 client_name, service_name,
 			 client_addr(rqstp));
@@ -200,6 +209,11 @@ iprop_get_updates_1_svc(kdb_last_t *arg, struct svc_req *rqstp)
 			(unsigned long)arg->last_sno);
     }
 
+    DPRINT("%s: request %s %s\n\tclprinc=`%s'\n\tsvcprinc=`%s'\n",
+	   whoami, obuf,
+	   ((kret == 0) ? "success" : error_message(kret)),
+	   client_name, service_name);
+
     krb5_klog_syslog(LOG_NOTICE,
 		     _("Request: %s, %s, %s, client=%s, service=%s, addr=%s"),
 		     whoami,
@@ -273,12 +287,13 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	goto out;
     }
 
-    DPRINT(("%s: start\n", whoami));
+    DPRINT("%s: start\n", whoami);
 
     {
 	gss_buffer_desc client_desc, service_desc;
 
 	if (setup_gss_names(rqstp, &client_desc, &service_desc) < 0) {
+	    DPRINT("%s: setup_gss_names failed\n", whoami);
 	    krb5_klog_syslog(LOG_ERR,
 			     _("%s: setup_gss_names failed"),
 			     whoami);
@@ -289,6 +304,7 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	if (client_name == NULL || service_name == NULL) {
 	    free(client_name);
 	    free(service_name);
+	    DPRINT("%s: out of memory\n", whoami);
 	    krb5_klog_syslog(LOG_ERR,
 			     _("%s: out of memory recording principal names"),
 			     whoami);
@@ -296,8 +312,8 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	}
     }
 
-    DPRINT(("%s: clprinc=`%s'\n\tsvcprinc=`%s'\n",
-	    whoami, client_name, service_name));
+    DPRINT("%s: clprinc=`%s'\n\tsvcprinc=`%s'\n",
+	    whoami, client_name, service_name);
 
     if (!kadm5int_acl_check(handle->context,
 			    rqst2name(rqstp),
@@ -306,6 +322,7 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 			    NULL)) {
 	ret.ret = UPDATE_PERM_DENIED;
 
+	DPRINT("%s: Permission denied\n", whoami);
 	krb5_klog_syslog(LOG_NOTICE, LOG_UNAUTH, whoami,
 			 client_name, service_name,
 			 client_addr(rqstp));
@@ -347,13 +364,14 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
      * acts like a callback to the slave).
      */
     fret = fork();
-    DPRINT(("%s: fork=%d (%d)\n", whoami, fret, getpid()));
+    DPRINT("%s: fork=%d (%d)\n", whoami, fret, getpid());
 
     switch (fret) {
     case -1: /* error */
 	if (nofork) {
 	    perror(whoami);
 	}
+	DPRINT("%s: fork failed\n", whoami);
 	krb5_klog_syslog(LOG_ERR,
 			 _("%s: fork failed: %s"),
 			 whoami,
@@ -361,7 +379,7 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	goto out;
 
     case 0: /* child */
-	DPRINT(("%s: run `%s' ...\n", whoami, ubuf));
+	DPRINT("%s: run `%s' ...\n", whoami, ubuf);
 	(void) signal(SIGCHLD, SIG_DFL);
 	/* run kdb5_util(1M) dump for IProp */
 	p = popen(ubuf, "w");
@@ -372,7 +390,7 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	    _exit(1);
 	}
 	pret = pclose(p);
-	DPRINT(("%s: pclose=%d\n", whoami, pret));
+	DPRINT("%s: pclose=%d\n", whoami, pret);
 	if (pret != 0) {
 	    /* XXX popen/pclose may not set errno
 	       properly, and the error could be from the
@@ -387,8 +405,8 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	    _exit(1);
 	}
 
-	DPRINT(("%s: exec `kprop -f %s %s' ...\n",
-		whoami, KPROP_DEFAULT_FILE, clhost));
+	DPRINT("%s: exec `kprop -f %s %s' ...\n",
+		whoami, KPROP_DEFAULT_FILE, clhost);
 	/* XXX Yuck!  */
 	if (getenv("KPROP_PORT")) {
 	    pret = execl(KPROP_DEFAULT_FILE, "kprop", "-f",
@@ -412,6 +430,9 @@ ipropx_resync(uint32_t vers, struct svc_req *rqstp)
 	ret.lastentry.last_time.seconds = 0;
 	ret.lastentry.last_time.useconds = 0;
 
+	DPRINT("%s: spawned resync process %d, client=%s, "
+		"service=%s, addr=%s\n", whoami, fret, client_name,
+		service_name, client_addr(rqstp));
 	krb5_klog_syslog(LOG_NOTICE,
 			 _("Request: %s, spawned resync process %d, client=%s, service=%s, addr=%s"),
 			 whoami, fret,