Now that rpc.gssd is the critical path of every
NFS mount, any favored mount, I thought I would
take a crack at making the daemon a bit more
debuggable by making the logging more readable.
The first level of debugging (-v) will only log
errors and warnings that are not normally logged.
I'm thinking this might be a good level to run
at a customer's site.
I also thought about changing the majority of the
printerr(0) which always log to printerr(1)s. I
decided not to since I figured more info is
better.
Note, I didn't remove any of the messages, I just pushed
them back to other debug levels.
I trimmed down the second level of debugging (-vv)
by again moving them back to other levels.
The third level (-vvv) is basically the same.
Using the fourth level (-vvvv) to enable all the logging
that old level three did.
Thoughts/Comments... A waste of a good Saturday afternoon?? ;-)
Steve Dickson (3):
gssd: reworked first level of debugging
gssd: log all fatal errors
gssd: reworked second level of debugging
utils/gssd/context_heimdal.c | 2 +-
utils/gssd/context_lucid.c | 6 +++---
utils/gssd/gssd.c | 14 +++++++-------
utils/gssd/gssd_proc.c | 32 +++++++++++++-------------------
utils/gssd/krb5_util.c | 28 ++++++++++++++++------------
5 files changed, 40 insertions(+), 42 deletions(-)
--
2.4.3
When gssd exist ensure a error message is logged.
Signed-off-by: Steve Dickson <[email protected]>
---
utils/gssd/gssd.c | 12 ++++++------
utils/gssd/gssd_proc.c | 2 +-
utils/gssd/krb5_util.c | 2 +-
3 files changed, 8 insertions(+), 8 deletions(-)
diff --git a/utils/gssd/gssd.c b/utils/gssd/gssd.c
index 078e558..804c53a 100644
--- a/utils/gssd/gssd.c
+++ b/utils/gssd/gssd.c
@@ -716,7 +716,7 @@ gssd_inotify_cb(int ifd, short UNUSED(which), void *UNUSED(data))
found:
if (!tdi) {
- printerr(1, "inotify event for unknown wd!!! - "
+ printerr(5, "inotify event for unknown wd!!! - "
"ev->wd (%d) ev->name (%s) ev->mask (0x%08x)\n",
ev->wd, ev->len > 0 ? ev->name : "<?>", ev->mask);
rescan = true;
@@ -820,7 +820,7 @@ main(int argc, char *argv[])
* the results of getpw*.
*/
if (setenv("HOME", "/", 1)) {
- printerr(1, "Unable to set $HOME: %s\n", strerror(errno));
+ printerr(0, "gssd: Unable to set $HOME: %s\n", strerror(errno));
exit(1);
}
@@ -891,19 +891,19 @@ main(int argc, char *argv[])
pipefs_dir = opendir(pipefs_path);
if (!pipefs_dir) {
- printerr(1, "ERROR: opendir(%s) failed: %s\n", pipefs_path, strerror(errno));
+ printerr(0, "ERROR: opendir(%s) failed: %s\n", pipefs_path, strerror(errno));
exit(EXIT_FAILURE);
}
pipefs_fd = dirfd(pipefs_dir);
if (fchdir(pipefs_fd)) {
- printerr(1, "ERROR: fchdir(%s) failed: %s\n", pipefs_path, strerror(errno));
+ printerr(0, "ERROR: fchdir(%s) failed: %s\n", pipefs_path, strerror(errno));
exit(EXIT_FAILURE);
}
inotify_fd = inotify_init1(IN_NONBLOCK);
if (inotify_fd == -1) {
- printerr(1, "ERROR: inotify_init1 failed: %s\n", strerror(errno));
+ printerr(0, "ERROR: inotify_init1 failed: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
@@ -920,7 +920,7 @@ main(int argc, char *argv[])
event_dispatch();
- printerr(1, "ERROR: event_dispatch() returned!\n");
+ printerr(0, "ERROR: event_dispatch() returned!\n");
return EXIT_FAILURE;
}
diff --git a/utils/gssd/gssd_proc.c b/utils/gssd/gssd_proc.c
index 3d9ca75..29f0e24 100644
--- a/utils/gssd/gssd_proc.c
+++ b/utils/gssd/gssd_proc.c
@@ -703,7 +703,7 @@ no_fork:
* try to use it after this point.
*/
if (serialize_context_for_kernel(&pd.pd_ctx, &token, &krb5oid, NULL)) {
- printerr(0, "WARNING: Failed to serialize krb5 context for "
+ printerr(1, "WARNING: Failed to serialize krb5 context for "
"user with uid %d for server %s\n",
uid, clp->servername);
goto out_return_error;
diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index 1d91483..0d07d1f 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -383,7 +383,7 @@ gssd_get_single_krb5_cred(krb5_context context,
"tickets. May have problems behind a NAT.\n");
#ifdef TEST_SHORT_LIFETIME
/* set a short lifetime (for debugging only!) */
- printerr(0, "WARNING: Using (debug) short machine cred lifetime!\n");
+ printerr(1, "WARNING: Using (debug) short machine cred lifetime!\n");
krb5_get_init_creds_opt_set_tkt_life(init_opts, 5*60);
#endif
opts = init_opts;
--
2.4.3
Trimmed down the number messages being logged
by moving them into level 3 or 4 of debugging
Signed-off-by: Steve Dickson <[email protected]>
---
utils/gssd/context_heimdal.c | 2 +-
utils/gssd/context_lucid.c | 6 +++---
utils/gssd/gssd.c | 2 +-
utils/gssd/gssd_proc.c | 6 +++---
utils/gssd/krb5_util.c | 10 +++++-----
5 files changed, 13 insertions(+), 13 deletions(-)
diff --git a/utils/gssd/context_heimdal.c b/utils/gssd/context_heimdal.c
index 1e8738a..d07103b 100644
--- a/utils/gssd/context_heimdal.c
+++ b/utils/gssd/context_heimdal.c
@@ -260,7 +260,7 @@ serialize_krb5_ctx(gss_ctx_id_t *_ctx, gss_buffer_desc *buf, int32_t *endtime)
if (write_heimdal_seq_key(&p, end, ctx)) goto out_err;
buf->length = p - (char *)buf->value;
- printerr(2, "serialize_krb5_ctx: returning buffer "
+ printerr(4, "serialize_krb5_ctx: returning buffer "
"with %d bytes\n", buf->length);
return 0;
diff --git a/utils/gssd/context_lucid.c b/utils/gssd/context_lucid.c
index badbe88..5d77c21 100644
--- a/utils/gssd/context_lucid.c
+++ b/utils/gssd/context_lucid.c
@@ -206,7 +206,7 @@ prepare_krb5_rfc4121_buffer(gss_krb5_lucid_context_v1_t *lctx,
if (WRITE_BYTES(&p, end, lctx->send_seq)) goto out_err;
/* Protocol 0 here implies DES3 or RC4 */
- printerr(2, "%s: protocol %d\n", __FUNCTION__, lctx->protocol);
+ printerr(4, "%s: protocol %d\n", __FUNCTION__, lctx->protocol);
if (lctx->protocol == 0) {
enctype = lctx->rfc1964_kd.ctx_key.type;
keysize = lctx->rfc1964_kd.ctx_key.length;
@@ -219,7 +219,7 @@ prepare_krb5_rfc4121_buffer(gss_krb5_lucid_context_v1_t *lctx,
keysize = lctx->cfx_kd.ctx_key.length;
}
}
- printerr(2, "%s: serializing key with enctype %d and size %d\n",
+ printerr(4, "%s: serializing key with enctype %d and size %d\n",
__FUNCTION__, enctype, keysize);
if (WRITE_BYTES(&p, end, enctype)) goto out_err;
@@ -265,7 +265,7 @@ serialize_krb5_ctx(gss_ctx_id_t *ctx, gss_buffer_desc *buf, int32_t *endtime)
gss_krb5_lucid_context_v1_t *lctx = 0;
int retcode = 0;
- printerr(2, "DEBUG: %s: lucid version!\n", __FUNCTION__);
+ printerr(4, "DEBUG: %s: lucid version!\n", __FUNCTION__);
maj_stat = gss_export_lucid_sec_context(&min_stat, ctx,
1, &return_ctx);
if (maj_stat != GSS_S_COMPLETE) {
diff --git a/utils/gssd/gssd.c b/utils/gssd/gssd.c
index 804c53a..e7cb07f 100644
--- a/utils/gssd/gssd.c
+++ b/utils/gssd/gssd.c
@@ -556,7 +556,7 @@ gssd_scan_topdir(const char *name)
if (clp->scanned)
continue;
- printerr(2, "destroying client %s\n", clp->relpath);
+ printerr(3, "destroying client %s\n", clp->relpath);
saveprev = clp->list.tqe_prev;
TAILQ_REMOVE(&tdi->clnt_list, clp, list);
gssd_destroy_client(clp);
diff --git a/utils/gssd/gssd_proc.c b/utils/gssd/gssd_proc.c
index 29f0e24..1ef68d8 100644
--- a/utils/gssd/gssd_proc.c
+++ b/utils/gssd/gssd_proc.c
@@ -231,7 +231,7 @@ populate_port(struct sockaddr *sa, const socklen_t salen,
switch (sa->sa_family) {
case AF_INET:
if (s4->sin_port != 0) {
- printerr(2, "DEBUG: port already set to %d\n",
+ printerr(4, "DEBUG: port already set to %d\n",
ntohs(s4->sin_port));
return 1;
}
@@ -239,7 +239,7 @@ populate_port(struct sockaddr *sa, const socklen_t salen,
#ifdef IPV6_SUPPORTED
case AF_INET6:
if (s6->sin6_port != 0) {
- printerr(2, "DEBUG: port already set to %d\n",
+ printerr(4, "DEBUG: port already set to %d\n",
ntohs(s6->sin6_port));
return 1;
}
@@ -393,7 +393,7 @@ create_auth_rpc_client(struct clnt_info *clp,
auth = authgss_create_default(rpc_clnt, tgtname, &sec);
if (!auth) {
/* Our caller should print appropriate message */
- printerr(2, "WARNING: Failed to create krb5 context for "
+ printerr(1, "WARNING: Failed to create krb5 context for "
"user with uid %d for server %s\n",
uid, tgtname);
goto out_fail;
diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index 0d07d1f..8ef8184 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -356,7 +356,7 @@ gssd_get_single_krb5_cred(krb5_context context,
*/
now += 300;
if (ple->ccname && ple->endtime > now && !nocache) {
- printerr(2, "INFO: Credentials in CC '%s' are good until %d\n",
+ printerr(3, "INFO: Credentials in CC '%s' are good until %d\n",
ple->ccname, ple->endtime);
code = 0;
goto out;
@@ -476,7 +476,7 @@ gssd_set_krb5_ccache_name(char *ccname)
#ifdef USE_GSS_KRB5_CCACHE_NAME
u_int maj_stat, min_stat;
- printerr(2, "using gss_krb5_ccache_name to select krb5 ccache %s\n",
+ printerr(3, "using gss_krb5_ccache_name to select krb5 ccache %s\n",
ccname);
maj_stat = gss_krb5_ccache_name(&min_stat, ccname, NULL);
if (maj_stat != GSS_S_COMPLETE) {
@@ -491,7 +491,7 @@ gssd_set_krb5_ccache_name(char *ccname)
* function above for which there is no generic gssapi
* equivalent.)
*/
- printerr(2, "using environment variable to select krb5 ccache %s\n",
+ printerr(3, "using environment variable to select krb5 ccache %s\n",
ccname);
setenv("KRB5CCNAME", ccname, 1);
#endif
@@ -1092,8 +1092,8 @@ gssd_setup_krb5_user_gss_ccache(uid_t uid, char *servername, char *dirpattern)
struct dirent *d;
int err, i, j;
- printerr(2, "getting credentials for client with uid %u for "
- "server %s\n", uid, servername);
+ printerr(3, "looking for client creds with uid %u for "
+ "server %s in %s\n", uid, servername, dirpattern);
for (i = 0, j = 0; dirpattern[i] != '\0'; i++) {
switch (dirpattern[i]) {
--
2.4.3
Cleaned up first level of debugging. Only
errors and warnings are logged.
Signed-off-by: Steve Dickson <[email protected]>
---
utils/gssd/gssd_proc.c | 24 +++++++++---------------
utils/gssd/krb5_util.c | 16 ++++++++++------
2 files changed, 19 insertions(+), 21 deletions(-)
diff --git a/utils/gssd/gssd_proc.c b/utils/gssd/gssd_proc.c
index cee8991..3d9ca75 100644
--- a/utils/gssd/gssd_proc.c
+++ b/utils/gssd/gssd_proc.c
@@ -150,7 +150,7 @@ do_downcall(int k5_fd, uid_t uid, struct authgss_private_data *pd,
unsigned int timeout = context_timeout;
unsigned int buf_size = 0;
- printerr(1, "doing downcall: lifetime_rec=%u acceptor=%.*s\n",
+ printerr(2, "doing downcall: lifetime_rec=%u acceptor=%.*s\n",
lifetime_rec, acceptor->length, acceptor->value);
buf_size = sizeof(uid) + sizeof(timeout) + sizeof(pd->pd_seq_win) +
sizeof(pd->pd_ctx_hndl.length) + pd->pd_ctx_hndl.length +
@@ -189,7 +189,7 @@ do_error_downcall(int k5_fd, uid_t uid, int err)
unsigned int timeout = 0;
int zero = 0;
- printerr(1, "doing error downcall\n");
+ printerr(2, "doing error downcall\n");
if (WRITE_BYTES(&p, end, uid)) goto out_err;
if (WRITE_BYTES(&p, end, timeout)) goto out_err;
@@ -484,7 +484,7 @@ krb5_not_machine_creds(struct clnt_info *clp, uid_t uid, char *tgtname,
char **dname;
int err, resp = -1;
- printerr(1, "krb5_not_machine_creds: uid %d tgtname %s\n",
+ printerr(2, "krb5_not_machine_creds: uid %d tgtname %s\n",
uid, tgtname);
*chg_err = change_identity(uid);
@@ -531,7 +531,7 @@ krb5_use_machine_creds(struct clnt_info *clp, uid_t uid, char *tgtname,
int nocache = 0;
int success = 0;
- printerr(1, "krb5_use_machine_creds: uid %d tgtname %s\n",
+ printerr(2, "krb5_use_machine_creds: uid %d tgtname %s\n",
uid, tgtname);
do {
@@ -601,8 +601,6 @@ process_krb5_upcall(struct clnt_info *clp, uid_t uid, int fd, char *tgtname,
gss_OID mech;
gss_buffer_desc acceptor = {0};
- printerr(1, "handling krb5 upcall (%s)\n", clp->relpath);
-
token.length = 0;
token.value = NULL;
memset(&pd, 0, sizeof(struct authgss_private_data));
@@ -628,8 +626,6 @@ process_krb5_upcall(struct clnt_info *clp, uid_t uid, int fd, char *tgtname,
* used for this case is not important.
*
*/
- printerr(2, "%s: service is '%s'\n", __func__,
- service ? service : "<null>");
if (uid != 0 || (uid == 0 && root_uses_machine_creds == 0 &&
service == NULL)) {
@@ -643,7 +639,7 @@ process_krb5_upcall(struct clnt_info *clp, uid_t uid, int fd, char *tgtname,
/* Child: fall through to rest of function */
childpid = getpid();
unsetenv("KRB5CCNAME");
- printerr(1, "CHILD forked pid %d \n", childpid);
+ printerr(2, "CHILD forked pid %d \n", childpid);
break;
case -1:
/* fork() failed! */
@@ -676,9 +672,7 @@ no_fork:
if (auth == NULL)
goto out_return_error;
} else {
- printerr(1, "WARNING: Failed to create krb5 context "
- "for user with uid %d for server %s\n",
- uid, clp->servername);
+ /* krb5_not_machine_creds logs the error */
goto out_return_error;
}
}
@@ -752,6 +746,8 @@ handle_krb5_upcall(struct clnt_info *clp)
return;
}
+ printerr(2, "\n%s: uid %d (%s)\n", __func__, uid, clp->relpath);
+
process_krb5_upcall(clp, uid, clp->krb5_fd, NULL, NULL);
}
@@ -768,8 +764,6 @@ handle_gssd_upcall(struct clnt_info *clp)
char *service = NULL;
char *enctypes = NULL;
- printerr(1, "handling gssd upcall (%s)\n", clp->relpath);
-
lbuflen = read(clp->gssd_fd, lbuf, sizeof(lbuf));
if (lbuflen <= 0 || lbuf[lbuflen-1] != '\n') {
printerr(0, "WARNING: handle_gssd_upcall: "
@@ -778,7 +772,7 @@ handle_gssd_upcall(struct clnt_info *clp)
}
lbuf[lbuflen-1] = 0;
- printerr(2, "%s: '%s'\n", __func__, lbuf);
+ printerr(2, "\n%s: '%s' (%s)\n", __func__, lbuf, clp->relpath);
for (p = strtok(lbuf, " "); p; p = strtok(NULL, " ")) {
if (!strncmp(p, "mech=", strlen("mech=")))
diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index f48de2c..1d91483 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -451,8 +451,7 @@ gssd_get_single_krb5_cred(krb5_context context,
}
code = 0;
- printerr(2, "Successfully obtained machine credentials for "
- "principal '%s' stored in ccache '%s'\n", pname, cc_name);
+ printerr(2, "%s: principal '%s' ccache:'%s'\n", __func__, pname, cc_name);
out:
#if HAVE_KRB5_GET_INIT_CREDS_OPT_SET_ADDRESSLESS
if (init_opts)
@@ -1410,16 +1409,21 @@ gssd_acquire_krb5_cred(gss_cred_id_t *gss_cred)
int
gssd_acquire_user_cred(gss_cred_id_t *gss_cred)
{
- OM_uint32 min_stat;
+ OM_uint32 maj_stat, min_stat;
int ret;
ret = gssd_acquire_krb5_cred(gss_cred);
/* force validation of cred to check for expiry */
if (ret == 0) {
- if (gss_inquire_cred(&min_stat, *gss_cred, NULL, NULL,
- NULL, NULL) != GSS_S_COMPLETE)
- ret = -1;
+ maj_stat = gss_inquire_cred(&min_stat, *gss_cred,
+ NULL, NULL, NULL, NULL);
+ if (maj_stat != GSS_S_COMPLETE) {
+ if (get_verbosity() > 0)
+ pgsserr("gss_inquire_cred",
+ maj_stat, min_stat, &krb5oid);
+ ret = -1;
+ }
}
return ret;
--
2.4.3
On Sat, Nov 07, 2015 at 01:14:07PM -0500, Steve Dickson wrote:
> Now that rpc.gssd is the critical path of every
> NFS mount, any favored mount, I thought I would
> take a crack at making the daemon a bit more
> debuggable by making the logging more readable.
>
> The first level of debugging (-v) will only log
> errors and warnings that are not normally logged.
> I'm thinking this might be a good level to run
> at a customer's site.
>
> I also thought about changing the majority of the
> printerr(0) which always log to printerr(1)s. I
> decided not to since I figured more info is
> better.
>
> Note, I didn't remove any of the messages, I just pushed
> them back to other debug levels.
>
> I trimmed down the second level of debugging (-vv)
> by again moving them back to other levels.
>
> The third level (-vvv) is basically the same.
>
> Using the fourth level (-vvvv) to enable all the logging
> that old level three did.
>
> Thoughts/Comments... A waste of a good Saturday afternoon?? ;-)
I haven't reviewed the patches, but those sound like reasonable things
to do to me.
--b.
>
> Steve Dickson (3):
> gssd: reworked first level of debugging
> gssd: log all fatal errors
> gssd: reworked second level of debugging
>
> utils/gssd/context_heimdal.c | 2 +-
> utils/gssd/context_lucid.c | 6 +++---
> utils/gssd/gssd.c | 14 +++++++-------
> utils/gssd/gssd_proc.c | 32 +++++++++++++-------------------
> utils/gssd/krb5_util.c | 28 ++++++++++++++++------------
> 5 files changed, 40 insertions(+), 42 deletions(-)
>
> --
> 2.4.3
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
On 11/07/2015 01:14 PM, Steve Dickson wrote:
> Now that rpc.gssd is the critical path of every
> NFS mount, any favored mount, I thought I would
> take a crack at making the daemon a bit more
> debuggable by making the logging more readable.
>
> The first level of debugging (-v) will only log
> errors and warnings that are not normally logged.
> I'm thinking this might be a good level to run
> at a customer's site.
>
> I also thought about changing the majority of the
> printerr(0) which always log to printerr(1)s. I
> decided not to since I figured more info is
> better.
>
> Note, I didn't remove any of the messages, I just pushed
> them back to other debug levels.
>
> I trimmed down the second level of debugging (-vv)
> by again moving them back to other levels.
>
> The third level (-vvv) is basically the same.
>
> Using the fourth level (-vvvv) to enable all the logging
> that old level three did.
>
> Thoughts/Comments... A waste of a good Saturday afternoon?? ;-)
>
> Steve Dickson (3):
> gssd: reworked first level of debugging
> gssd: log all fatal errors
> gssd: reworked second level of debugging
All three patches committed...
steved.