Whamcloud - gitweb
LU-1095 debug: Common client/server message standardization
[fs/lustre-release.git] / lustre / ldlm / ldlm_lib.c
index 2821552..2483afb 100644 (file)
@@ -28,9 +28,8 @@
 /*
  * Copyright (c) 2003, 2010, Oracle and/or its affiliates. All rights reserved.
  * Use is subject to license terms.
- */
-/*
- * Copyright (c) 2011 Whamcloud, Inc.
+ *
+ * Copyright (c) 2011, 2012, Whamcloud, Inc.
  */
 /*
  * This file is part of Lustre, http://www.lustre.org/
@@ -227,6 +226,7 @@ void client_destroy_import(struct obd_import *imp)
         sptlrpc_import_sec_put(imp);
         class_import_put(imp);
 }
+EXPORT_SYMBOL(client_destroy_import);
 
 /* configure an RPC client OBD device
  *
@@ -429,6 +429,8 @@ int client_obd_cleanup(struct obd_device *obddev)
         ldlm_namespace_free_post(obddev->obd_namespace);
         obddev->obd_namespace = NULL;
 
+        LASSERT(obddev->u.cli.cl_import == NULL);
+
         ldlm_put_ref();
         RETURN(0);
 }
@@ -561,13 +563,6 @@ int client_disconnect_export(struct obd_export *exp)
 
         ptlrpc_invalidate_import(imp);
 
-        if (imp->imp_rq_pool) {
-                ptlrpc_free_rq_pool(imp->imp_rq_pool);
-                imp->imp_rq_pool = NULL;
-        }
-        client_destroy_import(imp);
-        cli->cl_import = NULL;
-
         EXIT;
 
  out_disconnect:
@@ -625,24 +620,47 @@ static int target_handle_reconnect(struct lustre_handle *conn,
                                    struct obd_uuid *cluuid)
 {
         ENTRY;
+
         if (exp->exp_connection && exp->exp_imp_reverse) {
                 struct lustre_handle *hdl;
+                struct obd_device *target;
+
                 hdl = &exp->exp_imp_reverse->imp_remote_handle;
+                target = exp->exp_obd;
+
                 /* Might be a re-connect after a partition. */
                 if (!memcmp(&conn->cookie, &hdl->cookie, sizeof conn->cookie)) {
-                        CWARN("%s: %s reconnecting\n", exp->exp_obd->obd_name,
-                              cluuid->uuid);
+                        if (target->obd_recovering)
+                                LCONSOLE_WARN("%s: Client %s (at %s) reconnect"
+                                        "ing, waiting for %d clients in "
+                                        "recovery for %lds\n", target->obd_name,
+                                        obd_uuid2str(&exp->exp_client_uuid),
+                                        obd_export_nid2str(exp),
+                                        target->obd_max_recoverable_clients,
+                                        cfs_duration_sec(cfs_time_sub(
+                                        cfs_timer_deadline(
+                                        &target->obd_recovery_timer),
+                                        cfs_time_current())));
+                        else
+                                LCONSOLE_WARN("%s: Client %s (at %s) "
+                                        "reconnecting\n", target->obd_name,
+                                        obd_uuid2str(&exp->exp_client_uuid),
+                                        obd_export_nid2str(exp));
+
                         conn->cookie = exp->exp_handle.h_cookie;
                         /* target_handle_connect() treats EALREADY and
                          * -EALREADY differently.  EALREADY means we are
                          * doing a valid reconnect from the same client. */
                         RETURN(EALREADY);
                 } else {
-                        CERROR("%s reconnecting from %s, "
-                               "handle mismatch (ours "LPX64", theirs "
-                               LPX64")\n", cluuid->uuid,
-                               exp->exp_connection->c_remote_uuid.uuid,
-                               hdl->cookie, conn->cookie);
+                        LCONSOLE_WARN("%s: The server has already connected "
+                                      "client %s (at %s) with handle " LPX64
+                                      ", rejecting a client with the same "
+                                      "uuid trying to reconnect with "
+                                      "handle " LPX64, target->obd_name,
+                                      obd_uuid2str(&exp->exp_client_uuid),
+                                      obd_export_nid2str(exp),
+                                      hdl->cookie, conn->cookie);
                         memset(conn, 0, sizeof *conn);
                         /* target_handle_connect() treats EALREADY and
                          * -EALREADY differently.  -EALREADY is an error
@@ -696,6 +714,8 @@ int target_handle_connect(struct ptlrpc_request *req)
         struct obd_uuid remote_uuid;
         char *str;
         int rc = 0;
+        char *target_start;
+        int target_len;
         int mds_conn = 0;
         struct obd_connect_data *data, *tmpdata;
         int size, tmpsize;
@@ -716,16 +736,17 @@ int target_handle_connect(struct ptlrpc_request *req)
                 target = class_name2obd(str);
 
         if (!target || target->obd_stopping || !target->obd_set_up) {
-                LCONSOLE_ERROR_MSG(0x137, "UUID '%s' is not available "
-                                   "for connect (%s)\n", str,
-                                   !target ? "no target" :
-                                   (target->obd_stopping ? "stopping" :
-                                   "not set up"));
+                deuuidify(str, NULL, &target_start, &target_len);
+                LCONSOLE_ERROR_MSG(0x137, "%.*s: Not available for connect "
+                                   "from %s (%s)\n", target_len, target_start,
+                                   libcfs_nid2str(req->rq_peer.nid), !target ?
+                                   "no target" : (target->obd_stopping ?
+                                   "stopping" : "not set up"));
                 GOTO(out, rc = -ENODEV);
         }
 
         if (target->obd_no_conn) {
-                LCONSOLE_WARN("%s: temporarily refusing client connection "
+                LCONSOLE_WARN("%s: Temporarily refusing client connection "
                               "from %s\n", target->obd_name,
                               libcfs_nid2str(req->rq_peer.nid));
                 GOTO(out, rc = -EAGAIN);
@@ -819,22 +840,23 @@ int target_handle_connect(struct ptlrpc_request *req)
 
         /* we've found an export in the hash */
         if (export->exp_connecting) { /* bug 9635, et. al. */
-                CWARN("%s: exp %p already connecting\n",
-                      export->exp_obd->obd_name, export);
+                LCONSOLE_WARN("%s: Export %p already connecting from %s\n",
+                              export->exp_obd->obd_name, export,
+                              libcfs_nid2str(req->rq_peer.nid));
                 class_export_put(export);
                 export = NULL;
                 rc = -EALREADY;
         } else if (mds_conn && export->exp_connection) {
                 if (req->rq_peer.nid != export->exp_connection->c_peer.nid)
                         /* mds reconnected after failover */
-                        CWARN("%s: received MDS connection from NID %s,"
-                              " removing former export from NID %s\n",
+                        LCONSOLE_WARN("%s: Received MDS connection from "
+                            "%s, removing former export from %s\n",
                             target->obd_name, libcfs_nid2str(req->rq_peer.nid),
                             libcfs_nid2str(export->exp_connection->c_peer.nid));
                 else
                         /* new mds connection from the same nid */
-                        CWARN("%s: received new MDS connection from NID %s,"
-                              " removing former export from same NID\n",
+                        LCONSOLE_WARN("%s: Received new MDS connection from "
+                            "%s, removing former export from same NID\n",
                             target->obd_name, libcfs_nid2str(req->rq_peer.nid));
                 class_fail_export(export);
                 class_export_put(export);
@@ -846,11 +868,12 @@ int target_handle_connect(struct ptlrpc_request *req)
                     MSG_CONNECT_INITIAL)) {
                 /* in mds failover we have static uuid but nid can be
                  * changed*/
-                CWARN("%s: cookie %s seen on new NID %s when "
-                      "existing NID %s is already connected\n",
-                      target->obd_name, cluuid.uuid,
-                      libcfs_nid2str(req->rq_peer.nid),
-                      libcfs_nid2str(export->exp_connection->c_peer.nid));
+                LCONSOLE_WARN("%s: Client %s seen on new nid %s when "
+                              "existing nid %s is already connected\n",
+                              target->obd_name, cluuid.uuid,
+                              libcfs_nid2str(req->rq_peer.nid),
+                              libcfs_nid2str(
+                                      export->exp_connection->c_peer.nid));
                 rc = -EALREADY;
                 class_export_put(export);
                 export = NULL;
@@ -858,7 +881,6 @@ int target_handle_connect(struct ptlrpc_request *req)
                 cfs_spin_lock(&export->exp_lock);
                 export->exp_connecting = 1;
                 cfs_spin_unlock(&export->exp_lock);
-                class_export_put(export);
                 LASSERT(export->exp_obd == target);
 
                 rc = target_handle_reconnect(&conn, export, &cluuid);
@@ -870,18 +892,20 @@ no_export:
                 OBD_FAIL_TIMEOUT(OBD_FAIL_TGT_DELAY_CONNECT, 2 * obd_timeout);
         } else if (req->rq_export == NULL &&
                    cfs_atomic_read(&export->exp_rpc_count) > 0) {
-                CWARN("%s: refuse connection from %s/%s to 0x%p/%d\n",
-                      target->obd_name, cluuid.uuid,
-                      libcfs_nid2str(req->rq_peer.nid),
-                      export, cfs_atomic_read(&export->exp_refcount));
+                LCONSOLE_WARN("%s: Client %s (at %s) refused connection, "
+                              "still busy with %d references\n",
+                              target->obd_name, cluuid.uuid,
+                              libcfs_nid2str(req->rq_peer.nid),
+                              cfs_atomic_read(&export->exp_refcount));
                 GOTO(out, rc = -EBUSY);
         } else if (req->rq_export != NULL &&
                    (cfs_atomic_read(&export->exp_rpc_count) > 1)) {
                 /* the current connect rpc has increased exp_rpc_count */
-                CWARN("%s: refuse reconnection from %s@%s to 0x%p/%d\n",
-                      target->obd_name, cluuid.uuid,
-                      libcfs_nid2str(req->rq_peer.nid),
-                      export, cfs_atomic_read(&export->exp_rpc_count) - 1);
+                LCONSOLE_WARN("%s: Client %s (at %s) refused reconnection, "
+                              "still busy with %d active RPCs\n",
+                              target->obd_name, cluuid.uuid,
+                              libcfs_nid2str(req->rq_peer.nid),
+                              cfs_atomic_read(&export->exp_rpc_count) - 1);
                 cfs_spin_lock(&export->exp_lock);
                 if (req->rq_export->exp_conn_cnt <
                     lustre_msg_get_conn_cnt(req->rq_reqmsg))
@@ -890,9 +914,12 @@ no_export:
                 cfs_spin_unlock(&export->exp_lock);
                 GOTO(out, rc = -EBUSY);
         } else if (lustre_msg_get_conn_cnt(req->rq_reqmsg) == 1) {
-                CERROR("%s: NID %s (%s) reconnected with 1 conn_cnt; "
-                       "cookies not random?\n", target->obd_name,
-                       libcfs_nid2str(req->rq_peer.nid), cluuid.uuid);
+                if (!strstr(cluuid.uuid, "mdt"))
+                        LCONSOLE_WARN("%s: Rejecting reconnect from the "
+                                      "known client %s (at %s) because it "
+                                      "is indicating it is a new client",
+                                      target->obd_name, cluuid.uuid,
+                                      libcfs_nid2str(req->rq_peer.nid));
                 GOTO(out, rc = -EALREADY);
         } else {
                 OBD_FAIL_TIMEOUT(OBD_FAIL_TGT_DELAY_RECONNECT, 2 * obd_timeout);
@@ -902,7 +929,7 @@ no_export:
                 GOTO(out, rc);
         }
 
-        CWARN("%s: connection from %s@%s %st"LPU64" exp %p cur %ld last %ld\n",
+        CDEBUG(D_HA, "%s: connection from %s@%s %st"LPU64" exp %p cur %ld last %ld\n",
                target->obd_name, cluuid.uuid, libcfs_nid2str(req->rq_peer.nid),
               target->obd_recovering ? "recovering/" : "", data->ocd_transno,
               export, (long)cfs_time_current_sec(),
@@ -933,21 +960,27 @@ no_export:
 
                         t = cfs_timer_deadline(&target->obd_recovery_timer);
                         t = cfs_time_sub(t, cfs_time_current());
-                        CERROR("%s: denying connection for new client %s (%s): "
-                               "%d clients in recovery for "CFS_TIME_T"s\n",
-                               target->obd_name,
-                               libcfs_nid2str(req->rq_peer.nid), cluuid.uuid,
-                               cfs_atomic_read(&target-> \
-                                               obd_lock_replay_clients),
-                               cfs_duration_sec(t));
+                        LCONSOLE_WARN("%s: Denying connection for new client "
+                                      "%s (at %s), waiting for %d clients in "
+                                      "recovery for "CFS_TIME_T"s\n",
+                                      target->obd_name,
+                                      libcfs_nid2str(req->rq_peer.nid),
+                                      cluuid.uuid,
+                                      cfs_atomic_read(&target-> \
+                                                      obd_lock_replay_clients),
+                                      cfs_duration_sec(t));
                         rc = -EBUSY;
                 } else {
 dont_check_exports:
                         rc = obd_connect(req->rq_svc_thread->t_env,
                                          &export, target, &cluuid, data,
                                          client_nid);
-                        if (rc == 0)
+                        if (rc == 0) {
                                 conn.cookie = export->exp_handle.h_cookie;
+                                /* LU-1092 reconnect put export refcount in the
+                                 * end, connect needs take one here too. */
+                                class_export_get(export);
+                        }
                 }
         } else {
                 rc = obd_reconnect(req->rq_svc_thread->t_env,
@@ -995,7 +1028,8 @@ dont_check_exports:
         cfs_spin_lock(&export->exp_lock);
         if (export->exp_conn_cnt >= lustre_msg_get_conn_cnt(req->rq_reqmsg)) {
                 cfs_spin_unlock(&export->exp_lock);
-                CERROR("%s: %s already connected at higher conn_cnt: %d > %d\n",
+                CDEBUG(D_RPCTRACE, "%s: %s already connected at higher "
+                       "conn_cnt: %d > %d\n",
                        cluuid.uuid, libcfs_nid2str(req->rq_peer.nid),
                        export->exp_conn_cnt,
                        lustre_msg_get_conn_cnt(req->rq_reqmsg));
@@ -1037,7 +1071,9 @@ dont_check_exports:
                              &export->exp_connection->c_peer.nid,
                              &export->exp_nid_hash);
         }
-
+        /**
+          class_disconnect->class_export_recovery_cleanup() race
+         */
         if (target->obd_recovering && !export->exp_in_recovery) {
                 int has_transno;
                 __u64 transno = data->ocd_transno;
@@ -1130,6 +1166,8 @@ out:
                 cfs_spin_lock(&export->exp_lock);
                 export->exp_connecting = 0;
                 cfs_spin_unlock(&export->exp_lock);
+
+                class_export_put(export);
         }
         if (targref)
                 class_decref(targref, __FUNCTION__, cfs_current());
@@ -1408,34 +1446,46 @@ static void target_start_recovery_timer(struct obd_device *obd)
                       (obd->obd_max_recoverable_clients == 1) ? "s": "");
 }
 
-/* extend recovery window to have extra @duration seconds at least. */
-static void extend_recovery_timer(struct obd_device *obd, int drt)
+/**
+ * extend recovery window.
+ *
+ * if @extend is true, extend recovery window to have @drt remaining at least;
+ * otherwise, make sure the recovery timeout value is not less than @drt.
+ */
+static void extend_recovery_timer(struct obd_device *obd, int drt, bool extend)
 {
         cfs_time_t now;
         cfs_time_t end;
         cfs_duration_t left;
+        int to;
 
         cfs_spin_lock(&obd->obd_dev_lock);
         if (!obd->obd_recovering || obd->obd_abort_recovery) {
                 cfs_spin_unlock(&obd->obd_dev_lock);
                 return;
         }
-
         LASSERT(obd->obd_recovery_start != 0);
 
-        now = cfs_time_current_sec();
-        end = obd->obd_recovery_start + obd->obd_recovery_timeout;
+        now  = cfs_time_current_sec();
+        to   = obd->obd_recovery_timeout;
+        end  = obd->obd_recovery_start + to;
         left = cfs_time_sub(end, now);
-        if (left < 0) {
-                obd->obd_recovery_timeout += drt - left;
-        } else if (left < drt) {
-                drt -= left;
-                obd->obd_recovery_timeout += drt;
-        } else {
-                drt = left;
+
+        if (extend && (drt > left)) {
+                to += drt - left;
+        } else if (!extend && (drt > to)) {
+                to = drt;
+                /* reduce drt by already passed time */
+                drt -= obd->obd_recovery_timeout - left;
         }
 
-        cfs_timer_arm(&obd->obd_recovery_timer, cfs_time_shift(drt));
+        if (to > obd->obd_recovery_time_hard)
+                to = obd->obd_recovery_time_hard;
+        if (obd->obd_recovery_timeout < to) {
+                obd->obd_recovery_timeout = to;
+                cfs_timer_arm(&obd->obd_recovery_timer,
+                              cfs_time_shift(drt));
+        }
         cfs_spin_unlock(&obd->obd_dev_lock);
 
         CDEBUG(D_HA, "%s: recovery timer will expire in %u seconds\n",
@@ -1484,9 +1534,8 @@ check_and_start_recovery_timer(struct obd_device *obd,
         if (!(lsi->lsi_flags | LSI_IR_CAPABLE))
                 service_time += 2 * (CONNECTION_SWITCH_MAX +
                                      CONNECTION_SWITCH_INC);
-        service_time -= obd->obd_recovery_timeout;
-        if (service_time > 0)
-                extend_recovery_timer(obd, service_time);
+        if (service_time > obd->obd_recovery_timeout && !new_client)
+                extend_recovery_timer(obd, service_time, false);
 }
 
 /** Health checking routines */
@@ -1652,7 +1701,7 @@ repeat:
                  * reset timer, recovery will proceed with versions now,
                  * timeout is set just to handle reconnection delays
                  */
-                extend_recovery_timer(obd, RECONNECT_DELAY_MAX);
+                extend_recovery_timer(obd, RECONNECT_DELAY_MAX, true);
                 /** Wait for recovery events again, after evicting bad clients */
                 goto repeat;
         }
@@ -1776,9 +1825,20 @@ static int handle_recovery_req(struct ptlrpc_thread *thread,
                  * Add request timeout to the recovery time so next request from
                  * this client may come in recovery time
                  */
-                if (!AT_OFF)
-                        to = lustre_msg_get_timeout(req->rq_reqmsg);
-                 extend_recovery_timer(class_exp2obd(req->rq_export), to);
+                if (!AT_OFF) {
+                        struct ptlrpc_service *svc = req->rq_rqbd->rqbd_service;
+                        /* If the server sent early reply for this request,
+                         * the client will recalculate the timeout according to
+                         * current server estimate service time, so we will
+                         * use the maxium timeout here for waiting the client
+                         * sending the next req */
+                        to = max((int)at_est2timeout(
+                                 at_get(&svc->srv_at_estimate)),
+                                 (int)lustre_msg_get_timeout(req->rq_reqmsg));
+                        /* Add net_latency (see ptlrpc_replay_req) */
+                        to += lustre_msg_get_service_time(req->rq_reqmsg);
+                }
+                extend_recovery_timer(class_exp2obd(req->rq_export), to, true);
         }
 reqcopy_put:
         RETURN(rc);
@@ -1792,8 +1852,8 @@ static int target_recovery_thread(void *arg)
         struct target_recovery_data *trd = &obd->obd_recovery_data;
         unsigned long delta;
         unsigned long flags;
-        struct lu_env env;
-        struct ptlrpc_thread fake_svc_thread, *thread = &fake_svc_thread;
+        struct lu_env *env;
+        struct ptlrpc_thread *thread = NULL;
         int rc = 0;
         ENTRY;
 
@@ -1804,14 +1864,28 @@ static int target_recovery_thread(void *arg)
         RECALC_SIGPENDING;
         SIGNAL_MASK_UNLOCK(current, flags);
 
-        rc = lu_context_init(&env.le_ctx, LCT_MD_THREAD);
-        if (rc)
+        OBD_ALLOC_PTR(thread);
+        if (thread == NULL)
+                RETURN(-ENOMEM);
+
+        OBD_ALLOC_PTR(env);
+        if (env == NULL) {
+                OBD_FREE_PTR(thread);
+                RETURN(-ENOMEM);
+        }
+
+        rc = lu_context_init(&env->le_ctx, LCT_MD_THREAD);
+        if (rc) {
+                OBD_FREE_PTR(thread);
+                OBD_FREE_PTR(env);
                 RETURN(rc);
+        }
 
-        thread->t_env = &env;
+        thread->t_env = env;
         thread->t_id = -1; /* force filter_iobuf_get/put to use local buffers */
-        env.le_ctx.lc_thread = thread;
+        env->le_ctx.lc_thread = thread;
         thread->t_data = NULL;
+        thread->t_watchdog = NULL;
 
         CDEBUG(D_HA, "%s: started recovery thread pid %d\n", obd->obd_name,
                cfs_curproc_pid());
@@ -1902,9 +1976,12 @@ static int target_recovery_thread(void *arg)
 
         target_finish_recovery(obd);
 
-        lu_context_fini(&env.le_ctx);
+        lu_context_fini(&env->le_ctx);
         trd->trd_processing_task = 0;
         cfs_complete(&trd->trd_finishing);
+
+        OBD_FREE_PTR(thread);
+        OBD_FREE_PTR(env);
         RETURN(rc);
 }
 
@@ -2197,7 +2274,7 @@ int target_send_reply_msg(struct ptlrpc_request *req, int rc, int fail_id)
         }
 
         if (unlikely(rc)) {
-                DEBUG_REQ(D_ERROR, req, "processing error (%d)", rc);
+                DEBUG_REQ(D_NET, req, "processing error (%d)", rc);
                 req->rq_status = rc;
                 return (ptlrpc_send_error(req, 1));
         } else {
@@ -2211,7 +2288,6 @@ void target_send_reply(struct ptlrpc_request *req, int rc, int fail_id)
 {
         int                        netrc;
         struct ptlrpc_reply_state *rs;
-        struct obd_device         *obd;
         struct obd_export         *exp;
         struct ptlrpc_service     *svc;
         ENTRY;
@@ -2245,7 +2321,6 @@ void target_send_reply(struct ptlrpc_request *req, int rc, int fail_id)
         LASSERT (cfs_list_empty(&rs->rs_exp_list));
 
         exp = class_export_get (req->rq_export);
-        obd = exp->exp_obd;
 
         /* disable reply scheduling while I'm setting up */
         rs->rs_scheduled = 1;