LU-4761 tests: clean up spurious messages and files

Reduce spurious messages that appear in the test and console logs
that are not useful for debugging, and just clutter things up.

Clean up a few files left over from tests.

Signed-off-by: Andreas Dilger <andreas.dilger@intel.com>
Change-Id: Ie17888a8f9c5864530dcb455a0cd4e51f83ebbe5
Reviewed-on: https://review.whamcloud.com/29012
Tested-by: Jenkins
Tested-by: Maloo <hpdd-maloo@intel.com>
Reviewed-by: Jian Yu <jian.yu@intel.com>
Reviewed-by: Mike Pershin <mike.pershin@intel.com>
Reviewed-by: James Nunez <james.a.nunez@intel.com>
Reviewed-by: Oleg Drokin <oleg.drokin@intel.com>

diff --git a/lustre/mdt/mdt_xattr.c b/lustre/mdt/mdt_xattr.c
index 872cb77..c878041 100644 (file)
--- a/lustre/mdt/mdt_xattr.c
+++ b/lustre/mdt/mdt_xattr.c
@@ -71,14 +71,16 @@ static int mdt_getxattr_pack_reply(struct mdt_thread_info * info)
                    !strncmp(xattr_name, user_string, sizeof(user_string) - 1))
                        RETURN(-EOPNOTSUPP);
 
