various message adjustment (more verbose) for remote acl upcall and lsd

upcalls, for debugging.

diff --git a/lustre/mds/mds_acl.c b/lustre/mds/mds_acl.c
index 68eddf0..5012cad 100644 (file)
--- a/lustre/mds/mds_acl.c
+++ b/lustre/mds/mds_acl.c
@@ -58,7 +58,7 @@ static struct upcall_cache _rmtacl_upcall_cache;
 static struct list_head _rmtacl_upcall_hashtable[RMTACL_UPCALL_HASHSIZE];
 
 #define RMTACL_UPCALL_PATH              "/usr/bin/lacl_upcall"
-#define RMTACL_ACQUIRE_EXPIRE           (15)
+#define RMTACL_ACQUIRE_EXPIRE           (20)
 #define RMTACL_ENTRY_EXPIRE             (0)
 #define RMTACL_ERR_ENTRY_EXPIRE         (0)
 
@@ -132,8 +132,8 @@ static int rmtacl_make_upcall(struct upcall_cache *cache,
                        "/proc/fs/lustre/mds/lacl_upcall\n",
                        argv[0], rc);
         } else {
-                CDEBUG(D_SEC, "Invoked upcall %s %s %s %s\n",
-                       argv[0], argv[1], argv[2], argv[3]);
+                CDEBUG(D_SEC, "Invoked upcall %s %s %s %s %s %s\n",
+                       argv[0], argv[1], argv[2], argv[3], argv[4], argv[5]);
         }
         return rc;
 }
@@ -166,6 +166,7 @@ static int rmtacl_parse_downcall(struct upcall_cache *cache,
                 goto out;
 
         if (copy_from_user(desc->res, rargs->res, rargs->reslen)) {
+                CERROR("can't copy from userspace\n");
                 desc->upcall_status = -EFAULT;
                 goto out;
         }

diff --git a/lustre/sec/upcall_cache.c b/lustre/sec/upcall_cache.c
index ad4686a..6ce2e7f 100644 (file)
--- a/lustre/sec/upcall_cache.c
+++ b/lustre/sec/upcall_cache.c
@@ -68,7 +68,7 @@ static void free_entry(struct upcall_cache_entry *entry)
         LASSERT(cache->free_entry);
         LASSERT(atomic_read(&entry->ue_refcount) == 0);
 
-        CDEBUG(D_SEC, "destroy %s entry %p for key "LPU64"\n",
+        CDEBUG(D_SEC, "%s: destroy entry %p for key "LPU64"\n",
                cache->uc_name, entry, entry->ue_key);
 
         list_del(&entry->ue_hash);
@@ -139,7 +139,6 @@ __get_entry(struct upcall_cache *cache, unsigned int hash, __u64 key,
         ENTRY;
 
         LASSERT(hash < cache->uc_hashsize);
-
         head = &cache->uc_hashtable[hash];
 
 find_again:
@@ -222,12 +221,12 @@ find_again:
                         /* we're interrupted or upcall failed
                          * in the middle
                          */
-                        CERROR("entry %p not refreshed: cur %lu, key "LPU64", "
-                               "ref %d fl %u, ac %ld, ex %ld\n",
-                               entry, get_seconds(), entry->ue_key,
+                        CERROR("%s: entry %p not refreshed: key "LPU64", "
+                               "ref %d fl %u, cur %lu, ex %ld/%ld\n",
+                               cache->uc_name, entry, entry->ue_key,
                                atomic_read(&entry->ue_refcount),
-                               entry->ue_flags, entry->ue_acquire_expire,
-                               entry->ue_expire);
+                               entry->ue_flags, get_seconds(),
+                               entry->ue_acquire_expire, entry->ue_expire);
                         put_entry(entry);
                         write_unlock(&cache->uc_hashlock);
                         CERROR("Interrupted? Or check whether %s is in place\n",
@@ -287,7 +286,8 @@ void upcall_cache_put_entry(struct upcall_cache_entry *entry)
 
         write_lock(&cache->uc_hashlock);
         LASSERTF(atomic_read(&entry->ue_refcount) > 0,
-                 "entry %p: ref %d\n", entry, atomic_read(&entry->ue_refcount));
+                 "%s: entry %p: ref %d\n", cache->uc_name, entry,
+                 atomic_read(&entry->ue_refcount));
         put_entry(entry);
         write_unlock(&cache->uc_hashlock);
 }
@@ -316,7 +316,8 @@ int upcall_cache_downcall(struct upcall_cache *cache, __u64 key, void *args)
         if (!found) {
                 /* haven't found, it's possible */
                 write_unlock(&cache->uc_hashlock);
-                CWARN("key "LPU64" entry dosen't found\n", key);
+                CWARN("%s: key "LPU64" entry dosen't found\n",
+                      cache->uc_name, key);
                 RETURN(-EINVAL);
         }
 
@@ -325,28 +326,31 @@ int upcall_cache_downcall(struct upcall_cache *cache, __u64 key, void *args)
                         /* This should not happen, just give a warning
                          * at this moment.
                          */
-                        CWARN("entry %p(key "LPU64", ac %ld, ex %ld): "
-                              "already valid???\n", entry, entry->ue_key,
+                        CWARN("%s: entry %p(key "LPU64", cur %lu, ex %ld/%ld) "
+                              "already valid\n", cache->uc_name,
+                              entry, entry->ue_key, get_seconds(),
                               entry->ue_acquire_expire, entry->ue_expire);
                         GOTO(out, rc = 0);
                 }
 
-                CWARN("stale entry %p: cur %lu, key "LPU64", ref %d, "
-                      "fl %u, ac %ld, ex %ld\n",
-                       entry, get_seconds(), entry->ue_key,
-                       atomic_read(&entry->ue_refcount), entry->ue_flags,
-                       entry->ue_acquire_expire, entry->ue_expire);
+                CWARN("%s: stale entry %p: key "LPU64", ref %d, fl %u, "
+                      "cur %lu, ex %ld/%ld\n",
+                      cache->uc_name, entry, entry->ue_key,
+                      atomic_read(&entry->ue_refcount),
+                      entry->ue_flags, get_seconds(),
+                      entry->ue_acquire_expire, entry->ue_expire);
                 GOTO(out, rc = -EINVAL);
         }
 
         if (!UC_CACHE_IS_ACQUIRING(entry) ||
             UC_CACHE_IS_INVALID(entry) ||
             UC_CACHE_IS_EXPIRED(entry)) {
-                CWARN("stale entry %p: cur %lu, key "LPU64", ref %d, "
-                      "fl %u, ac %ld, ex %ld\n",
-                       entry, get_seconds(), entry->ue_key,
-                       atomic_read(&entry->ue_refcount), entry->ue_flags,
-                       entry->ue_acquire_expire, entry->ue_expire);
+                CWARN("%s: invalid entry %p: key "LPU64", ref %d, fl %u, "
+                      "cur %lu, ex %ld/%ld\n",
+                      cache->uc_name, entry, entry->ue_key,
+                      atomic_read(&entry->ue_refcount),
+                      entry->ue_flags, get_seconds(), 
+                      entry->ue_acquire_expire, entry->ue_expire);
                 GOTO(out, rc = -EINVAL);
         }
 
@@ -367,8 +371,8 @@ int upcall_cache_downcall(struct upcall_cache *cache, __u64 key, void *args)
         }
 
         UC_CACHE_SET_VALID(entry);
