From 12cda360eaf57b6919b6b4724b139d9394e0e1cf Mon Sep 17 00:00:00 2001 From: John Johansen Date: Tue, 2 May 2023 04:57:07 -0700 Subject: [PATCH] UBUNTU: SAUCE: apparmor4.0.0 [57/90]: prompt - Improve debug statements BugLink: http://bugs.launchpad.net/bugs/2028253 Prompting debug is missing some output that can be helpful when debugging. Signed-off-by: John Johansen (cherry picked from https://gitlab.com/jjohansen/apparmor-kernel) Signed-off-by: Andrea Righi (cherry picked from commit 566e51cd6a4284623362c0a925e410160d84a56a https://git.launchpad.net/~apparmor-dev/ubuntu-kernel-next) Signed-off-by: Paolo Pisati --- security/apparmor/file.c | 32 ++++++++++++------- security/apparmor/include/lib.h | 2 +- security/apparmor/notify.c | 56 ++++++++++++++++++--------------- 3 files changed, 52 insertions(+), 38 deletions(-) diff --git a/security/apparmor/file.c b/security/apparmor/file.c index 10c4119b510b..5bc9b947c91e 100644 --- a/security/apparmor/file.c +++ b/security/apparmor/file.c @@ -96,28 +96,29 @@ static int check_cache(struct aa_profile *profile, /* TODO: need rcu locking around whole check once we allow * removing node from cache */ - AA_DEBUG(DEBUG_UPCALL, "attempting prompt upcall pid %d name:'%s'", - current->pid, ad->name); + AA_DEBUG(DEBUG_UPCALL, "cache check: profile '%s', pid %d name:'%s'", + profile->base.hname, current->pid, ad->name); hit = aa_audit_cache_find(&profile->learning_cache, ad); if (hit) { - AA_DEBUG(DEBUG_UPCALL, "matched node in profile cache"); + AA_DEBUG(DEBUG_UPCALL, " matched node in audit cache"); if (ad->request & hit->data.denied) { /* this request could only partly succeed prompting for * the part and failing makes no sense */ AA_DEBUG(DEBUG_UPCALL, - "cache hit denied, request: 0x%x by cached deny 0x%x\n", + " hit denied, request: 0x%x by cached deny 0x%x\n", ad->request, hit->data.denied); aa_put_audit_node(hit); return ad->error; } else if (ad->request & ~hit->data.request) { /* asking for more perms than is cached */ AA_DEBUG(DEBUG_UPCALL, - "cache miss insufficient perms, request: 0x%x cached 0x%x\n", + " miss insufficient perms, request: 0x%x cached 0x%x\n", ad->request, hit->data.request); /* continue to do prompt */ } else { - AA_DEBUG(DEBUG_UPCALL, "cache hit"); + AA_DEBUG(DEBUG_UPCALL, "cache hit->error %d. returning 0", + hit->data.error); aa_put_audit_node(hit); /* don't audit: if its in the cache already audited */ return 1; @@ -161,7 +162,7 @@ static int check_user(struct aa_profile *profile, if (err) { // do we want to do something special with -ERESTARTSYS AA_DEBUG(DEBUG_UPCALL, "notifcation failed with error %d\n", - ad->error); + err); goto return_to_audit; } @@ -219,14 +220,21 @@ int aa_audit_file(const struct cred *subj_cred, /* learning cache - not audit dedup yet */ err = check_cache(profile, &ad); - if (err != 0) + if (err != 0) { + AA_DEBUG(DEBUG_UPCALL, "cache early bail %d\n", err); /* cached */ - return ad.error; - + return ad.err; + } implicit_deny = (ad.request & ~perms->allow) & ~perms->deny; if (USER_MODE(profile)) perms->prompt = ALL_PERMS_MASK; + if (ad.request & MAY_EXEC) + AA_DEBUG(DEBUG_UPCALL, + "do prompt %d: exec req 0x%x, allow 0x%x, deny 0x%x, ideny 0x%x, prompt 0x%x", + prompt, ad.request, perms->allow, perms->deny, + implicit_deny, perms->prompt); + /* don't prompt * - if explicit deny * - if implicit_deny is not entirely covered by prompt @@ -235,9 +243,11 @@ int aa_audit_file(const struct cred *subj_cred, if (prompt && !(request & perms->deny) && (perms->prompt & implicit_deny) == implicit_deny) { err = check_user(profile, &ad, perms); - if (err == -ERESTARTSYS) + if (err == -ERESTARTSYS) { + AA_DEBUG(DEBUG_UPCALL, " check user returned -ERESTART_SYS"); /* are there other errors we should bail on */ return err; + } } } diff --git a/security/apparmor/include/lib.h b/security/apparmor/include/lib.h index 49a0c586fade..7ea3bbf8ee21 100644 --- a/security/apparmor/include/lib.h +++ b/security/apparmor/include/lib.h @@ -46,7 +46,7 @@ extern struct aa_dfa *stacksplitdfa; #define AA_DEBUG(opt, fmt, args...) \ do { \ if (aa_g_debug & opt) \ - pr_warn_ratelimited("%s: " fmt, __func__, ##args); \ + pr_warn("%s: " fmt, __func__, ##args); \ } while (0) #define AA_DEBUG_ON(C, args...) do { if (C) AA_DEBUG(args); } while (0) #define AA_DEBUG_LABEL(LAB, X, fmt, args) \ diff --git a/security/apparmor/notify.c b/security/apparmor/notify.c index 647791f88504..b650a10c9f4b 100644 --- a/security/apparmor/notify.c +++ b/security/apparmor/notify.c @@ -326,13 +326,15 @@ static void dispatch_notif(struct aa_listener *listener, lockdep_assert_held(&listener->lock); AA_DEBUG_ON(knotif->id, DEBUG_UPCALL, - "redispatching notification with id %lld as new id %lld", + "id %lld: redispatching notification as new id %lld", knotif->id, listener->last_id); knotif->ntype = ntype; knotif->id = ++listener->last_id; init_completion(&knotif->ready); INIT_LIST_HEAD(&knotif->list); __listener_add_knotif(listener, knotif); + AA_DEBUG(DEBUG_UPCALL, "id %lld: %s wake_up_interruptible", + knotif->id, __func__); // TODO: wake up listener } @@ -358,16 +360,18 @@ static int handle_synchronous_notif(struct aa_listener *listener, __listener_del_knotif(listener, knotif); spin_unlock(&listener->lock); if (werr == 0) { - AA_DEBUG(DEBUG_UPCALL, "prompt timed out %lld", + AA_DEBUG(DEBUG_UPCALL, "id %lld: prompt timed out", knotif->id); //err = -1; // TODO: ???; err = 0; } else if (werr == -ERESTARTSYS) { // interrupt fired syscall needs to be restarted // instead of mediated + AA_DEBUG(DEBUG_UPCALL, "id %lld: prompt interrupted, error %ld", + knotif->id, werr); err = -ERESTARTSYS; } else { - AA_DEBUG(DEBUG_UPCALL, "prompt errored out %lld error %ld", + AA_DEBUG(DEBUG_UPCALL, "id %lld: prompt errored out error %ld", knotif->id, werr); err = (int) werr; } @@ -380,7 +384,7 @@ static int handle_synchronous_notif(struct aa_listener *listener, if (!list_empty(&knotif->list)) { __listener_del_knotif(listener, knotif); AA_DEBUG(DEBUG_UPCALL, - "bug prompt knotif still on listener list at notif completion %lld", + "id %lld: bug prompt knotif still on listener list at notif completion", knotif->id); } spin_unlock(&listener->lock); @@ -419,7 +423,7 @@ int aa_do_notification(u16 ntype, struct aa_audit_node *node) /* delvier notification - dispatch determines if we break */ dispatch_notif(listener, ntype, knotif); // count); spin_unlock(&listener->lock); - AA_DEBUG(DEBUG_UPCALL, "found listener for %lld\n", + AA_DEBUG(DEBUG_UPCALL, "id %lld: found listener\n", knotif->id); /* break to prompt */ @@ -433,8 +437,8 @@ int aa_do_notification(u16 ntype, struct aa_audit_node *node) aa_put_listener(listener); } spin_unlock(&ns->listener_lock); - AA_DEBUG(DEBUG_UPCALL, "%d listener matches for %lld\n", count, - knotif->id); + AA_DEBUG(DEBUG_UPCALL, "id %lld: %d listener matches\n", + knotif->id, count); /* count == 0 is no match found. No change to audit params * long term need to fold prompt perms into denied @@ -453,8 +457,8 @@ static bool response_is_valid(struct apparmor_notif_resp *reply, if ((knotif->ad->request | knotif->ad->denied) & ~(reply->allow | reply->deny)) { AA_DEBUG(DEBUG_UPCALL, - "response does not cover permission bits in the upcall request/reply 0x%x/0x%x deny/reply 0x%x/0x%x", - knotif->ad->request, reply->allow, knotif->ad->denied, + "id %lld: response does not cover permission bits in the upcall request/reply 0x%x/0x%x deny/reply 0x%x/0x%x", + knotif->id, knotif->ad->request, reply->allow, knotif->ad->denied, reply->deny); return false; } @@ -531,7 +535,7 @@ long aa_listener_unotif_response(struct aa_listener *listener, } if (!response_is_valid(uresp, knotif)) { ret = -EINVAL; - AA_DEBUG(DEBUG_UPCALL, "response not valid"); + AA_DEBUG(DEBUG_UPCALL, "id %lld: response not valid", knotif->id); __listener_complete_user_pending(listener, knotif, NULL); goto out; } @@ -546,19 +550,16 @@ long aa_listener_unotif_response(struct aa_listener *listener, struct aa_audit_node *hit; struct aa_profile *profile = labels_profile(node->data.subj_label); - /* TODO: shouldn't add until after auditing it, or at - * least having a refcount. Fix once removing entry is - * allowed - */ - AA_DEBUG(DEBUG_UPCALL, "inserting cache entry requ 0x%x denied 0x%x", - node->data.request, node->data.denied); + AA_DEBUG(DEBUG_UPCALL, "id %lld: inserting cache entry requ 0x%x denied 0x%x", + knotif->id, node->data.request, node->data.denied); hit = aa_audit_cache_insert(&profile->learning_cache, node); - AA_DEBUG(DEBUG_UPCALL, "cache insert %s: name %s node %s\n", - hit != node ? "lost race" : "", + AA_DEBUG(DEBUG_UPCALL, "id %lld: cache insert %s: name %s node %s\n", + knotif->id, hit != node ? "lost race" : "", hit->data.name, node->data.name); if (hit != node) { - AA_DEBUG(DEBUG_UPCALL, "updating existing cache entry"); + AA_DEBUG(DEBUG_UPCALL, "id %lld: updating existing cache entry", + knotif->id); aa_audit_cache_update_ent(&profile->learning_cache, hit, &node->data); aa_put_audit_node(hit); @@ -572,7 +573,7 @@ long aa_listener_unotif_response(struct aa_listener *listener, ret = size; - AA_DEBUG(DEBUG_UPCALL, "completing notif %lld", knotif->id); + AA_DEBUG(DEBUG_UPCALL, "id %lld: completing notif", knotif->id); __listener_complete_user_pending(listener, knotif, uresp); out: spin_unlock(&listener->lock); @@ -592,8 +593,10 @@ static long build_v3_unotif(struct aa_knotif *knotif, void __user *buf, int psize, nsize = 0; u16 size; + AA_DEBUG(DEBUG_UPCALL, "building notif max size %d", max_size); size = sizeof(unotif); profile = labels_profile(knotif->ad->subj_label); + AA_BUG(profile == NULL); psize = strlen(profile->base.hname) + 1; size += psize; if (knotif->ad->name) @@ -651,15 +654,16 @@ static long build_mediation_notif(struct aa_listener *listener, ret = build_v3_unotif(knotif, buf, max_size); if (ret < 0) { AA_DEBUG(DEBUG_UPCALL, - "error (%ld): failed to copy to notif %lld data to user reading size %ld, maxsize %d", - ret, knotif->id, + "id %lld: (error=%ld) failed to copy data to user reading size %ld, maxsize %d", + knotif->id, ret, sizeof(union apparmor_notif_all), max_size); listener_repush_knotif(listener, knotif); goto out; } break; default: - AA_DEBUG(DEBUG_UPCALL, "unknown notification class"); + AA_BUG("unknown notification class"); + AA_DEBUG(DEBUG_UPCALL, "id %lld: unknown notification class", knotif->id); /* skip and move onto the next notification * release knotif * currently knotif cleanup handled by waking task in @@ -687,7 +691,7 @@ long aa_listener_unotif_recv(struct aa_listener *listener, void __user *buf, ret = -ENOENT; break; } - AA_DEBUG(DEBUG_UPCALL, "removed notif %lld from listener queue", + AA_DEBUG(DEBUG_UPCALL, "id %lld: removed notif from listener queue", knotif->id); ret = build_mediation_notif(listener, knotif, buf, max_size); @@ -697,10 +701,10 @@ long aa_listener_unotif_recv(struct aa_listener *listener, void __user *buf, goto out; if (knotif->ad->type == AUDIT_APPARMOR_USER) { - AA_DEBUG(DEBUG_UPCALL, "adding notif %lld to pending", knotif->id); + AA_DEBUG(DEBUG_UPCALL, "id %lld: adding notif to pending", knotif->id); listener_push_user_pending(listener, knotif); } else { - AA_DEBUG(DEBUG_UPCALL, "non-prompt audit in notif"); + AA_DEBUG(DEBUG_UPCALL, "id %lld: non-prompt audit notif delivered", knotif->id); } out: return ret;