Skip to content

Commit

Permalink
Improve kpropd debug and syslog output
Browse files Browse the repository at this point in the history 
Add additional debug output and syslogs.  Remove "kpropd:" from
syslogs.  Always call openlog().  Clean up C style of a few messages.

[ghudson@mit.edu: split and combine commits; commit message]
  • Loading branch information
@nicowilliams @greghudson
nicowilliams authored and greghudson committed Oct 5, 2012
1 parent f1c85fb commit 0d4f7d5
Showing 1 changed file with 123 additions and 39 deletions.
162 changes: 123 additions & 39 deletions src/slave/kpropd.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -413,10 +413,19 @@ do_standalone()
wait_pid = waitpid(child_pid, &status, 0);
} while (wait_pid == -1 && errno == EINTR);
if (wait_pid == -1) {
/* Something bad happened; panic. */
if (debug) {
fprintf(stderr, _("waitpid() failed to wait for doit() "
"(%d %s)\n"), errno, strerror(errno));
}
com_err(progname, errno,
_("while waiting to receive database"));
exit(1);
}
if (debug) {
fprintf(stderr, _("Database load process for full propagation "
"completed.\n"));
}

close(s);

Expand Down Expand Up @@ -601,6 +610,8 @@ do_iprop(kdb_log_context *log_ctx)
unsigned int pollin, backoff_time;
int backoff_cnt = 0;
int reinit_cnt = 0;
struct timeval iprop_start, iprop_end;
unsigned long usec;
time_t frrequested = 0;
time_t now;

Expand All @@ -612,6 +623,9 @@ do_iprop(kdb_log_context *log_ctx)
kadm5_iprop_handle_t handle;
kdb_hlog_t *ulog;

if (debug)
fprintf(stderr, _("Incremental propagation enabled\n"));

ulog = log_ctx->ulog;

pollin = params.iprop_poll_time;
Expand Down Expand Up @@ -691,6 +705,10 @@ do_iprop(kdb_log_context *log_ctx)
/*
* Authentication, initialize rpcsec_gss handle etc.
*/
if (debug) {
fprintf(stderr, _("Initializing kadm5 as client %s\n"),
iprop_svc_princstr);
}
retval = kadm5_init_with_skey(kpropd_context, iprop_svc_princstr,
srvtab,
master_svc_princstr,
Expand All @@ -701,6 +719,8 @@ do_iprop(kdb_log_context *log_ctx)
&server_handle);

if (retval) {
if (debug)
fprintf(stderr, _("kadm5 initialization failed!\n"));
if (retval == KADM5_RPC_ERROR) {
reinit_cnt++;
if (server_handle)
Expand All @@ -712,6 +732,10 @@ do_iprop(kdb_log_context *log_ctx)
"while attempting to connect"
" to master KDC ... retrying"));
backoff_time = backoff_from_master(&reinit_cnt);
if (debug) {
fprintf(stderr, _("Sleeping %d seconds to re-initialize "
"kadm5 (RPC ERROR)\n"), backoff_time);
}
(void) sleep(backoff_time);
goto reinit;
} else {
Expand All @@ -728,11 +752,19 @@ do_iprop(kdb_log_context *log_ctx)
_("while initializing %s interface, retrying"),
progname);
backoff_time = backoff_from_master(&reinit_cnt);
if (debug) {
fprintf(stderr, _("Sleeping %d seconds to re-initialize "
"kadm5 (krb5kdc not running?)\n"),
backoff_time);
}
sleep(backoff_time);
goto reinit;
}
}

if (debug)
fprintf(stderr, _("kadm5 initialization succeeded\n"));

/*
* Reset re-initialization count to zero now.
*/
Expand Down Expand Up @@ -760,6 +792,9 @@ do_iprop(kdb_log_context *log_ctx)
* or (if needed) do a full resync of the krb5 db.
*/

