system/posix-acl: Log reason for EACCES

It is becoming increasingly difficult to debug the reason why posix-acl decides
to fail a fop with EACCES. This patch prints a big log everytime such
a condition occurs giving out the details that may help in finding why the fop
is errored out.

Change-Id: I2505baaafb5d77ef6c187554ff027df9b20468db
BUG: 1394548
Signed-off-by: Pranith Kumar K <pkarampu@redhat.com>
Reviewed-on: http://review.gluster.org/15837
Smoke: Gluster Build System <jenkins@build.gluster.org>
NetBSD-regression: NetBSD Build System <jenkins@build.gluster.org>
CentOS-regression: Gluster Build System <jenkins@build.gluster.org>
Reviewed-by: Raghavendra Talur <rtalur@redhat.com>

7 files changed, 176 insertions, 17 deletions

diff --git a/libglusterfs/src/common-utils.c b/libglusterfs/src/common-utils.c
index 14a344958fd..18c2a39d60e 100644
--- a/libglusterfs/src/common-utils.c
+++ b/libglusterfs/src/common-utils.c
@@ -36,7 +36,6 @@
 #endif
 #include <libgen.h>
 
-#include "glusterfs-acl.h"
 #include "compat-errno.h"
 #include "logging.h"
 #include "common-utils.h"
@@ -4588,3 +4587,11 @@ gf_bits_index (uint64_t n)
 {
     return ffsll(n) - 1;
 }
+
+const char*
+gf_fop_string (glusterfs_fop_t fop)
+{
+        if ((fop > GF_FOP_NULL) && (fop < GF_FOP_MAXVALUE))
+                return gf_fop_list[fop];
+        return "INVALID";
+}
diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h
index 082a44403dc..324555b34f5 100644
--- a/libglusterfs/src/common-utils.h
+++ b/libglusterfs/src/common-utils.h
@@ -866,4 +866,6 @@ gf_bits_count (uint64_t n);
 int32_t
 gf_bits_index (uint64_t n);
 
+const char*
+gf_fop_string (glusterfs_fop_t fop);
 #endif /* _COMMON_UTILS_H */
diff --git a/libglusterfs/src/glfs-message-id.h b/libglusterfs/src/glfs-message-id.h
index 8601c5cc5ab..d77e90cbec9 100644
--- a/libglusterfs/src/glfs-message-id.h
+++ b/libglusterfs/src/glfs-message-id.h
@@ -181,7 +181,11 @@ GLFS_MSGID_COMP_SYMLINK_CACHE_END
 
 #define GLFS_MSGID_COMP_INDEX              GLFS_MSGID_COMP_LEASES_END
 #define GLFS_MSGID_COMP_INDEX_END          (GLFS_MSGID_COMP_INDEX +\
-                                            GLFS_MSGID_SEGMENT)
+                                           GLFS_MSGID_SEGMENT)
+
+#define GLFS_MSGID_COMP_POSIX_ACL          GLFS_MSGID_COMP_INDEX_END
+#define GLFS_MSGID_COMP_POSIX_ACL_END      (GLFS_MSGID_COMP_POSIX_ACL +\
+                                           GLFS_MSGID_SEGMENT)
 /* --- new segments for messages goes above this line --- */
 
 #endif /* !_GLFS_MESSAGE_ID_H_ */
diff --git a/libglusterfs/src/glusterfs-acl.h b/libglusterfs/src/glusterfs-acl.h
index 55f94ff0509..2a1661686bc 100644
--- a/libglusterfs/src/glusterfs-acl.h
+++ b/libglusterfs/src/glusterfs-acl.h
@@ -100,6 +100,7 @@ struct posix_acl_ctx {
         uid_t             uid;
         gid_t             gid;
         mode_t            perm;
+        glusterfs_fop_t   fop;
         struct posix_acl *acl_access;
         struct posix_acl *acl_default;
 };
diff --git a/xlators/system/posix-acl/src/Makefile.am b/xlators/system/posix-acl/src/Makefile.am
index c2214ecf4c9..f57070ce4a4 100644
--- a/xlators/system/posix-acl/src/Makefile.am
+++ b/xlators/system/posix-acl/src/Makefile.am
@@ -4,7 +4,8 @@ posix_acl_la_LDFLAGS = -module $(GF_XLATOR_DEFAULT_LDFLAGS)
 posix_acl_la_SOURCES = posix-acl.c posix-acl-xattr.c
 posix_acl_la_LIBADD = $(top_builddir)/libglusterfs/src/libglusterfs.la
 
