Whamcloud - gitweb
LU-12368 ptlrpc: make DEBUG_REQ messages consistent
[fs/lustre-release.git] / lustre / ptlrpc / client.c
index 3789162..b6c7782 100644 (file)
@@ -437,14 +437,16 @@ static int unpack_reply(struct ptlrpc_request *req)
        if (SPTLRPC_FLVR_POLICY(req->rq_flvr.sf_rpc) != SPTLRPC_POLICY_NULL) {
                rc = ptlrpc_unpack_rep_msg(req, req->rq_replen);
                if (rc) {
-                       DEBUG_REQ(D_ERROR, req, "unpack_rep failed: %d", rc);
+                       DEBUG_REQ(D_ERROR, req, "unpack_rep failed: rc = %d",
+                                 rc);
                        return -EPROTO;
                }
        }
 
        rc = lustre_unpack_rep_ptlrpc_body(req, MSG_PTLRPC_BODY_OFF);
        if (rc) {
-               DEBUG_REQ(D_ERROR, req, "unpack ptlrpc body failed: %d", rc);
+               DEBUG_REQ(D_ERROR, req, "unpack ptlrpc body failed: rc = %d",
+                         rc);
                return -EPROTO;
        }
        return 0;
@@ -505,6 +507,8 @@ __must_hold(&req->rq_lock)
        req->rq_deadline = req->rq_sent + req->rq_timeout +
                           ptlrpc_at_get_net_latency(req);
 
+       /* The below message is checked in replay-single.sh test_65{a,b} */
+       /* The below message is checked in sanity-{gss,krb5} test_8 */
        DEBUG_REQ(D_ADAPTTO, req,
                  "Early reply #%d, new deadline in %llds (%llds)",
                  req->rq_early_count,
@@ -1200,7 +1204,7 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
        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.");
+               DEBUG_REQ(D_ERROR, req, "Uninitialized import");
                *status = -EIO;
        } else if (imp->imp_state == LUSTRE_IMP_CLOSED) {
                unsigned int opc = lustre_msg_get_opc(req->rq_reqmsg);
@@ -1210,11 +1214,11 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
                 * race with umount
                 */
                DEBUG_REQ((opc == OBD_PING || opc == OST_STATFS) ?
-                         D_HA : D_ERROR, req, "IMP_CLOSED ");
+                         D_HA : D_ERROR, req, "IMP_CLOSED");
                *status = -EIO;
        } else if (ptlrpc_send_limit_expired(req)) {
                /* probably doesn't need to be a D_ERROR afterinitial testing */
-               DEBUG_REQ(D_HA, req, "send limit expired ");
+               DEBUG_REQ(D_HA, req, "send limit expired");
                *status = -ETIMEDOUT;
        } else if (req->rq_send_state == LUSTRE_IMP_CONNECTING &&
                   imp->imp_state == LUSTRE_IMP_CONNECTING) {
@@ -1244,7 +1248,7 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
                            imp->imp_state == LUSTRE_IMP_REPLAY_LOCKS ||
                            imp->imp_state == LUSTRE_IMP_REPLAY_WAIT ||
                            imp->imp_state == LUSTRE_IMP_RECOVER)) {
-                       DEBUG_REQ(D_HA, req, "allow during recovery.\n");
+                       DEBUG_REQ(D_HA, req, "allow during recovery");
                } else {
                        delay = 1;
                }
@@ -1301,32 +1305,28 @@ static bool ptlrpc_console_allow(struct ptlrpc_request *req, __u32 opc, int err)
  */
 static int ptlrpc_check_status(struct ptlrpc_request *req)
 {
-       int err;
+       int rc;
 
        ENTRY;
-       err = lustre_msg_get_status(req->rq_repmsg);
+       rc = lustre_msg_get_status(req->rq_repmsg);
        if (lustre_msg_get_type(req->rq_repmsg) == PTL_RPC_MSG_ERR) {
                struct obd_import *imp = req->rq_import;
                lnet_nid_t nid = imp->imp_connection->c_peer.nid;
                __u32 opc = lustre_msg_get_opc(req->rq_reqmsg);
 
-               if (ptlrpc_console_allow(req, opc, err))
+               if (ptlrpc_console_allow(req, opc, rc))
                        LCONSOLE_ERROR_MSG(0x11,
                                           "%s: operation %s to node %s failed: rc = %d\n",
                                           imp->imp_obd->obd_name,
                                           ll_opcode2str(opc),
-                                          libcfs_nid2str(nid), err);
-               RETURN(err < 0 ? err : -EINVAL);
+                                          libcfs_nid2str(nid), rc);
+               RETURN(rc < 0 ? rc : -EINVAL);
        }
 