if (debug)
fprintf(stderr, _("Calling iprop_get_updates_1()\n"));
gettimeofday(&iprop_start, NULL);
incr_ret = iprop_get_updates_1(&mylast, handle->clnt);
if (incr_ret == (kdb_incr_result_t *)NULL) {
clnt_perror(handle->clnt,
Expand All @@ -768,6 +803,10 @@ do_iprop(kdb_log_context *log_ctx)
kadm5_destroy((void *)server_handle);
server_handle = (void *)NULL;
handle = (kadm5_iprop_handle_t)NULL;
if (debug) {
fprintf(stderr, _("Reinitializing iprop because get updates "
"failed\n"));
}
goto reinit;
}

Expand All @@ -788,6 +827,10 @@ do_iprop(kdb_log_context *log_ctx)
break;
} else {
frrequested = now;
if (debug)
fprintf(stderr, _("Full resync needed\n"));
syslog(LOG_INFO, _("kpropd: Full resync needed."));

full_ret = full_resync(handle->clnt);
if (full_ret == (kdb_fullresync_result_t *)
NULL) {
Expand All @@ -804,33 +847,43 @@ do_iprop(kdb_log_context *log_ctx)

switch (full_ret->ret) {
case UPDATE_OK:
if (debug)
fprintf(stderr, _("Full resync request granted\n"));
syslog(LOG_INFO, _("Full resync request granted."));
backoff_cnt = 0;
break;

case UPDATE_BUSY:
/*
* Exponential backoff
*/
if (debug)
fprintf(stderr, _("Exponential backoff\n"));
backoff_cnt++;
break;

case UPDATE_FULL_RESYNC_NEEDED:
case UPDATE_NIL:
default:
backoff_cnt = 0;
syslog(LOG_ERR, _("kpropd: Full resync,"
" invalid return from master KDC."));
break;

case UPDATE_PERM_DENIED:
syslog(LOG_ERR, _("kpropd: Full resync,"
" permission denied."));
if (debug)
fprintf(stderr, _("Full resync permission denied\n"));
syslog(LOG_ERR, _("Full resync, permission denied."));
goto error;

case UPDATE_ERROR:
syslog(LOG_ERR, _("kpropd: Full resync,"
" error returned from master KDC."));
if (debug)
fprintf(stderr, _("Full resync error from master\n"));
syslog(LOG_ERR, _(" Full resync, "
"error returned from master KDC."));
goto error;

default:
backoff_cnt = 0;
if (debug) {
fprintf(stderr,
_("Full resync invalid result from master\n"));
}
syslog(LOG_ERR, _("Full resync, "
"invalid return from master KDC."));
break;
}
break;

Expand All @@ -843,37 +896,56 @@ do_iprop(kdb_log_context *log_ctx)
* entries using the kdb conv api and will commit
* the entries to the slave kdc database
*/
if (debug) {
fprintf(stderr,
_("Got incremental updates from the master\n"));
}
retval = ulog_replay(kpropd_context, incr_ret,
db_args);

if (retval) {
const char *msg =
krb5_get_error_message(kpropd_context, retval);
syslog(LOG_ERR,
_("kpropd: ulog_replay failed (%s), updates not registered."), msg);
if (debug) {
fprintf(stderr, _("ulog_replay failed (%s), updates not "
"registered\n"), msg);
}
syslog(LOG_ERR, _("ulog_replay failed (%s), updates "
"not registered."), msg);
krb5_free_error_message(kpropd_context, msg);
break;
}

if (debug)
fprintf(stderr, _("Update transfer "
"from master was OK\n"));
gettimeofday(&iprop_end, NULL);
usec = (iprop_end.tv_sec - iprop_start.tv_sec) * 1000000 +
iprop_end.tv_usec - iprop_start.tv_usec;
syslog(LOG_INFO, _("Incremental updates: %d updates / %lu us"),
incr_ret->updates.kdb_ulog_t_len, usec);
if (debug) {
fprintf(stderr, _("Incremental updates: %d updates / "
"%lu us\n"),
incr_ret->updates.kdb_ulog_t_len, usec);
}
break;

case UPDATE_PERM_DENIED:
syslog(LOG_ERR, _("kpropd: get_updates,"
" permission denied."));
if (debug)
fprintf(stderr, _("get_updates permission denied\n"));
syslog(LOG_ERR, _("get_updates, permission denied."));
goto error;

case UPDATE_ERROR:
syslog(LOG_ERR, _("kpropd: get_updates, error "
"returned from master KDC."));
if (debug)
fprintf(stderr, _("get_updates error from master\n"));
syslog(LOG_ERR, _("get_updates, error returned from master KDC."));
goto error;

case UPDATE_BUSY:
/*
* Exponential backoff
*/
if (debug)
fprintf(stderr, _("get_updates master busy; backoff\n"));
backoff_cnt++;
break;

Expand All @@ -882,16 +954,16 @@ do_iprop(kdb_log_context *log_ctx)
* Master-slave are in sync
*/
if (debug)
fprintf(stderr, _("Master, slave KDC's "
"are in-sync, no updates\n"));
fprintf(stderr, _("KDC is synchronized with master.\n"));
backoff_cnt = 0;
frrequested = 0;
break;

default:
backoff_cnt = 0;
syslog(LOG_ERR, _("kpropd: get_updates,"
" invalid return from master KDC."));
if (debug)
fprintf(stderr, _("get_updates invalid result from master\n"));
syslog(LOG_ERR, _("get_updates, invalid return from master KDC."));
break;
}

Expand All @@ -905,31 +977,34 @@ do_iprop(kdb_log_context *log_ctx)
*/
if (backoff_cnt > 0) {
backoff_time = backoff_from_master(&backoff_cnt);
if (debug)
if (debug) {
fprintf(stderr, _("Busy signal received "
"from master, backoff for %d secs\n"),
backoff_time);
}
(void) sleep(backoff_time);
}
else
} else {
if (debug) {
fprintf(stderr, _("Waiting for %d seconds before checking "
"for updates again\n"), pollin);
}
(void) sleep(pollin);
}

}


