LU-1095 debug: Quiet/cleanup various common console messages

Turn off several common message we always observe when restarting
servers assuming they are for the expected return code.  Simply
move others which are not helpful to an administrator to the
internal debug kernel log.  Less noise means you are more likely
to spot the important error messages.

Signed-off-by: Christopher J. Morrone <morrone2@llnl.gov>
Signed-off-by: Prakash Surya <surya1@llnl.gov>
Change-Id: I523eacfe3c72480d62c915537427aa6c99428647
Reviewed-on: http://review.whamcloud.com/2201
Tested-by: Hudson
Reviewed-by: Mike Pershin <mike.pershin@intel.com>
Tested-by: Maloo <whamcloud.maloo@gmail.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/lustre/ldlm/ldlm_lib.c b/lustre/ldlm/ldlm_lib.c
index 40df0e4..b15c10a 100644 (file)
--- a/lustre/ldlm/ldlm_lib.c
+++ b/lustre/ldlm/ldlm_lib.c
@@ -2176,9 +2176,9 @@ void target_recovery_init(struct lu_target *lut, svc_handler_t handler)
                 return;
         }
 
                 return;
         }
 

-        CWARN("RECOVERY: service %s, %d recoverable clients, "
-              "last_transno "LPU64"\n", obd->obd_name,
-              obd->obd_max_recoverable_clients, obd->obd_last_committed);
+       CDEBUG(D_HA, "RECOVERY: service %s, %d recoverable clients, "
+              "last_transno "LPU64"\n", obd->obd_name,
+              obd->obd_max_recoverable_clients, obd->obd_last_committed);

         LASSERT(obd->obd_stopping == 0);
         obd->obd_next_recovery_transno = obd->obd_last_committed + 1;
         obd->obd_recovery_start = 0;
         LASSERT(obd->obd_stopping == 0);
         obd->obd_next_recovery_transno = obd->obd_last_committed + 1;
         obd->obd_recovery_start = 0;

diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c
index bc78f92..f98c8dd 100644 (file)
--- a/lustre/ldlm/ldlm_request.c
+++ b/lustre/ldlm/ldlm_request.c
@@ -105,12 +105,17 @@ int ldlm_expired_completion_wait(void *data)
                 if (ptlrpc_check_suspend())
                         RETURN(0);
 
                 if (ptlrpc_check_suspend())
                         RETURN(0);
 

-                LDLM_ERROR(lock, "lock timed out (enqueued at "CFS_TIME_T", "
-                           CFS_DURATION_T"s ago); not entering recovery in "
-                           "server code, just going back to sleep",
-                           lock->l_last_activity,
-                           cfs_time_sub(cfs_time_current_sec(),
-                           lock->l_last_activity));
+               LCONSOLE_WARN("lock timed out (enqueued at "CFS_TIME_T", "
+                             CFS_DURATION_T"s ago)\n",
+                             lock->l_last_activity,
+                             cfs_time_sub(cfs_time_current_sec(),
+                                          lock->l_last_activity));
+               LDLM_DEBUG(lock, "lock timed out (enqueued at "CFS_TIME_T", "
+                          CFS_DURATION_T"s ago); not entering recovery in "
+                          "server code, just going back to sleep",
+                          lock->l_last_activity,
+                          cfs_time_sub(cfs_time_current_sec(),
+                                       lock->l_last_activity));

                 if (cfs_time_after(cfs_time_current(), next_dump)) {
                         last_dump = next_dump;
                         next_dump = cfs_time_shift(300);
                 if (cfs_time_after(cfs_time_current(), next_dump)) {
                         last_dump = next_dump;
                         next_dump = cfs_time_shift(300);


@@ -1233,10 +1238,11 @@ int ldlm_cli_cancel_req(struct obd_export *exp, cfs_list_t *cancels,
                         ptlrpc_req_finished(req);
                         continue;
                 } else if (rc != ELDLM_OK) {
                         ptlrpc_req_finished(req);
                         continue;
                 } else if (rc != ELDLM_OK) {

-                       if (rc != -ESHUTDOWN)
-                               CERROR("Got rc %d from cancel RPC: canceling "
-                                      "anyway\n", rc);
-                        break;
+                       /* -ESHUTDOWN is common on umount */
+                       CDEBUG_LIMIT(rc == -ESHUTDOWN ? D_DLMTRACE : D_ERROR,
+                                    "Got rc %d from cancel RPC: "
+                                    "canceling anyway\n", rc);
+                       break;

                 }
                 sent = count;
                 break;
                 }
                 sent = count;
                 break;


@@ -1870,11 +1876,11 @@ int ldlm_cli_cancel_list(cfs_list_t *cancels, int count,
                                                   cancels, 1, flags);
                 }
 
                                                   cancels, 1, flags);
                 }
 