-noinst_HEADERS = posix-acl.h posix-acl-xattr.h posix-acl-mem-types.h
+noinst_HEADERS = posix-acl.h posix-acl-xattr.h posix-acl-mem-types.h \
+		 posix-acl-messages.h
 
 AM_CPPFLAGS = $(GF_CPPFLAGS) -I$(top_srcdir)/libglusterfs/src \
 	-I$(top_srcdir)/rpc/xdr/src -I$(top_builddir)/rpc/xdr/src
diff --git a/xlators/system/posix-acl/src/posix-acl-messages.h b/xlators/system/posix-acl/src/posix-acl-messages.h
new file mode 100644
index 00000000000..ab93d749924
--- /dev/null
+++ b/xlators/system/posix-acl/src/posix-acl-messages.h
@@ -0,0 +1,56 @@
+/*
+ Copyright (c) 2016 Red Hat, Inc. <http://www.redhat.com>
+ This file is part of GlusterFS.
+
+ This file is licensed to you under your choice of the GNU Lesser
+ General Public License, version 3 or any later version (LGPLv3 or
+ later), or the GNU General Public License, version 2 (GPLv2), in all
+ cases as published by the Free Software Foundation.
+ */
+
+#ifndef _POSIX_ACL_MESSAGES_H_
+#define _POSIX_ACL_MESSAGES_H_
+
+#include "glfs-message-id.h"
+
+/*! \file posix-acl-messages.h
+ *  \brief POSIX-ACL log-message IDs and their descriptions.
+ */
+
+/* NOTE: Rules for message additions
+ * 1) Each instance of a message is _better_ left with a unique message ID, even
+ * if the message format is the same. Reasoning is that, if the message
+ * format needs to change in one instance, the other instances are not
+ * impacted or the new change does not change the ID of the instance being
+ * modified.
+ * 2) Addition of a message,
+ * - Should increment the GLFS_NUM_MESSAGES
+ * - Append to the list of messages defined, towards the end
+ * - Retain macro naming as glfs_msg_X (for redability across developers)
+ * NOTE: Rules for message format modifications
+ * 3) Check acorss the code if the message ID macro in question is reused
+ * anywhere. If reused then then the modifications should ensure correctness
+ * everywhere, or needs a new message ID as (1) above was not adhered to. If
+ * not used anywhere, proceed with the required modification.
+ * NOTE: Rules for message deletion
+ * 4) Check (3) and if used anywhere else, then cannot be deleted. If not used
+ * anywhere, then can be deleted, but will leave a hole by design, as
+ * addition rules specify modification to the end of the list and not filling
+ * holes.
+ */
+
+#define GLFS_COMP_BASE_POSIX_ACL      GLFS_MSGID_COMP_POSIX_ACL
+#define GLFS_NUM_MESSAGES       1
+#define GLFS_MSGID_END        (GLFS_COMP_BASE_POSIX_ACL + GLFS_NUM_MESSAGES + 1)
+
+#define glfs_msg_start_x GLFS_COMP_BASE_POSIX_ACL, "Invalid: Start of messages"
+
+/*!
+ * @messageid 139001
+ * @diagnosis Access to the file/directory for the operation is denied.
+ * @recommendedaction The log contains details as to why it denied access.
+ */
+#define POSIX_ACL_MSG_EACCES             (GLFS_COMP_BASE_POSIX_ACL + 1)
+
+#define glfs_msg_end_x GLFS_MSGID_END, "Invalid: End of messages"
+#endif /* !_POSIX_ACL_MESSAGES_H_ */
diff --git a/xlators/system/posix-acl/src/posix-acl.c b/xlators/system/posix-acl/src/posix-acl.c
index 9d467910339..9b3698618fa 100644
--- a/xlators/system/posix-acl/src/posix-acl.c
+++ b/xlators/system/posix-acl/src/posix-acl.c
@@ -16,7 +16,7 @@
 #include "posix-acl.h"
 #include "posix-acl-xattr.h"
 #include "posix-acl-mem-types.h"