error:
if (debug)
fprintf(stderr, _("ERROR returned by master, bailing\n"));
syslog(LOG_ERR, _("kpropd: ERROR returned by master KDC,"
" bailing.\n"));
syslog(LOG_ERR, _("ERROR returned by master KDC, bailing.\n"));
done:
if(iprop_svc_princstr)
free(iprop_svc_princstr);
if (master_svc_princstr)
free(master_svc_princstr);
if ((retval = krb5_cc_close(kpropd_context, cc))) {
com_err(progname, retval,
_("while closing default ccache"));
com_err(progname, retval, _("while closing default ccache"));
return retval;
}
if (def_realm && kpropd_context)
Expand Down Expand Up @@ -1120,13 +1195,9 @@ void PRS(argv)
/* We don't take any arguments, only options */
usage();
}
/*
* If not in debug mode, switch com_err reporting to syslog
*/
if (! debug) {
openlog("kpropd", LOG_PID | LOG_ODELAY, SYSLOG_CLASS);
openlog("kpropd", LOG_PID | LOG_ODELAY, SYSLOG_CLASS);
if (!debug)
set_com_err_hook(kpropd_com_err_proc);
}
/*
* Get my hostname, so we can construct my service name
*/
Expand Down Expand Up @@ -1215,7 +1286,8 @@ kerberos_authenticate(context, fd, clientp, etype, my_sin)
com_err(progname, retval, _("while unparsing client name"));
exit(1);
}
printf("krb5_recvauth(%d, %s, %s, ...)\n", fd, kprop_version, name);
fprintf(stderr, "krb5_recvauth(%d, %s, %s, ...)\n", fd, kprop_version,
name);
free(name);
}

Expand Down Expand Up @@ -1399,6 +1471,9 @@ recv_database(context, fd, database_fd, confmsg)
exit(1);
}

if (debug)
fprintf(stderr, _("Full propagation transfer started.\n"));

/*
* Now start receiving the database from the net
*/
Expand Down Expand Up @@ -1451,6 +1526,10 @@ recv_database(context, fd, database_fd, confmsg)
received_size, database_size);
send_error(context, fd, KRB5KRB_ERR_GENERIC, buf);
}

if (debug)
fprintf(stderr, _("Full propagation transfer finished.\n"));

/*
* Create message acknowledging number of bytes received, but
* don't send it until kdb5_util returns successfully.
Expand Down Expand Up @@ -1604,6 +1683,11 @@ load_database(context, kdb_util, database_file_name)
}
}

if (!WIFEXITED(waitb)) {
com_err(progname, 0, _("%s load terminated"), kdb_util);
exit(1);
}

error_ret = WEXITSTATUS(waitb);
if (error_ret) {
com_err(progname, 0, _("%s returned a bad exit status (%d)"),
Expand Down

0 comments on commit 0d4f7d5

Please sign in to comment.