-                if (res < 0) {
-                       if (res != -ESHUTDOWN)
-                               CERROR("ldlm_cli_cancel_list: %d\n", res);
-                        res = count;
-                }
+               if (res < 0) {
+                       CDEBUG_LIMIT(res == -ESHUTDOWN ? D_DLMTRACE : D_ERROR,
+                                    "ldlm_cli_cancel_list: %d\n", res);
+                       res = count;
+               }

 
                 count -= res;
                 ldlm_lock_list_put(cancels, l_bl_ast, res);
 
                 count -= res;
                 ldlm_lock_list_put(cancels, l_bl_ast, res);

diff --git a/lustre/mdt/mdt_handler.c b/lustre/mdt/mdt_handler.c
index 27ebdbb..097cbb0 100644 (file)
--- a/lustre/mdt/mdt_handler.c
+++ b/lustre/mdt/mdt_handler.c
@@ -3012,9 +3012,9 @@ static int mdt_recovery(struct mdt_thread_info *info)
         }
 
         if (unlikely(!class_connected_export(req->rq_export))) {
         }
 
         if (unlikely(!class_connected_export(req->rq_export))) {

-                CERROR("operation %d on unconnected MDS from %s\n",
-                       lustre_msg_get_opc(req->rq_reqmsg),
-                       libcfs_id2str(req->rq_peer));
+               CDEBUG(D_HA, "operation %d on unconnected MDS from %s\n",
+                      lustre_msg_get_opc(req->rq_reqmsg),
+                      libcfs_id2str(req->rq_peer));

                 /* FIXME: For CMD cleanup, when mds_B stop, the req from
                  * mds_A will get -ENOTCONN(especially for ping req),
                  * which will cause that mds_A deactive timeout, then when
                 /* FIXME: For CMD cleanup, when mds_B stop, the req from
                  * mds_A will get -ENOTCONN(especially for ping req),
                  * which will cause that mds_A deactive timeout, then when

diff --git a/lustre/mgc/mgc_request.c b/lustre/mgc/mgc_request.c
index 7c1e087..0c2f107 100644 (file)
--- a/lustre/mgc/mgc_request.c
+++ b/lustre/mgc/mgc_request.c
@@ -1158,12 +1158,12 @@ static int mgc_import_event(struct obd_device *obd,
                 ldlm_namespace_cleanup(ns, LDLM_FL_LOCAL_ONLY);
                 break;
         }
                 ldlm_namespace_cleanup(ns, LDLM_FL_LOCAL_ONLY);
                 break;
         }

-        case IMP_EVENT_ACTIVE:
-                LCONSOLE_WARN("%s: Reactivating import\n", obd->obd_name);
-                /* Clearing obd_no_recov allows us to continue pinging */
-                obd->obd_no_recov = 0;
-                mgc_notify_active(obd);
-                break;
+       case IMP_EVENT_ACTIVE:
+               CDEBUG(D_INFO, "%s: Reactivating import\n", obd->obd_name);
+               /* Clearing obd_no_recov allows us to continue pinging */
+               obd->obd_no_recov = 0;
+               mgc_notify_active(obd);
+               break;

         case IMP_EVENT_OCD:
                 break;
         case IMP_EVENT_DEACTIVATE:
         case IMP_EVENT_OCD:
                 break;
         case IMP_EVENT_DEACTIVATE:

diff --git a/lustre/obdclass/genops.c b/lustre/obdclass/genops.c
index d39caa9..c6d7e5b 100644 (file)
--- a/lustre/obdclass/genops.c
+++ b/lustre/obdclass/genops.c
@@ -1448,9 +1448,10 @@ int obd_export_evict_by_nid(struct obd_device *obd, const char *nid)
                 LASSERTF(doomed_exp != obd->obd_self_export,
                          "self-export is hashed by NID?\n");
                 exports_evicted++;
                 LASSERTF(doomed_exp != obd->obd_self_export,
                          "self-export is hashed by NID?\n");
                 exports_evicted++;

-                CWARN("%s: evict NID '%s' (%s) #%d at adminstrative request\n",
-                       obd->obd_name, nid, doomed_exp->exp_client_uuid.uuid,
-                       exports_evicted);
+               LCONSOLE_WARN("%s: evicting %s (at %s) by administrative "
+                             "request\n", obd->obd_name,
+                             obd_uuid2str(&doomed_exp->exp_client_uuid),
+                             obd_export_nid2str(doomed_exp));

                 class_fail_export(doomed_exp);
                 class_export_put(doomed_exp);
         } while (1);
                 class_fail_export(doomed_exp);
                 class_export_put(doomed_exp);
         } while (1);