-        CDEBUG(D_SEC, "create ucache entry %p(key "LPU64")\n",
-               entry, entry->ue_key);
+        CDEBUG(D_SEC, "%s: create ucache entry %p(key "LPU64")\n",
+               cache->uc_name, entry, entry->ue_key);
 out:
         wake_up_all(&entry->ue_waitq);
         write_unlock(&cache->uc_hashlock);
@@ -386,7 +390,6 @@ void upcall_cache_flush_one(struct upcall_cache *cache, __u64 key)
 
         hash = cache->hash(cache, key);
         LASSERT(hash < cache->uc_hashsize);
-
         head = &cache->uc_hashtable[hash];
 
         write_lock(&cache->uc_hashlock);
@@ -398,6 +401,12 @@ void upcall_cache_flush_one(struct upcall_cache *cache, __u64 key)
         }
 
         if (found) {
+                CWARN("%s: flush entry %p: key "LPU64", ref %d, fl %x, "
+                      "cur %lu, ex %ld/%ld\n",
+                      cache->uc_name, entry, entry->ue_key,
+                      atomic_read(&entry->ue_refcount), entry->ue_flags,
+                      get_seconds(), entry->ue_acquire_expire,
+                      entry->ue_expire);
                 UC_CACHE_SET_EXPIRED(entry);
                 if (!atomic_read(&entry->ue_refcount))
                         free_entry(entry);

diff --git a/lustre/utils/lacl_upcall.c b/lustre/utils/lacl_upcall.c
index dec19f4..7a7164d 100644 (file)
--- a/lustre/utils/lacl_upcall.c
+++ b/lustre/utils/lacl_upcall.c
@@ -31,6 +31,7 @@
 #include <fcntl.h>
 #include <pwd.h>
 #include <grp.h>
+#include <syslog.h>
 
 #include <liblustre.h>
 #include <linux/lustre_idl.h>
@@ -41,6 +42,16 @@
 #include <portals/ptlctl.h>
 #include <portals/types.h>
 
+static int g_testing = 0;
+
+#define log_msg(fmt, args...)                           \
+        {                                               \
+                if (g_testing)                          \
+                        printf(fmt, ## args);           \
+                else                                    \
+                        syslog(LOG_ERR, fmt, ## args);  \
+        }
+
 int switch_user_identity(uid_t uid)
 {
         gid_t           gid;
@@ -51,8 +62,10 @@ int switch_user_identity(uid_t uid)
         int             i;
 
         /* originally must be root */
-        if (getuid() != 0 || geteuid() != 0)
+        if (getuid() != 0 || geteuid() != 0) {
+                log_msg("non-root: %u/%u\n", getuid(), geteuid());
                 return -EPERM;
+        }
 
         /* nothing more is needed for root */
         if (uid == 0)
@@ -64,12 +77,16 @@ int switch_user_identity(uid_t uid)
          */
         maxgroups = sysconf(_SC_NGROUPS_MAX);
         groups = malloc(maxgroups * sizeof(gid_t));
-        if (!groups)
+        if (!groups) {
+                log_msg("memory alloc failure\n");
                 return -ENOMEM;
+        }
 
         pw = getpwuid(uid);
-        if (!pw)
+        if (!pw) {
+                log_msg("no such uid %u\n", uid);
                 return -EPERM;
+        }
 
         gid = pw->pw_gid;
 
@@ -88,16 +105,19 @@ int switch_user_identity(uid_t uid)
         endgrent();
 
         if (setgroups(ngroups, groups) == -1) {
+                log_msg("set %d groups: %s\n", ngroups, strerror(errno));
                 free(groups);
                 return -EPERM;
         }
         free(groups);
 
         if (setgid(gid) == -1) {
+                log_msg("setgid %u: %s\n", gid, strerror(errno));
                 return -EPERM;
         }
 
         if (setuid(uid) == -1) {
+                log_msg("setuid %u: %s\n", uid, strerror(errno));
                 return -EPERM;
         }
 
@@ -163,6 +183,7 @@ void do_acl_command(uid_t uid, char *lroot, char *cmdline)
         }
 
         if (chdir(lroot) < 0) {
+                log_msg("chdir to %s: %s\n", lroot, strerror(errno));
                 printf("MDS: can't change dir\n");
                 return;
         }
@@ -195,11 +216,19 @@ int main (int argc, char **argv)
         int      pipeout[2], pipeerr[2], pid;
         int      output_size, rd, childret;
 
-        if (argc != 6)
+        if (argc != 6) {
+                log_msg("invalid argc %d\n", argc);
                 return -1;
+        }
+
+        /* XXX temp for debugging */
+        log_msg("enter: %s %s %s %s %s\n",
+                argv[1], argv[2], argv[3], argv[4], argv[5]);
 
-        if (strcmp(argv[4], "get") && strcmp(argv[4], "set"))
+        if (strcmp(argv[4], "get") && strcmp(argv[4], "set")) {
+                log_msg("invalid arg 4: %s\n", argv[4]);
                 return -1;
+        }
 
         dc_args.key = strtoull(argv[1], NULL, 16);
         dc_args.res = output;
@@ -300,10 +329,19 @@ wait_child:
 
 downcall:
         dc_fd = open(dc_name, O_WRONLY);
-        if (dc_fd != -1) {
-                write(dc_fd, &dc_args, sizeof(dc_args));
+        if (dc_fd < 0) {
+                log_msg("can't open %s: %s\n", dc_name, strerror(errno));
+        } else {
+                int rc;
+
+                rc = write(dc_fd, &dc_args, sizeof(dc_args));
+                if (rc != sizeof(dc_args))
+                        log_msg("write error: ret %d\n", rc);
+
                 close(dc_fd);
         }
 
+        /* XXX temp for debugging */
+        log_msg("finished upcall\n");
         return 0;
 }

diff --git a/lustre/utils/lsd_upcall.c b/lustre/utils/lsd_upcall.c
index 1fbd45a..e1fbf5b 100644 (file)
--- a/lustre/utils/lsd_upcall.c
+++ b/lustre/utils/lsd_upcall.c
@@ -410,7 +410,6 @@ int main (int argc, char **argv)
                 fclose(conf_fp);
         }
 
-
 do_downcall:
         if (testing) {
                 show_result(&ioc_data);
@@ -428,8 +427,9 @@ do_downcall:
                 if (rc != sizeof(ioc_data)) {
                         log_msg(testing, "partial write ret %d: %s\n",
                                 rc, strerror(errno));
+                        return 1;
                 }
 
-                return (rc != sizeof(ioc_data));
+                return 0;
         }
 }