-                size = mo_xattr_get(info->mti_env,
-                                    mdt_object_child(info->mti_object),
-                                    &LU_BUF_NULL, xattr_name);
-        } else if (valid == OBD_MD_FLXATTRLS) {
-                size = mo_xattr_list(info->mti_env,
-                                     mdt_object_child(info->mti_object),
-                                     &LU_BUF_NULL);
+               size = mo_xattr_get(info->mti_env,
+                                   mdt_object_child(info->mti_object),
+                                   &LU_BUF_NULL, xattr_name);
+       } else if (valid == OBD_MD_FLXATTRLS) {
+               xattr_name = "list";
+               size = mo_xattr_list(info->mti_env,
+                                    mdt_object_child(info->mti_object),
+                                    &LU_BUF_NULL);
        } else if (valid == OBD_MD_FLXATTRALL) {
+               xattr_name = "all";
                /* N.B. eadatasize = 0 is not valid for FLXATTRALL */
                /* We could calculate accurate sizes, but this would
                 * introduce a lot of overhead, let's do it later... */
@@ -94,8 +96,9 @@ static int mdt_getxattr_pack_reply(struct mdt_thread_info * info)
        if (size == -ENODATA) {
                size = 0;
        } else if (size < 0) {
-               if (size != -EOPNOTSUPP)
-                       CERROR("Error geting EA size: %d\n", size);
+               if (size != -EOPNOTSUPP && size != -ENOENT)
+                       CERROR("%s: error geting EA size for '%s': rc = %d\n",
+                              mdt_obd_name(info->mti_mdt), xattr_name, size);
                RETURN(size);
        }
 

diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c
index 1c05e76..e145ea3 100644 (file)
--- a/lustre/ptlrpc/client.c
+++ b/lustre/ptlrpc/client.c
@@ -1155,17 +1155,19 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
         LASSERT (status != NULL);
         *status = 0;
 
-        if (req->rq_ctx_init || req->rq_ctx_fini) {
-                /* always allow ctx init/fini rpc go through */
-        } else if (imp->imp_state == LUSTRE_IMP_NEW) {
-                DEBUG_REQ(D_ERROR, req, "Uninitialized import.");
-                *status = -EIO;
+       if (req->rq_ctx_init || req->rq_ctx_fini) {
+               /* always allow ctx init/fini rpc go through */
+       } else if (imp->imp_state == LUSTRE_IMP_NEW) {
+               DEBUG_REQ(D_ERROR, req, "Uninitialized import.");
+               *status = -EIO;
        } else if (imp->imp_state == LUSTRE_IMP_CLOSED) {
-               /* pings may safely race with umount */
-               DEBUG_REQ(lustre_msg_get_opc(req->rq_reqmsg) == OBD_PING ?
+               unsigned int opc = lustre_msg_get_opc(req->rq_reqmsg);
+
+               /* pings or MDS-equivalent STATFS may safely race with umount */
+               DEBUG_REQ((opc == OBD_PING || opc == OST_STATFS) ?
                          D_HA : D_ERROR, req, "IMP_CLOSED ");
                *status = -EIO;
-        } else if (ptlrpc_send_limit_expired(req)) {
+       } else if (ptlrpc_send_limit_expired(req)) {
                /* probably doesn't need to be a D_ERROR after initial testing*/
                DEBUG_REQ(D_HA, req, "send limit expired ");
                *status = -ETIMEDOUT;
@@ -1213,16 +1215,12 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
  * \retval false if no message should be printed
  * \retval true  if console message should be printed
  */
-static bool ptlrpc_console_allow(struct ptlrpc_request *req)
+static bool ptlrpc_console_allow(struct ptlrpc_request *req, __u32 opc, int err)
 {
-       __u32 opc;
-
        LASSERT(req->rq_reqmsg != NULL);
-       opc = lustre_msg_get_opc(req->rq_reqmsg);
 
        /* Suppress particular reconnect errors which are to be expected. */
        if (opc == OST_CONNECT || opc == MDS_CONNECT || opc == MGS_CONNECT) {
-               int err;
 
                /* Suppress timed out reconnect requests */
                if (lustre_handle_is_used(&req->rq_import->imp_remote_handle) ||
@@ -1232,12 +1230,20 @@ static bool ptlrpc_console_allow(struct ptlrpc_request *req)
                /* Suppress most unavailable/again reconnect requests, but
                 * print occasionally so it is clear client is trying to
                 * connect to a server where no target is running. */
-               err = lustre_msg_get_status(req->rq_repmsg);
                if ((err == -ENODEV || err == -EAGAIN) &&
                    req->rq_import->imp_conn_cnt % 30 != 20)
                        return false;
        }
 
+       if (opc == LDLM_ENQUEUE && err == -EAGAIN)
+               /* -EAGAIN is normal when using POSIX flocks */
+               return false;
+
+       if (opc == OBD_PING && (err == -ENODEV || err == -ENOTCONN) &&
+           (req->rq_xid & 0xf) != 10)
+               /* Suppress most ping requests, they may fail occasionally */
+               return false;
+
        return true;
 }
 
@@ -1256,9 +1262,7 @@ static int ptlrpc_check_status(struct ptlrpc_request *req)
                lnet_nid_t nid = imp->imp_connection->c_peer.nid;
                __u32 opc = lustre_msg_get_opc(req->rq_reqmsg);
 
-               /* -EAGAIN is normal when using POSIX flocks */
-               if (ptlrpc_console_allow(req) &&
-                   !(opc == LDLM_ENQUEUE && err == -EAGAIN))
+               if (ptlrpc_console_allow(req, opc, err))
                        LCONSOLE_ERROR_MSG(0x11, "%s: operation %s to node %s "
                                           "failed: rc = %d\n",
                                           imp->imp_obd->obd_name,
@@ -2097,6 +2101,7 @@ EXPORT_SYMBOL(ptlrpc_check_set);
 int ptlrpc_expire_one_request(struct ptlrpc_request *req, int async_unlink)
 {
        struct obd_import *imp = req->rq_import;
+       unsigned int debug_mask = D_RPCTRACE;
        int rc = 0;
        ENTRY;
 
@@ -2104,12 +2109,15 @@ int ptlrpc_expire_one_request(struct ptlrpc_request *req, int async_unlink)
        req->rq_timedout = 1;
        spin_unlock(&req->rq_lock);
 
-       DEBUG_REQ(D_WARNING, req, "Request sent has %s: [sent %lld/real %lld]",
-                  req->rq_net_err ? "failed due to network error" :
-                     ((req->rq_real_sent == 0 ||
+       if (ptlrpc_console_allow(req, lustre_msg_get_opc(req->rq_reqmsg),
+                                 lustre_msg_get_status(req->rq_reqmsg)))
+               debug_mask = D_WARNING;
+       DEBUG_REQ(debug_mask, req, "Request sent has %s: [sent %lld/real %lld]",
+                 req->rq_net_err ? "failed due to network error" :
+                    ((req->rq_real_sent == 0 ||
                       req->rq_real_sent < req->rq_sent ||
                       req->rq_real_sent >= req->rq_deadline) ?
-                      "timed out for sent delay" : "timed out for slow reply"),
+                     "timed out for sent delay" : "timed out for slow reply"),
                  (s64)req->rq_sent, (s64)req->rq_real_sent);
 
        if (imp != NULL && obd_debug_peer_on_timeout)

diff --git a/lustre/tests/sanity.sh b/lustre/tests/sanity.sh
index 171b60e..0c8b657 100755 (executable)
--- a/lustre/tests/sanity.sh
+++ b/lustre/tests/sanity.sh
@@ -1674,7 +1674,8 @@ test_27u() { # bug 4900
        unlinkmany $DIR/$tdir/t- 1000
        trap 0
        [[ $OBJS -gt 0 ]] &&
-               error "$OBJS objects created on OST-0. See $TLOG" || pass
+               error "$OBJS objects created on OST-0. See $TLOG" ||
+               rm -f $TLOG
 }
 run_test 27u "skip object creation on OSC w/o objects"
 
@@ -3839,6 +3840,7 @@ test_43a() {
                cp -p multiop $DIR/$tdir/multiop
        MULTIOP_PROG=$DIR/$tdir/multiop multiop_bg_pause $TMP/$tfile.junk O_c ||
                error "multiop open $TMP/$tfile.junk failed"
+       rm $TMP/$tfile.junk     # delete junk file on close (not part of test)
        MULTIOP_PID=$!
        $MULTIOP $DIR/$tdir/multiop Oc && error "expected error, got success"
        kill -USR1 $MULTIOP_PID || error "kill -USR1 PID $MULTIOP_PID failed"
@@ -3853,6 +3855,7 @@ test_43b() {
                cp -p multiop $DIR/$tdir/multiop
        MULTIOP_PROG=$DIR/$tdir/multiop multiop_bg_pause $TMP/$tfile.junk O_c ||
                error "multiop open $TMP/$tfile.junk failed"
+       rm $TMP/$tfile.junk     # delete junk file on close (not part of test)
        MULTIOP_PID=$!
        $TRUNCATE $DIR/$tdir/multiop 0 && error "expected error, got success"
        kill -USR1 $MULTIOP_PID || error "kill -USR1 PID $MULTIOP_PID failed"
@@ -11111,9 +11114,8 @@ test_156() {
                log "cache hits:: before: $BEFORE, after: $AFTER"
        fi
 
-       rm -f $file
        restore_lustre_params < $p
-       rm -f $p
+       rm -f $p $file
 }
 run_test 156 "Verification of tunables"
 
@@ -14299,6 +14301,14 @@ test_246() { # LU-7371
 }
 run_test 246 "Read file of size 4095 should return right length"
 
+cleanup_247() {
+       local submount=$1
+
+       trap 0
+       umount_client $submount
+       rmdir $submount
+}
+
 test_247a() {
        lctl get_param -n mdc.$FSNAME-MDT0000*.import |
                grep -q subtree ||
@@ -14310,11 +14320,11 @@ test_247a() {
        mkdir -p $submount || error "mkdir $submount failed"
        FILESET="$FILESET/$tdir" mount_client $submount ||
                error "mount $submount failed"
+       trap "cleanup_247 $submount" EXIT
        echo foo > $submount/$tfile || error "write $submount/$tfile failed"
        [ $(cat $MOUNT/$tdir/$tfile) = "foo" ] ||
                error "read $MOUNT/$tdir/$tfile failed"
-       umount_client $submount || error "umount $submount failed"
-       rmdir $submount
+       cleanup_247 $submount
 }
 run_test 247a "mount subdir as fileset"
 
@@ -14341,12 +14351,12 @@ test_247c() {
 
        mkdir -p $MOUNT/$tdir/dir1
        mkdir -p $submount || error "mkdir $submount failed"
+       trap "cleanup_247 $submount" EXIT
        FILESET="$FILESET/$tdir" mount_client $submount ||
                error "mount $submount failed"
        local fid=$($LFS path2fid $MOUNT/)
        $LFS fid2path $submount $fid && error "fid2path should fail"
-       umount_client $submount || error "umount $submount failed"
-       rmdir $submount
+       cleanup_247 $submount
 }
 run_test 247c "running fid2path outside root"
 
@@ -14360,10 +14370,10 @@ test_247d() {
        mkdir -p $submount || error "mkdir $submount failed"
        FILESET="$FILESET/$tdir" mount_client $submount ||
                error "mount $submount failed"
+       trap "cleanup_247 $submount" EXIT
        local fid=$($LFS path2fid $submount/dir1)
        $LFS fid2path $submount $fid || error "fid2path should succeed"
-       umount_client $submount || error "umount $submount failed"
-       rmdir $submount
+       cleanup_247 $submount
 }
 run_test 247d "running fid2path inside root"
 
@@ -16780,7 +16790,7 @@ test_403() {
 
        wait
 
-       [ `cat $tfile` -gt 0 ] || error "wrong nlink count: `cat $tfile`"
+       [ $(cat $tfile) -gt 0 ] || error "wrong nlink count: $(cat $tfile)"
 
        rm -f $tfile $file1 $file2
 }