diff --git a/lustre/obdclass/obd_config.c b/lustre/obdclass/obd_config.c
index fa49749..d23f1b9 100644 (file)
--- a/lustre/obdclass/obd_config.c
+++ b/lustre/obdclass/obd_config.c
@@ -1303,12 +1303,12 @@ int class_process_proc_param(char *prefix, struct lprocfs_vars *lvars,
                         CERROR("writing proc entry %s err %d\n",
                                var->name, rc);
                         rc = 0;
                         CERROR("writing proc entry %s err %d\n",
                                var->name, rc);
                         rc = 0;

-                } else {
-                        CDEBUG(D_CONFIG, "%s.%.*s: set parameter %.*s=%s\n",
-                                      lustre_cfg_string(lcfg, 0),
-                                      (int)strlen(prefix) - 1, prefix,
-                                      (int)(sval - key - 1), key, sval);
-                }
+               } else {
+                       CDEBUG(D_CONFIG, "%s.%.*s: Set parameter %.*s=%s\n",
+                                        lustre_cfg_string(lcfg, 0),
+                                        (int)strlen(prefix) - 1, prefix,
+                                        (int)(sval - key - 1), key, sval);
+               }

         }
 
         if (rc > 0)
         }
 
         if (rc > 0)

diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c
index 5ebdef3..3d4d73a 100644 (file)
--- a/lustre/ptlrpc/client.c
+++ b/lustre/ptlrpc/client.c
@@ -1033,9 +1033,11 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
         } else if (imp->imp_state == LUSTRE_IMP_NEW) {
                 DEBUG_REQ(D_ERROR, req, "Uninitialized import.");
                 *status = -EIO;
         } 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) {
-                DEBUG_REQ(D_ERROR, req, "IMP_CLOSED ");
-                *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 ?
+                         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 after initial testing */
                 DEBUG_REQ(D_ERROR, req, "send limit expired ");
         } else if (ptlrpc_send_limit_expired(req)) {
                 /* probably doesn't need to be a D_ERROR after initial testing */
                 DEBUG_REQ(D_ERROR, req, "send limit expired ");


@@ -1047,11 +1049,11 @@ static int ptlrpc_import_delay_req(struct obd_import *imp,
                         DEBUG_REQ(D_ERROR, req, "invalidate in flight");
                         *status = -EIO;
                 }
                         DEBUG_REQ(D_ERROR, req, "invalidate in flight");
                         *status = -EIO;
                 }

