diff --git a/kadmin/ext.c b/kadmin/ext.c index 41e177fce..7f6764db5 100644 --- a/kadmin/ext.c +++ b/kadmin/ext.c @@ -68,6 +68,12 @@ do_ext_keytab(krb5_principal principal, void *data) if (ret) goto out; + /* Debug: record which principal was fetched and some context */ + krb5_warnx(context, "do_ext_keytab: fetched principal %s mask=0x%x n_key_data=%d", + unparsed ? unparsed : "", + mask, + (int)princ.n_key_data); + if (!e->random_key_flag) { if (princ.n_key_data == 0) { krb5_warnx(context, "principal has no keys, or user lacks " @@ -111,6 +117,13 @@ do_ext_keytab(krb5_principal principal, void *data) keys[i].keyblock.keyvalue.data = kd->key_data_contents[0]; keys[i].timestamp = time(NULL); n_k++; + + /* Debug: log each key extracted (kvno/enctype) for the principal */ + krb5_warnx(context, "do_ext_keytab: principal=%s key_index=%zu kvno=%d enctype=%d", + unparsed ? unparsed : "", + i, + keys[i].vno, + keys[i].keyblock.keytype); } } else if (e->random_key_flag) { ret = kadm5_randkey_principal_3(e->kadm_handle, principal, e->keep, @@ -208,6 +221,10 @@ ext_keytab(struct ext_keytab_options *opt, int argc, char **argv) return ret; } + /* Debug: record ext_keytab invocation details */ + krb5_warnx(context, "ext_keytab: invoking foreach_principal for %zu principals, enctypes=%s", + (size_t)argc, enctypes ? enctypes : ""); + for(i = 0; i < argc; i++) { ret = foreach_principal(argv[i], do_ext_keytab, "ext", &data); if (ret) diff --git a/kadmin/get.c b/kadmin/get.c index 1942d6389..111390f9a 100644 --- a/kadmin/get.c +++ b/kadmin/get.c @@ -488,12 +488,71 @@ do_get_entry(krb5_principal principal, void *data) e->upto--; memset(&princ, 0, sizeof(princ)); - ret = kadm5_get_principal(e->kadm_handle, principal, - &princ, - e->mask | e->extra_mask); + + /* Loud tracing: record which principal we are about to request from kadmind. + * + * Guard the unparse call: don't call into unparse with a NULL principal + * and only use the unparsed string if the call succeeds. + */ + { + char *want = NULL; + if (principal != NULL && krb5_unparse_name(context, principal, &want) == 0 && want != NULL) { + krb5_warnx(context, "kadmin:get: do_get_entry: requesting principal lookup for %s (mask=0x%x extra_mask=0x%x) (pid=%d)", + want, e->mask, e->extra_mask, (int)getpid()); + } else { + krb5_warnx(context, "kadmin:get: do_get_entry: requesting principal lookup for (mask=0x%x extra_mask=0x%x) (pid=%d)", + e->mask, e->extra_mask, (int)getpid()); + } + free(want); + } + + /* Always request the principal field so we can safely unparse/format + * the returned entry. Some callers request only TL_DATA (eg aliases), + * and the kadm5 backend may return successful results without filling + * the principal pointer which leads to crashes when we try to use it. + */ + { + uint32_t want_mask = e->mask | e->extra_mask | KADM5_PRINCIPAL; + ret = kadm5_get_principal(e->kadm_handle, principal, + &princ, + want_mask); + } + if (ret == 0) { + /* Success: log the fact we received a principal record and some basic info */ + { + char *got = NULL; + if (krb5_unparse_name(context, princ.principal, &got) == 0) { + krb5_warnx(context, "kadmin:get: do_get_entry: kadm5_get_principal succeeded: principal=%s kvno=%d n_key_data=%d (pid=%d)", + got ? got : "", + princ.kvno, + princ.n_key_data, + (int)getpid()); + } else { + krb5_warnx(context, "kadmin:get: do_get_entry: kadm5_get_principal succeeded: kvno=%d n_key_data=%d (pid=%d)", + princ.kvno, princ.n_key_data, (int)getpid()); + } + free(got); + } + (e->format)(e, &princ); kadm5_free_principal_ent(e->kadm_handle, &princ); + } else { + /* Failure: log explicit error so we can trace failing lookups. + * + * Guard the unparse call similarly to above. + */ + { + char *want2 = NULL; + if (principal != NULL && krb5_unparse_name(context, principal, &want2) == 0 && want2 != NULL) { + krb5_warn(context, ret, "kadmin:get: do_get_entry: kadm5_get_principal(%s) failed (pid=%d)", + want2, (int)getpid()); + } else { + krb5_warn(context, ret, "kadmin:get: do_get_entry: kadm5_get_principal() failed (pid=%d)", + (int)getpid()); + } + free(want2); + } } e->n++; @@ -627,8 +686,14 @@ getit(struct get_options *opt, const char *name, int argc, char **argv) return 0; } - for(i = 0; i < argc; i++) + for(i = 0; i < argc; i++) { + /* Loud tracing: announce each foreach_principal invocation */ + krb5_warnx(context, "kadmin:get: getit: invoking foreach_principal for arg[%d]=%s (call %d of %d) (pid=%d)", + i, argv[i] ? argv[i] : "", i+1, argc, (int)getpid()); ret = foreach_principal(argv[i], do_get_entry, name, &data); + if (ret) + krb5_warn(context, ret, "kadmin:get: getit: foreach_principal(%s) returned error", argv[i] ? argv[i] : ""); + } kadm5_destroy(data.kadm_handle); diff --git a/kadmin/rpc.c b/kadmin/rpc.c index c826b9dfd..e23deb0a8 100644 --- a/kadmin/rpc.c +++ b/kadmin/rpc.c @@ -624,7 +624,31 @@ proc_get_principal(kadm5_server_context *contextp, if(ret) goto fail; + /* Loud tracing: log which client requested this GET and what principal is being looked up */ + { + char *want = NULL; + (void) krb5_unparse_name(contextp->context, princ, &want); + krb5_warnx(contextp->context, + "proc_get_principal: received GET request for principal=%s mask=0x%x (pid=%d ppid=%d uid=%d)", + want ? want : "", + mask, + (int)getpid(), + (int)getppid(), + (int)getuid()); + free(want); + } + ret = kadm5_get_principal(contextp, princ, &ent, mask); + if (ret) { + /* Extra log to make failures obvious at the call site */ + char *want2 = NULL; + (void) krb5_unparse_name(contextp->context, princ, &want2); + krb5_warn(contextp->context, ret, + "proc_get_principal: kadm5_get_principal failed for principal=%s (pid=%d)", + want2 ? want2 : "", + (int)getpid()); + free(want2); + } fail: krb5_warn(contextp->context, ret, "get principal principal"); diff --git a/kadmin/server.c b/kadmin/server.c index edaff61cc..b72d3a5de 100644 --- a/kadmin/server.c +++ b/kadmin/server.c @@ -226,6 +226,8 @@ kadmind_dispatch_int(void *kadm_handlep, krb5_boolean initial, ret_sp = krb5_store_int32(rsp, KADM5_FAILURE); goto fail; } + /* Debug: record which client and numeric command we received */ + krb5_warnx(contextp->context, "kadmind_dispatch: received request from client=%s cmd=%d", client, cmd); switch(cmd){ case kadm_nop:{ @@ -268,6 +270,8 @@ kadmind_dispatch_int(void *kadm_handlep, krb5_boolean initial, mask |= KADM5_PRINCIPAL; krb5_unparse_name_fixed(contextp->context, princ, name, sizeof(name)); krb5_warnx(contextp->context, "%s: %s %s", client, op, name); + /* Debug: include mask/keys_ok context so we can correlate admin requests to keytab lookups */ + krb5_warnx(contextp->context, "kadmind_dispatch: GET invoked by %s for %s (mask=0x%x, keys_ok=%d)", client, name, mask, keys_ok); /* If the caller doesn't have KADM5_PRIV_GET, we're done. */ ret = _kadm5_acl_check_permission(contextp, KADM5_PRIV_GET, princ); @@ -307,6 +311,7 @@ kadmind_dispatch_int(void *kadm_handlep, krb5_boolean initial, } } + krb5_warnx(contextp->context, "kadmind_dispatch: calling kadm5_get_principal for %s (mask=0x%x, keys_ok=%d)", name, mask, keys_ok); ret = kadm5_get_principal(kadm_handlep, princ, &ent, mask); ret_sp = krb5_store_int32(rsp, ret); if (ret == 0) { diff --git a/lib/hdb/hdb-keytab.c b/lib/hdb/hdb-keytab.c index c9b469cb1..269c3fa0c 100644 --- a/lib/hdb/hdb-keytab.c +++ b/lib/hdb/hdb-keytab.c @@ -149,10 +149,55 @@ hkt_fetch_kvno(krb5_context context, HDB * db, krb5_const_principal principal, * enctypes should work. */ + /* Debug: record the requested principal and keytab context */ + { + char *princ_name = NULL; + if (krb5_unparse_name(context, principal, &princ_name) == 0) { + krb5_warnx(context, "hkt_fetch_kvno: looking up principal=%s in keytab=%s kvno=%u flags=0x%x", + princ_name ? princ_name : "", + k->path ? k->path : "", + (unsigned)kvno, + (unsigned)flags); + } else { + krb5_warnx(context, "hkt_fetch_kvno: looking up in keytab=%s kvno=%u flags=0x%x", + k->path ? k->path : "", + (unsigned)kvno, + (unsigned)flags); + } + free(princ_name); + } + ret = krb5_kt_get_entry(context, k->keytab, principal, kvno, 0, &ktentry); if (ret) { + char *princ_name2 = NULL; + if (krb5_unparse_name(context, principal, &princ_name2) == 0) { + krb5_warnx(context, "hkt_fetch_kvno: krb5_kt_get_entry returned %d for principal=%s keytab=%s", + ret, princ_name2 ? princ_name2 : "", k->path ? k->path : ""); + } else { + krb5_warnx(context, "hkt_fetch_kvno: krb5_kt_get_entry returned %d for keytab=%s", + ret, k->path ? k->path : ""); + } + free(princ_name2); ret = HDB_ERR_NOENTRY; goto out; + } else { + /* Success: record what the keytab returned for inspection */ + { + char *entry_princ = NULL; + if (krb5_unparse_name(context, ktentry.principal, &entry_princ) == 0) { + krb5_warnx(context, "hkt_fetch_kvno: krb5_kt_get_entry succeeded: entry_principal=%s vno=%d enctype=%d keytab=%s", + entry_princ ? entry_princ : "", + ktentry.vno, + ktentry.keyblock.keytype, + k->path ? k->path : ""); + } else { + krb5_warnx(context, "hkt_fetch_kvno: krb5_kt_get_entry succeeded: entry_principal= vno=%d enctype=%d keytab=%s", + ktentry.vno, + ktentry.keyblock.keytype, + k->path ? k->path : ""); + } + free(entry_princ); + } } ret = krb5_copy_principal(context, principal, &entry->principal); diff --git a/lib/kadm5/init_c.c b/lib/kadm5/init_c.c index 8cc7cf476..76d880881 100644 --- a/lib/kadm5/init_c.c +++ b/lib/kadm5/init_c.c @@ -191,6 +191,20 @@ _kadm5_c_init_context(kadm5_client_context **ctx, } if ((*ctx)->readonly_kadmind_port == 0) (*ctx)->readonly_kadmind_port = (*ctx)->kadmind_port; + + /* + * Extra debug: emit context-level info to help trace client init-time + * decisions in test logs. + */ + krb5_warnx(context, + "_kadm5_c_init_context: realm=%s admin_server=%s readonly_admin_server=%s kadmind_port=%u readonly_port=%u (pid=%d)", + (*ctx)->realm ? (*ctx)->realm : "", + (*ctx)->admin_server ? (*ctx)->admin_server : "", + (*ctx)->readonly_admin_server ? (*ctx)->readonly_admin_server : "", + (unsigned)ntohs((*ctx)->kadmind_port), + (unsigned)ntohs((*ctx)->readonly_kadmind_port), + (int)getpid()); + return 0; } @@ -226,6 +240,16 @@ kadm5_c_dup_context(void *vin, void **out) if (in->readonly_admin_server && (ctx->readonly_admin_server = strdup(in->readonly_admin_server)) == NULL) ret = krb5_enomem(context); + + /* Preserve client identity and prompter behavior in duplicated context */ + if (in->client_name && (ctx->client_name = strdup(in->client_name)) == NULL) + ret = krb5_enomem(context); + if (in->service_name && (ctx->service_name = strdup(in->service_name)) == NULL) + ret = krb5_enomem(context); + /* Copy the prompter pointer so duplicated contexts behave the same + with respect to prompting vs keytab-based auth. */ + ctx->prompter = in->prompter; + if (in->keytab && (ctx->keytab = strdup(in->keytab)) == NULL) ret = krb5_enomem(context); if (in->ccache) { @@ -292,7 +316,24 @@ get_new_cache(krb5_context context, krb5_get_init_creds_opt_set_forwardable (opt, FALSE); krb5_get_init_creds_opt_set_proxiable (opt, FALSE); + /* + * Extra debug: record the inputs to credential selection so tests can + * observe why keytab vs password paths were chosen. + */ + krb5_warnx(context, + "get_new_cache: entry client=%s password_provided=%d prompter=%p keytab=%s server_name=%s (pid=%d)", + client ? krb5_principal_get_comp_string(context, client, 0) : "", + password ? 1 : 0, + (void *)prompter, + keytab ? keytab : "", + server_name ? server_name : "", + (int)getpid()); + if(password == NULL && prompter == NULL) { + /* Debug: choosing keytab-based initial credentials */ + krb5_warnx(context, "get_new_cache: choosing keytab auth (keytab=%s, client=%s)", + keytab ? keytab : "", + client ? krb5_principal_get_comp_string(context, client, 0) : ""); krb5_keytab kt; if(keytab == NULL) ret = krb5_kt_default(context, &kt); @@ -309,8 +350,21 @@ get_new_cache(krb5_context context, 0, server_name, opt); + /* Log success/failure of keytab credential attempt for diagnostics */ + if (ret == 0) { + krb5_warnx(context, "get_new_cache: krb5_get_init_creds_keytab succeeded for principal=%s using keytab=%s", + client ? krb5_principal_get_comp_string(context, client, 0) : "", + keytab ? keytab : ""); + } else { + krb5_warn(context, ret, "get_new_cache: krb5_get_init_creds_keytab failed (keytab=%s)", keytab ? keytab : ""); + } krb5_kt_close(context, kt); } else { + /* Debug: choosing password-based initial credentials */ + krb5_warnx(context, "get_new_cache: choosing password auth (password_provided=%d prompter=%p client=%s)", + password ? 1 : 0, + (void *)prompter, + client ? krb5_principal_get_comp_string(context, client, 0) : ""); ret = krb5_get_init_creds_password (context, &cred, client, @@ -320,6 +374,13 @@ get_new_cache(krb5_context context, 0, server_name, opt); + if (ret == 0) { + krb5_warnx(context, "get_new_cache: krb5_get_init_creds_password succeeded for principal=%s", + client ? krb5_principal_get_comp_string(context, client, 0) : ""); + } else { + krb5_warn(context, ret, "get_new_cache: krb5_get_init_creds_password failed for principal=%s", + client ? krb5_principal_get_comp_string(context, client, 0) : ""); + } } krb5_get_init_creds_opt_free(context, opt); switch(ret){ @@ -448,6 +509,27 @@ _kadm5_c_get_cred_cache(krb5_context context, if(server_name == NULL) server_name = KADM5_ADMIN_SERVICE; + /* + * Extra debug: log the invocation and environment so we can correlate + * with test harness behavior (e.g. whether KRB5_KTNAME / KRB5CCNAME + * were set). + */ + { + const char *env_kt = secure_getenv ? secure_getenv("KRB5_KTNAME") : getenv("KRB5_KTNAME"); + const char *env_cc = secure_getenv ? secure_getenv("KRB5CCNAME") : getenv("KRB5CCNAME"); + krb5_warnx(context, + "_kadm5_c_get_cred_cache: called client_name=%s server_name=%s password_provided=%d prompter=%p keytab=%s ccache=%p env.KRB5_KTNAME=%s env.KRB5CCNAME=%s (pid=%d)", + client_name ? client_name : "", + server_name ? server_name : "", + password ? 1 : 0, + (void *)prompter, + keytab ? keytab : "", + (void *)ccache, + env_kt ? env_kt : "", + env_cc ? env_cc : "", + (int)getpid()); + } + if(client_name != NULL) { ret = krb5_parse_name(context, client_name, &client); if(ret) @@ -502,14 +584,20 @@ _kadm5_c_get_cred_cache(krb5_context context, if(id && client && (default_client == NULL || krb5_principal_compare(context, client, default_client) != 0)) { + /* Debug: attempting to obtain kadmin ticket from existing credential cache */ + krb5_warnx(context, "_kadm5_c_get_cred_cache: trying credential cache to get kadmin ticket (client=%s)", + client ? krb5_principal_get_comp_string(context, client, 0) : ""); ret = get_kadm_ticket(context, id, client, server_name); if(ret == 0) { + krb5_warnx(context, "_kadm5_c_get_cred_cache: got kadmin ticket from cache for client=%s", + client ? krb5_principal_get_comp_string(context, client, 0) : ""); *ret_cache = id; krb5_free_principal(context, default_client); if (default_client != client) krb5_free_principal(context, client); return 0; } + krb5_warn(context, ret, "_kadm5_c_get_cred_cache: get_kadm_ticket from cache failed for client=%s", client ? krb5_principal_get_comp_string(context, client, 0) : ""); if(ccache != NULL) /* couldn't get ticket from cache */ return -1; @@ -522,6 +610,21 @@ _kadm5_c_get_cred_cache(krb5_context context, ret = get_new_cache(context, client, password, prompter, keytab, server_name, ret_cache); + + /* + * Extra debug: report the result of get_new_cache so caller logs + * can show why auth succeeded/failed. + */ + if (ret == 0) { + krb5_warnx(context, "_kadm5_c_get_cred_cache: get_new_cache succeeded for client=%s (pid=%d)", + client ? krb5_principal_get_comp_string(context, client, 0) : "", + (int)getpid()); + } else { + krb5_warn(context, ret, "_kadm5_c_get_cred_cache: get_new_cache failed for client=%s (pid=%d)", + client ? krb5_principal_get_comp_string(context, client, 0) : "", + (int)getpid()); + } + krb5_free_principal(context, client); return ret; } @@ -545,6 +648,17 @@ kadm_connect(kadm5_client_context *ctx) krb5_context context = ctx->context; int writable = 0; + /* + * Extra debug: record connect intent and client context pointers + * to help correlate kadmin network activity with credential selection. + */ + krb5_warnx(context, "kadm_connect: entering (client_name=%s prompter=%p keytab=%s ccache=%p pid=%d)", + ctx->client_name ? ctx->client_name : "", + (void *)ctx->prompter, + ctx->keytab ? ctx->keytab : "", + (void *)ctx->ccache, + (int)getpid()); + if (ctx->ac) krb5_auth_con_free(context, ctx->ac); ctx->ac = NULL; @@ -658,6 +772,12 @@ out: rk_closesocket(s); krb5_auth_con_free(context, ctx->ac); ctx->ac = NULL; + } else { + /* Extra debug: successful connect and auth */ + krb5_warnx(context, "kadm_connect: success connected_to_writable=%d sock=%d (pid=%d)", + (int)ctx->connected_to_writable, + (int)ctx->sock, + (int)getpid()); } return ret; } @@ -704,6 +824,20 @@ kadm5_c_init_with_context(krb5_context context, kadm5_client_context *ctx = NULL; krb5_ccache cc; + /* + * Extra debug: record initialization flags and pointers so we can later + * understand whether a prompter was provided (which affects keytab vs + * password selection) and whether a keytab or ccache was requested. + */ + krb5_warnx(context, "kadm5_c_init_with_context: client_name=%s password_provided=%d prompter=%p keytab=%s ccache=%p service_name=%s (pid=%d)", + client_name ? client_name : "", + password ? 1 : 0, + (void *)prompter, + keytab ? keytab : "", + (void *)ccache, + service_name ? service_name : "", + (int)getpid()); + ret = _kadm5_c_init_context(&ctx, realm_params, context); if (ret) return ret; @@ -736,6 +870,19 @@ kadm5_c_init_with_context(krb5_context context, ctx->sock = -1; *server_handle = ctx; + + /* + * Extra debug: final context values after init so logs show what the + * kadm client will carry into subsequent connect attempts. + */ + krb5_warnx(context, "kadm5_c_init_with_context: done ctx=%p client_name=%s prompter=%p keytab=%s ccache=%p (pid=%d)", + (void *)ctx, + ctx->client_name ? ctx->client_name : "", + (void *)ctx->prompter, + ctx->keytab ? ctx->keytab : "", + (void *)ctx->ccache, + (int)getpid()); + return 0; } @@ -922,4 +1069,3 @@ kadm5_init(char *client_name, char *pass, { } #endif - diff --git a/lib/krb5/expand_hostname.c b/lib/krb5/expand_hostname.c index 1f1824f76..02f1a48a7 100644 --- a/lib/krb5/expand_hostname.c +++ b/lib/krb5/expand_hostname.c @@ -69,17 +69,22 @@ krb5_expand_hostname (krb5_context context, int error; if ((context->flags & KRB5_CTX_F_DNS_CANONICALIZE_HOSTNAME) == 0 || - krb5_config_get_bool(context, NULL, "libdefaults", "block_dns", NULL)) + krb5_config_get_bool(context, NULL, "libdefaults", "block_dns", NULL)) { + krb5_warnx(context, "krb5_expand_hostname: DNS canonicalization disabled or blocked for hostname %s", orig_hostname); return copy_hostname (context, orig_hostname, new_hostname); + } memset (&hints, 0, sizeof(hints)); hints.ai_flags = AI_CANONNAME; error = getaddrinfo (orig_hostname, NULL, &hints, &ai); - if (error) + if (error) { + krb5_warnx(context, "krb5_expand_hostname: getaddrinfo(%s) failed: %s", orig_hostname, gai_strerror(error)); return copy_hostname (context, orig_hostname, new_hostname); + } for (a = ai; a != NULL; a = a->ai_next) { if (a->ai_canonname != NULL) { + krb5_warnx(context, "krb5_expand_hostname: canonical name for %s -> %s", orig_hostname, a->ai_canonname); *new_hostname = strdup (a->ai_canonname); freeaddrinfo (ai); if (*new_hostname == NULL) @@ -89,6 +94,7 @@ krb5_expand_hostname (krb5_context context, } } freeaddrinfo (ai); + krb5_warnx(context, "krb5_expand_hostname: no canonical name found for %s, falling back to copy_hostname", orig_hostname); return copy_hostname (context, orig_hostname, new_hostname); } @@ -145,20 +151,25 @@ krb5_expand_hostname_realms (krb5_context context, int error; krb5_error_code ret = 0; - if ((context->flags & KRB5_CTX_F_DNS_CANONICALIZE_HOSTNAME) == 0) + if ((context->flags & KRB5_CTX_F_DNS_CANONICALIZE_HOSTNAME) == 0) { + krb5_warnx(context, "krb5_expand_hostname_realms: DNS canonicalization disabled for hostname %s", orig_hostname); return vanilla_hostname (context, orig_hostname, new_hostname, realms); + } memset (&hints, 0, sizeof(hints)); hints.ai_flags = AI_CANONNAME; error = getaddrinfo (orig_hostname, NULL, &hints, &ai); - if (error) + if (error) { + krb5_warnx(context, "krb5_expand_hostname_realms: getaddrinfo(%s) failed: %s", orig_hostname, gai_strerror(error)); return vanilla_hostname (context, orig_hostname, new_hostname, realms); + } for (a = ai; a != NULL; a = a->ai_next) { if (a->ai_canonname != NULL) { + krb5_warnx(context, "krb5_expand_hostname_realms: canonical name for %s -> %s", orig_hostname, a->ai_canonname); ret = copy_hostname (context, a->ai_canonname, new_hostname); if (ret) { freeaddrinfo (ai); @@ -168,11 +179,13 @@ krb5_expand_hostname_realms (krb5_context context, ret = krb5_get_host_realm (context, *new_hostname, realms); if (ret == 0) { freeaddrinfo (ai); + krb5_warnx(context, "krb5_expand_hostname_realms: host %s mapped to realm %s", *new_hostname, realms && *realms ? (*realms)[0] : ""); return 0; } free (*new_hostname); } } freeaddrinfo(ai); + krb5_warnx(context, "krb5_expand_hostname_realms: no canonical name/realm found for %s, falling back to vanilla_hostname", orig_hostname); return vanilla_hostname (context, orig_hostname, new_hostname, realms); } diff --git a/lib/krb5/keytab.c b/lib/krb5/keytab.c index bcb3ed837..9c44adb80 100644 --- a/lib/krb5/keytab.c +++ b/lib/krb5/keytab.c @@ -217,6 +217,31 @@ krb5_kt_resolve(krb5_context context, residual = keytab_name(name, &type, &type_len); + /* + * Aggressive process-context logging: + * Print pid/ppid/uid/gid and the raw name string being resolved + * so test captures show which process attempted to resolve which + * keytab and with what parsed type/residual. + * + * We intentionally always emit this via krb5_warnx to make sure it + * appears in stderr/journal during tests. + */ + { + pid_t pid = getpid(); + pid_t ppid = getppid(); + uid_t uid = getuid(); + gid_t gid = getgid(); + krb5_warnx(context, + "krb5_kt_resolve: pid=%d ppid=%d uid=%d gid=%d resolving name=\"%s\" parsed_type=\"%.*s\" residual=\"%s\"", + (int)pid, + (int)ppid, + (int)uid, + (int)gid, + name ? name : "", + (int)type_len, type ? type : "", + residual ? residual : ""); + } + for(i = 0; i < context->num_kt_types; i++) { if(strncasecmp(type, context->kt_types[i].prefix, type_len) == 0) break; @@ -251,8 +276,15 @@ static const char *default_ktname(krb5_context context) const char *tmp = NULL; tmp = secure_getenv("KRB5_KTNAME"); - if(tmp != NULL) + if(tmp != NULL) { + /* Aggressive logging: record environment override */ + krb5_warnx(context, "default_ktname: using KRB5_KTNAME from env: \"%s\" (pid=%d)", tmp, (int)getpid()); return tmp; + } + /* Aggressive logging: record context default choice as well */ + krb5_warnx(context, "default_ktname: using context->default_keytab: \"%s\" (pid=%d)", + context->default_keytab ? context->default_keytab : "", + (int)getpid()); return context->default_keytab; } @@ -597,6 +629,13 @@ _krb5_kt_principal_not_found(krb5_context context, else kvno_str[0] = '\0'; + /* Provide a concise debug line so tests can see what principal/keytab/enctype failed */ + krb5_warnx(context, "kt_principal_not_found: principal=%s kvno=%s keytab=%s enctype=%s", + princ ? princ : "", + kvno_str[0] ? kvno_str : "", + kt_name ? kt_name : "unknown keytab", + enctype_str ? enctype_str : "unknown enctype"); + krb5_set_error_message(context, ret, N_("Failed to find %s%s in keytab %s (%s)", "principal, kvno, keytab file, enctype"), @@ -636,27 +675,81 @@ krb5_kt_get_entry_wrapped(krb5_context context, entry->vno = 0; while (krb5_kt_next_entry(context, id, &tmp, &cursor) == 0) { + /* Always-log the entry we're inspecting and what is being requested */ + { + char *entry_unp = NULL; + char *want_unp = NULL; + + (void) krb5_unparse_name(context, tmp.principal, &entry_unp); + (void) krb5_unparse_name(context, principal, &want_unp); + + krb5_warnx(context, "krb5_kt_get_entry_wrapped: inspecting entry=%s vno=%d enctype=%d against requested=%s kvno=%u enctype=%d", + entry_unp ? entry_unp : "", + tmp.vno, + tmp.keyblock.keytype, + want_unp ? want_unp : "", + (unsigned)kvno, + (int)enctype); + + free(entry_unp); + free(want_unp); + } + if (krb5_kt_compare(context, &tmp, principal, 0, enctype)) { /* the file keytab might only store the lower 8 bits of the kvno, so only compare those bits */ if (kvno == tmp.vno || (tmp.vno < 256 && kvno % 256 == tmp.vno)) { + /* Matched principal and kvno -> return this entry */ + { + char *matched = NULL; + (void) krb5_unparse_name(context, tmp.principal, &matched); + krb5_warnx(context, "krb5_kt_get_entry_wrapped: matched entry=%s vno=%d enctype=%d -- returning", + matched ? matched : "", + tmp.vno, + tmp.keyblock.keytype); + free(matched); + } krb5_kt_copy_entry_contents (context, &tmp, entry); krb5_kt_free_entry (context, &tmp); krb5_kt_end_seq_get(context, id, &cursor); return 0; } else if (kvno == 0 && tmp.vno > entry->vno) { + /* Matched principal but kvno selection logic prefers a higher vno */ + { + char *matched = NULL; + (void) krb5_unparse_name(context, tmp.principal, &matched); + krb5_warnx(context, "krb5_kt_get_entry_wrapped: matched principal %s but kvno differs (entry.vno=%d tmp.vno=%d); selecting higher vno for now", + matched ? matched : "", + entry->vno, + tmp.vno); + free(matched); + } if (entry->vno) krb5_kt_free_entry (context, entry); krb5_kt_copy_entry_contents (context, &tmp, entry); + } else { + /* Matched name but kvno didn't match and we are not in kvno-selection mode; log it. */ + char *matched = NULL; + (void) krb5_unparse_name(context, tmp.principal, &matched); + krb5_warnx(context, "krb5_kt_get_entry_wrapped: matched principal %s but kvno mismatch (tmp.vno=%d requested_kvno=%u); continuing iteration", + matched ? matched : "", + tmp.vno, + (unsigned)kvno); + free(matched); } } krb5_kt_free_entry(context, &tmp); } krb5_kt_end_seq_get (context, id, &cursor); - if (entry->vno == 0) + if (entry->vno == 0) { + /* No matching kvno was found in the keytab iteration; log and return */ + krb5_warnx(context, "krb5_kt_get_entry_wrapped: no matching entry found -> invoking _krb5_kt_principal_not_found"); return _krb5_kt_principal_not_found(context, KRB5_KT_NOTFOUND, id, principal, enctype, kvno); + } + krb5_warnx(context, "krb5_kt_get_entry_wrapped: returning selected entry vno=%d enctype=%d", + entry->vno, entry->keyblock.keytype); return 0; } @@ -688,6 +781,25 @@ krb5_kt_get_entry(krb5_context context, krb5_const_principal try_princ; krb5_name_canon_iterator name_canon_iter; + /* Debug: record incoming keytab lookup request (always emitted) */ + { + char *want_unp = NULL; + char *kt_full = NULL; + + if (principal && krb5_unparse_name(context, principal, &want_unp) != 0) + want_unp = NULL; + (void) krb5_kt_get_full_name(context, id, &kt_full); + + krb5_warnx(context, "krb5_kt_get_entry: requested principal=%s keytab=%s kvno=%u enctype=%d", + want_unp ? want_unp : "", + kt_full ? kt_full : "", + (unsigned)kvno, + (int)enctype); + + free(want_unp); + free(kt_full); + } + if (!principal) /* Use `NULL' instead of `principal' to quiet static analizers */ return krb5_kt_get_entry_wrapped(context, id, NULL, kvno, enctype, diff --git a/lib/krb5/keytab_file.c b/lib/krb5/keytab_file.c index 61b5d6d29..a8d15a5a2 100644 --- a/lib/krb5/keytab_file.c +++ b/lib/krb5/keytab_file.c @@ -380,9 +380,19 @@ fkt_start_seq_get_int(krb5_context context, d->filename, strerror(ret)); return ret; } + + /* Loud logging: record that we opened the keytab file and process info */ + krb5_warnx(context, "fkt_start_seq_get_int: opened keytab \"%s\" fd=%d flags=0x%x pid=%d uid=%d", + d->filename ? d->filename : "", + c->fd, + (unsigned)flags, + (int)getpid(), + (int)getuid()); + rk_cloexec(c->fd); ret = _krb5_xlock(context, c->fd, exclusive, d->filename); if (ret) { + krb5_warnx(context, "fkt_start_seq_get_int: failed to lock keytab \"%s\": ret=%d", d->filename ? d->filename : "", ret); close(c->fd); return ret; } @@ -394,6 +404,7 @@ fkt_start_seq_get_int(krb5_context context, stdio_mode = "wb"; c->sp = krb5_storage_stdio_from_fd(c->fd, stdio_mode); if (c->sp == NULL) { + krb5_warnx(context, "fkt_start_seq_get_int: krb5_storage_stdio_from_fd returned NULL for \"%s\"", d->filename ? d->filename : ""); close(c->fd); return krb5_enomem(context); } @@ -403,12 +414,17 @@ fkt_start_seq_get_int(krb5_context context, krb5_storage_free(c->sp); close(c->fd); krb5_clear_error_message(context); + krb5_warnx(context, "fkt_start_seq_get_int: failed reading pvno from \"%s\": ret=%d", d->filename ? d->filename : "", ret); return ret; } + /* Log the pvno read */ + krb5_warnx(context, "fkt_start_seq_get_int: keytab \"%s\" pvno=%d", d->filename ? d->filename : "", (int)pvno); + if(pvno != 5) { krb5_storage_free(c->sp); close(c->fd); krb5_clear_error_message (context); + krb5_warnx(context, "fkt_start_seq_get_int: keytab \"%s\" has bad vno (%d)", d->filename ? d->filename : "", (int)pvno); return KRB5_KEYTAB_BADVNO; } ret = krb5_ret_int8(c->sp, &tag); @@ -416,10 +432,19 @@ fkt_start_seq_get_int(krb5_context context, krb5_storage_free(c->sp); close(c->fd); krb5_clear_error_message(context); + krb5_warnx(context, "fkt_start_seq_get_int: failed reading tag from \"%s\": ret=%d", d->filename ? d->filename : "", ret); return ret; } + + /* Log the tag/version we read */ + krb5_warnx(context, "fkt_start_seq_get_int: keytab \"%s\" header tag=%d", d->filename ? d->filename : "", (int)tag); + id->version = tag; storage_set_flags(context, c->sp, id->version); + + /* Final confirmation log */ + krb5_warnx(context, "fkt_start_seq_get_int: keytab \"%s\" opened successfully (fd=%d, version=%d)", d->filename ? d->filename : "", c->fd, (int)id->version); + return 0; } @@ -450,26 +475,50 @@ fkt_next_entry_int(krb5_context context, pos = krb5_storage_seek(cursor->sp, 0, SEEK_CUR); loop: ret = krb5_ret_int32(cursor->sp, &len); - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: krb5_ret_int32 returned %d for keytab \"%s\" at pos=%lld", ret, d->filename ? d->filename : "", (long long)pos); return ret; + } if(len < 0) { pos = krb5_storage_seek(cursor->sp, -len, SEEK_CUR); goto loop; } ret = krb5_kt_ret_principal (context, d, cursor->sp, &entry->principal); - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: krb5_kt_ret_principal failed for keytab \"%s\" at pos=%lld: ret=%d", d->filename ? d->filename : "", (long long)pos, ret); goto out; + } ret = krb5_ret_uint32(cursor->sp, &utmp32); entry->timestamp = utmp32; - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: failed reading timestamp for keytab \"%s\" at pos=%lld: ret=%d", d->filename ? d->filename : "", (long long)pos, ret); goto out; + } ret = krb5_ret_int8(cursor->sp, &tmp8); - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: failed reading vno (8bit) for keytab \"%s\" at pos=%lld: ret=%d", d->filename ? d->filename : "", (long long)pos, ret); goto out; + } entry->vno = tmp8; ret = krb5_kt_ret_keyblock (context, d, cursor->sp, &entry->keyblock); - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: krb5_kt_ret_keyblock failed for keytab \"%s\" at pos=%lld: ret=%d", d->filename ? d->filename : "", (long long)pos, ret); goto out; + } + + /* Log the entry we just read (principal, vno, enctype, timestamp) */ + { + char *princname = NULL; + (void) krb5_unparse_name(context, entry->principal, &princname); + krb5_warnx(context, "fkt_next_entry_int: read entry principal=%s pos=%lld timestamp=%u vno=%d enctype=%d", + princname ? princname : "", + (long long)pos, + (unsigned)entry->timestamp, + entry->vno, + entry->keyblock.keytype); + free(princname); + } + /* there might be a 32 bit kvno here * if it's zero, assume that the 8bit one was right, * otherwise trust the new value */ @@ -492,8 +541,10 @@ loop: if(start) *start = pos; if(end) *end = pos + 4 + len; out: - if (ret) + if (ret) { + krb5_warnx(context, "fkt_next_entry_int: error reading keytab \"%s\" at pos=%lld: ret=%d", d->filename ? d->filename : "", (long long)pos, ret); krb5_kt_free_entry(context, entry); + } krb5_storage_seek(cursor->sp, pos + 4 + len, SEEK_SET); return ret; } diff --git a/lib/krb5/principal.c b/lib/krb5/principal.c index f8a61cfc7..ed8d4ebfc 100644 --- a/lib/krb5/principal.c +++ b/lib/krb5/principal.c @@ -1466,18 +1466,23 @@ krb5_sname_to_principal(krb5_context context, for (cp = remote_host; *cp; cp++) if (isupper((unsigned char) (*cp))) *cp = tolower((unsigned char) (*cp)); + /* Debug-ish: record the input/normalized hostname and service for tracing. */ + krb5_warnx(context, "krb5_sname_to_principal: remote_host=%s sname=%s type=%d", + remote_host ? remote_host : "", + sname ? sname : "", + (int)type); /* * If there is only one name canon rule and it says to * canonicalize the old way, do that now, as we used to. */ - ret = _krb5_get_name_canon_rules(context, &rules); - if (ret) { - _krb5_debug(context, 5, "Failed to get name canon rules: ret = %d", - ret); - free(remote_host); - return ret; - } + ret = _krb5_get_name_canon_rules(context, &rules); + if (ret) { + krb5_warnx(context, "Failed to get name canon rules: ret = %d", + ret); + free(remote_host); + return ret; + } if (rules[0].type == KRB5_NCRT_NSS && rules[1].type == KRB5_NCRT_BOGUS) { _krb5_debug(context, 5, "Using nss for name canon immediately"); @@ -1895,6 +1900,17 @@ apply_name_canon_rule(krb5_context context, krb5_name_canon_rule rules, _krb5_debug(context, 5, N_("Applying a name rule (type %d) to %s", ""), rule->type, orig_hostname); + /* Extra debug: print rule details to help trace name canonicalization. */ + krb5_warnx(context, "name_canon: rule_idx=%zu type=%d mindots=%u maxdots=%u match_domain=%s match_realm=%s realm=%s domain=%s options=0x%x", + rule_idx, + (int)rule->type, + (unsigned)rule->mindots, + (unsigned)rule->maxdots, + rule->match_domain ? rule->match_domain : "", + rule->match_realm ? rule->match_realm : "", + rule->realm ? rule->realm : "", + rule->domain ? rule->domain : "", + (int)rule->options); if (rule->mindots > 0 || rule->maxdots > 0) { for (cp = strchr(orig_hostname, '.'); cp && *cp; cp = strchr(cp + 1, '.')) @@ -1929,36 +1945,38 @@ apply_name_canon_rule(krb5_context context, krb5_name_canon_rule rules, new_hostname = tmp_hostname; break; - case KRB5_NCRT_NSS: - if ((rule->options & KRB5_NCRO_USE_DNSSEC)) { - ret = KRB5KDC_ERR_S_PRINCIPAL_UNKNOWN; - krb5_set_error_message(context, ret, - "Secure hostname resolution not supported"); - goto out; - } - _krb5_debug(context, 5, "Using name service lookups"); - ret = krb5_sname_to_principal_old(context, rule->realm, - orig_hostname, sname, - KRB5_NT_SRV_HST, - &nss); - if (rules[rule_idx + 1].type != KRB5_NCRT_BOGUS && - (ret == KRB5_ERR_BAD_HOSTNAME || - ret == KRB5_ERR_HOST_REALM_UNKNOWN)) { - /* - * Bad hostname / realm unknown -> rule inapplicable if - * there's more rules. If it's the last rule then we want - * to return all errors from krb5_sname_to_principal_old() - * here. - */ - ret = 0; - goto out; - } - if (ret) - goto out; + case KRB5_NCRT_NSS: + if ((rule->options & KRB5_NCRO_USE_DNSSEC)) { + ret = KRB5KDC_ERR_S_PRINCIPAL_UNKNOWN; + krb5_set_error_message(context, ret, + "Secure hostname resolution not supported"); + goto out; + } + _krb5_debug(context, 5, "Using name service lookups"); + ret = krb5_sname_to_principal_old(context, rule->realm, + orig_hostname, sname, + KRB5_NT_SRV_HST, + &nss); + /* If subsequent rule exists and we got a hostname/realm error, + * treat this rule as inapplicable (unless last rule). */ + if (rules[rule_idx + 1].type != KRB5_NCRT_BOGUS && + (ret == KRB5_ERR_BAD_HOSTNAME || + ret == KRB5_ERR_HOST_REALM_UNKNOWN)) { + ret = 0; + goto out; + } + if (ret) { + _krb5_debug(context, 3, "krb5_sname_to_principal_old failed for %s: ret=%d", orig_hostname, ret); + goto out; + } - new_hostname = krb5_principal_get_comp_string(context, nss, 1); - new_realm = krb5_principal_get_realm(context, nss); - break; + new_hostname = krb5_principal_get_comp_string(context, nss, 1); + new_realm = krb5_principal_get_realm(context, nss); + /* Log what nss resolution produced for inspection in tests */ + _krb5_debug(context, 3, "krb5_sname_to_principal_old: resolved %s -> canonical=%s realm=%s", orig_hostname, + new_hostname ? new_hostname : "", + new_realm ? new_realm : ""); + break; default: /* Can't happen */