-
+#include "posix-acl-messages.h"
 
 #define UINT64(ptr) ((uint64_t)((long)(ptr)))
 #define PTR(num) ((void *)((long)(num)))
@@ -181,6 +181,92 @@ sticky_permits (call_frame_t *frame, inode_t *parent, inode_t *inode)
         return 0;
 }
 
+static gf_boolean_t
+_does_acl_exist (struct posix_acl *acl)
+{
+        if (acl && (acl->count > POSIX_ACL_MINIMAL_ACE_COUNT))
+                return _gf_true;
+        return _gf_false;
+}
+
+static void
+posix_acl_get_acl_string (call_frame_t *frame, struct posix_acl *acl,
+                          char **acl_str)
+{
+        int                   i        = 0;
+        size_t                size_acl = 0;
+        size_t                offset   = 0;
+        struct posix_ace      *ace     = NULL;
+        char                  tmp_str[1024] = {0};
+#define NON_GRP_FMT "(tag:%"PRIu16",perm:%"PRIu16",id:%"PRIu32")"
+#define GRP_FMT "(tag:%"PRIu16",perm:%"PRIu16",id:%"PRIu32",in-groups:%d)"
+
+        if (!_does_acl_exist (acl))
+                goto out;
+
+        ace = acl->entries;
+        for (i = 0; i < acl->count; i++) {
+                if (ace->tag != POSIX_ACL_GROUP) {
+                        size_acl += snprintf (tmp_str, sizeof tmp_str,
+                                     NON_GRP_FMT, ace->tag, ace->perm, ace->id);
+                } else {
+                        size_acl += snprintf (tmp_str, sizeof tmp_str,
+                                        GRP_FMT, ace->tag,
+                                       ace->perm, ace->id,
+                                       frame_in_group (frame, ace->id));
+                }
+
+                ace++;
+        }
+
+        *acl_str = GF_CALLOC (1, size_acl + 1, gf_posix_acl_mt_char);
+        if (!*acl_str)
+                goto out;
+
+        ace = acl->entries;
+        for (i = 0; i < acl->count; i++) {
+                if (ace->tag != POSIX_ACL_GROUP) {
+                        offset += snprintf (*acl_str + offset,
+                                            size_acl - offset,
+                                     NON_GRP_FMT, ace->tag, ace->perm, ace->id);
+                } else {
+                        offset += snprintf (*acl_str + offset,
+                                       size_acl - offset,
+                                       GRP_FMT, ace->tag, ace->perm, ace->id,
+                                       frame_in_group (frame, ace->id));
+                }
+
+                ace++;
+        }
+out:
+        return;
+}
+
+static void
+posix_acl_log_permit_denied (call_frame_t *frame, inode_t *inode, int want,
+                             struct posix_acl_ctx *ctx, struct posix_acl *acl)
+{
+        char     *acl_str = NULL;
+        client_t *client  = frame->root->client;
+
+        if (!frame || !inode || !ctx)
+                goto out;
+
+        posix_acl_get_acl_string (frame, acl, &acl_str);
+
+        gf_msg (frame->this->name, GF_LOG_INFO, EACCES, POSIX_ACL_MSG_EACCES,
+                "client: %s, gfid: %s, req(uid:%d,gid:%d,perm:%d,"
+                "ngrps:%"PRIu16"), ctx(uid:%d,gid:%d,in-groups:%d,perm:%d%d%d,"
+                "updated-fop:%s, acl:%s)", client ? client->client_uid : "-",
+                uuid_utoa (inode->gfid), frame->root->uid, frame->root->gid,
+                want, frame->root->ngrps, ctx->uid, ctx->gid,
+                frame_in_group (frame, ctx->gid), (ctx->perm & S_IRWXU) >> 6,
+                (ctx->perm & S_IRWXG) >> 3, ctx->perm & S_IRWXO,
+                gf_fop_string (ctx->fop), acl_str ? acl_str : "-");
+out:
+        GF_FREE (acl_str);
+        return;
+}
 
 static int
 acl_permits (call_frame_t *frame, inode_t *inode, int want)
@@ -211,7 +297,7 @@ acl_permits (call_frame_t *frame, inode_t *inode, int want)
 
         ace = acl->entries;
 