-       if (err < 0) {
-               DEBUG_REQ(D_INFO, req, "status is %d", err);
-       } else if (err > 0) {
-               /* XXX: translate this error from net to host */
-               DEBUG_REQ(D_INFO, req, "status is %d", err);
-       }
+       if (rc)
+               DEBUG_REQ(D_INFO, req, "check status: rc = %d", rc);
 
-       RETURN(err);
+       RETURN(rc);
 }
 
 /**
@@ -1394,7 +1394,7 @@ static int after_reply(struct ptlrpc_request *req)
        if (req->rq_reply_truncated) {
                if (ptlrpc_no_resend(req)) {
                        DEBUG_REQ(D_ERROR, req,
-                                 "reply buffer overflow, expected: %d, actual size: %d",
+                                 "reply buffer overflow, expected=%d, actual size=%d",
                                  req->rq_nob_received, req->rq_repbuf_len);
                        RETURN(-EOVERFLOW);
                }
@@ -1423,7 +1423,7 @@ static int after_reply(struct ptlrpc_request *req)
         */
        rc = sptlrpc_cli_unwrap_reply(req);
        if (rc) {
-               DEBUG_REQ(D_ERROR, req, "unwrap reply failed (%d):", rc);
+               DEBUG_REQ(D_ERROR, req, "unwrap reply failed: rc = %d", rc);
                RETURN(rc);
        }
 
@@ -1442,8 +1442,8 @@ static int after_reply(struct ptlrpc_request *req)
            ptlrpc_no_resend(req) == 0 && !req->rq_no_retry_einprogress) {
                time64_t now = ktime_get_real_seconds();
 
-               DEBUG_REQ(req->rq_nr_resend > 0 ? D_ERROR : D_RPCTRACE, req,
-                         "Resending request on EINPROGRESS");
+               DEBUG_REQ((req->rq_nr_resend % 8 == 1 ? D_WARNING : 0) |
+                         D_RPCTRACE, req, "resending request on EINPROGRESS");
                spin_lock(&req->rq_lock);
                req->rq_resend = 1;
                spin_unlock(&req->rq_lock);
@@ -1690,7 +1690,8 @@ static int ptlrpc_send_new_req(struct ptlrpc_request *req)
                RETURN(rc);
        }
        if (rc) {
-               DEBUG_REQ(D_HA, req, "send failed (%d); expect timeout", rc);
+               DEBUG_REQ(D_HA, req, "send failed, expect timeout: rc = %d",
+                         rc);
                spin_lock(&req->rq_lock);
                req->rq_net_err = 1;
                spin_unlock(&req->rq_lock);
@@ -3054,7 +3055,7 @@ static int ptlrpc_replay_interpret(const struct lu_env *env,
        if (!ptlrpc_client_replied(req) ||
            (req->rq_bulk &&
             lustre_msg_get_status(req->rq_repmsg) == -ETIMEDOUT)) {
-               DEBUG_REQ(D_ERROR, req, "request replay timed out.\n");
+               DEBUG_REQ(D_ERROR, req, "request replay timed out");
                GOTO(out, rc = -ETIMEDOUT);
        }
 
@@ -3066,7 +3067,7 @@ static int ptlrpc_replay_interpret(const struct lu_env *env,
        /** VBR: check version failure */
        if (lustre_msg_get_status(req->rq_repmsg) == -EOVERFLOW) {
                /** replay was failed due to version mismatch */
-               DEBUG_REQ(D_WARNING, req, "Version mismatch during replay\n");
+               DEBUG_REQ(D_WARNING, req, "Version mismatch during replay");
                spin_lock(&imp->imp_lock);
                imp->imp_vbr_failed = 1;
                spin_unlock(&imp->imp_lock);
@@ -3089,13 +3090,13 @@ static int ptlrpc_replay_interpret(const struct lu_env *env,
        /* transaction number shouldn't be bigger than the latest replayed */
        if (req->rq_transno > lustre_msg_get_transno(req->rq_reqmsg)) {
                DEBUG_REQ(D_ERROR, req,
-                         "Reported transno %llu is bigger than the replayed one: %llu",
+                         "Reported transno=%llu is bigger than replayed=%llu",
                          req->rq_transno,
                          lustre_msg_get_transno(req->rq_reqmsg));
                GOTO(out, rc = -EINVAL);
        }
 
-       DEBUG_REQ(D_HA, req, "got rep");
+       DEBUG_REQ(D_HA, req, "got reply");
 
        /* let the callback do fixups, possibly including in the request */
        if (req->rq_replay_cb)