-        } else if (imp->imp_invalid || imp->imp_obd->obd_no_recov) {
-                if (!imp->imp_deactive)
-                          DEBUG_REQ(D_ERROR, req, "IMP_INVALID");
-                *status = -ESHUTDOWN; /* bz 12940 */
-        } else if (req->rq_import_generation != imp->imp_generation) {
+       } else if (imp->imp_invalid || imp->imp_obd->obd_no_recov) {
+               if (!imp->imp_deactive)
+                       DEBUG_REQ(D_NET, req, "IMP_INVALID");
+               *status = -ESHUTDOWN; /* bz 12940 */
+       } else if (req->rq_import_generation != imp->imp_generation) {

                 DEBUG_REQ(D_ERROR, req, "req wrong generation:");
                 *status = -EIO;
         } else if (req->rq_send_state != imp->imp_state) {
                 DEBUG_REQ(D_ERROR, req, "req wrong generation:");
                 *status = -EIO;
         } else if (req->rq_send_state != imp->imp_state) {


@@ -1111,18 +1113,18 @@ static int ptlrpc_check_status(struct ptlrpc_request *req)
         ENTRY;
 
         err = lustre_msg_get_status(req->rq_repmsg);
         ENTRY;
 
         err = 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;
-                __u32 opc = lustre_msg_get_opc(req->rq_reqmsg);
-                if (ptlrpc_console_allow(req))
-                        LCONSOLE_ERROR_MSG(0x011,"an error occurred while "
-                                           "communicating with %s. The %s "
-                                           "operation failed with %d\n",
-                                           libcfs_nid2str(
-                                           imp->imp_connection->c_peer.nid),
-                                           ll_opcode2str(opc), err);
-                RETURN(err < 0 ? err : -EINVAL);
-        }
+       if (lustre_msg_get_type(req->rq_repmsg) == PTL_RPC_MSG_ERR) {
+               struct obd_import *imp = req->rq_import;
+               __u32 opc = lustre_msg_get_opc(req->rq_reqmsg);
+               if (ptlrpc_console_allow(req))
+                       LCONSOLE_ERROR_MSG(0x011, "%s: Communicating with %s,"
+                                          " operation %s failed with %d.\n",
+                                          imp->imp_obd->obd_name,
+                                          libcfs_nid2str(
+                                          imp->imp_connection->c_peer.nid),
+                                          ll_opcode2str(opc), err);
+               RETURN(err < 0 ? err : -EINVAL);
+       }

 
         if (err < 0) {
                 DEBUG_REQ(D_INFO, req, "status is %d", err);
 
         if (err < 0) {
                 DEBUG_REQ(D_INFO, req, "status is %d", err);

diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c
index 30af7d4..09b32fa 100644 (file)
--- a/lustre/ptlrpc/service.c
+++ b/lustre/ptlrpc/service.c
@@ -1091,14 +1091,14 @@ static int ptlrpc_check_req(struct ptlrpc_request *req)
 {
         int rc = 0;
 
 {
         int rc = 0;
 

-        if (unlikely(lustre_msg_get_conn_cnt(req->rq_reqmsg) <
-                     req->rq_export->exp_conn_cnt)) {
-                DEBUG_REQ(D_ERROR, req,
-                          "DROPPING req from old connection %d < %d",
-                          lustre_msg_get_conn_cnt(req->rq_reqmsg),
-                          req->rq_export->exp_conn_cnt);
-                return -EEXIST;
-        }
+       if (unlikely(lustre_msg_get_conn_cnt(req->rq_reqmsg) <
+                    req->rq_export->exp_conn_cnt)) {
+               DEBUG_REQ(D_RPCTRACE, req,
+                         "DROPPING req from old connection %d < %d",
+                         lustre_msg_get_conn_cnt(req->rq_reqmsg),
+                         req->rq_export->exp_conn_cnt);
+               return -EEXIST;
+       }

         if (unlikely(req->rq_export->exp_obd &&
                      req->rq_export->exp_obd->obd_fail)) {
              /* Failing over, don't handle any more reqs, send
         if (unlikely(req->rq_export->exp_obd &&
                      req->rq_export->exp_obd->obd_fail)) {
              /* Failing over, don't handle any more reqs, send


@@ -2020,15 +2020,15 @@ put_conn:
         lu_context_exit(&request->rq_session);
         lu_context_fini(&request->rq_session);
 
         lu_context_exit(&request->rq_session);
         lu_context_fini(&request->rq_session);
 

-        if (unlikely(cfs_time_current_sec() > request->rq_deadline)) {
-                DEBUG_REQ(D_WARNING, request, "Request x"LPU64" took longer "
-                          "than estimated ("CFS_DURATION_T":"CFS_DURATION_T"s);"
-                          " client may timeout.",
-                          request->rq_xid, cfs_time_sub(request->rq_deadline,
-                          request->rq_arrival_time.tv_sec),
-                          cfs_time_sub(cfs_time_current_sec(),
-                          request->rq_deadline));
-        }
+       if (unlikely(cfs_time_current_sec() > request->rq_deadline)) {
+                    DEBUG_REQ(D_WARNING, request, "Request took longer "
+                              "than estimated ("CFS_DURATION_T":"CFS_DURATION_T"s);"
+                              " client may timeout.",
+                              cfs_time_sub(request->rq_deadline,
+                                           request->rq_arrival_time.tv_sec),
+                              cfs_time_sub(cfs_time_current_sec(),
+                                           request->rq_deadline));
+       }

 
         cfs_gettimeofday(&work_end);
         timediff = cfs_timeval_sub(&work_end, &work_start, NULL);
 
         cfs_gettimeofday(&work_end);
         timediff = cfs_timeval_sub(&work_end, &work_start, NULL);