-        if (acl->count > POSIX_ACL_MINIMAL_ACE_COUNT)
+        if (_does_acl_exist (acl))
                 acl_present = 1;
 
         for (i = 0; i < acl->count; i++) {
@@ -283,6 +369,7 @@ green:
         goto out;
 red:
         verdict = 0;
+        posix_acl_log_permit_denied (frame, inode, want, ctx, acl);
 out:
         if (acl)
                 posix_acl_unref (frame->this, acl);
@@ -786,9 +873,9 @@ posix_acl_inherit_file (xlator_t *this, loc_t *loc, dict_t *params, mode_t mode,
         return retmode;
 }
 
-
 int
-posix_acl_ctx_update (inode_t *inode, xlator_t *this, struct iatt *buf)
+posix_acl_ctx_update (inode_t *inode, xlator_t *this, struct iatt *buf,
+                      glusterfs_fop_t fop)
 {
         struct posix_acl_ctx *ctx = NULL;
 	struct posix_acl     *acl = NULL;
@@ -809,9 +896,10 @@ posix_acl_ctx_update (inode_t *inode, xlator_t *this, struct iatt *buf)
                 ctx->uid   = buf->ia_uid;
                 ctx->gid   = buf->ia_gid;
                 ctx->perm  = st_mode_from_ia (buf->ia_prot, buf->ia_type);
+                ctx->fop   = fop;
 
 		acl = ctx->acl_access;
-		if (!acl || !(acl->count > POSIX_ACL_MINIMAL_ACE_COUNT))
+                if (!_does_acl_exist (acl))
 			goto unlock;
 
 		/* This is an extended ACL (not minimal acl). In case we
@@ -853,7 +941,6 @@ unlock:
         return ret;
 }
 
-
 int
 posix_acl_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                       int op_ret, int op_errno, inode_t *inode,
@@ -911,7 +998,7 @@ acl_default:
         }
 
 acl_set:
-        posix_acl_ctx_update (inode, this, buf);
+        posix_acl_ctx_update (inode, this, buf, GF_FOP_LOOKUP);
 
         ret = posix_acl_set (inode, this, acl_access, acl_default);
         if (ret)
@@ -1283,7 +1370,7 @@ posix_acl_mkdir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, buf);
+        posix_acl_ctx_update (inode, this, buf, GF_FOP_MKDIR);
 
 unwind:
         STACK_UNWIND_STRICT (mkdir, frame, op_ret, op_errno, inode, buf,
@@ -1326,7 +1413,7 @@ posix_acl_mknod_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, buf);
+        posix_acl_ctx_update (inode, this, buf, GF_FOP_MKNOD);
 
 unwind:
         STACK_UNWIND_STRICT (mknod, frame, op_ret, op_errno, inode, buf,
@@ -1369,7 +1456,7 @@ posix_acl_create_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, buf);
+        posix_acl_ctx_update (inode, this, buf, GF_FOP_CREATE);
 
 unwind:
         STACK_UNWIND_STRICT (create, frame, op_ret, op_errno, fd, inode, buf,
@@ -1412,7 +1499,7 @@ posix_acl_symlink_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, buf);
+        posix_acl_ctx_update (inode, this, buf, GF_FOP_SYMLINK);
 
 unwind:
         STACK_UNWIND_STRICT (symlink, frame, op_ret, op_errno, inode, buf,
@@ -1700,7 +1787,8 @@ posix_acl_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                                     data->len);
 
         acl_set:
-                posix_acl_ctx_update (entry->inode, this, &entry->d_stat);
+                posix_acl_ctx_update (entry->inode, this, &entry->d_stat,
+                                      GF_FOP_READDIRP);
 
                 ret = posix_acl_set (entry->inode, this,
                                      acl_access, acl_default);
@@ -1837,7 +1925,7 @@ posix_acl_setattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, postbuf);
+        posix_acl_ctx_update (inode, this, postbuf, GF_FOP_SETATTR);
 
 unwind:
         STACK_UNWIND_STRICT (setattr, frame, op_ret, op_errno, prebuf,
@@ -1883,7 +1971,7 @@ posix_acl_fsetattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret != 0)
                 goto unwind;
 
-        posix_acl_ctx_update (inode, this, postbuf);
+        posix_acl_ctx_update (inode, this, postbuf, GF_FOP_FSETATTR);
 
 unwind:
         STACK_UNWIND_STRICT (fsetattr, frame, op_ret, op_errno, prebuf,