cfs_cpu_fini();
+ /* the below message is checked in test-framework.sh check_mem_leak() */
if (atomic_read(&libcfs_kmemory) != 0)
CERROR("Portals memory leaked: %d bytes\n",
atomic_read(&libcfs_kmemory));
atomic_dec(&req->rq_import->imp_unregistering);
}
- DEBUG_REQ(D_INFO, req, "move req \"%s\" -> \"%s\"",
+ DEBUG_REQ(D_INFO, req, "move request phase from %s to %s",
ptlrpc_rqphase2str(req), ptlrpc_phase2str(new_phase));
req->rq_phase = new_phase;
MA_PFID = 1 << 7,
MA_LMV_DEF = 1 << 8,
MA_SOM = 1 << 9,
+ MA_FORCE_LOG = 1 << 10, /* forced close logged in mdt_mfd_close */
};
typedef enum {
struct ptlrpc_request *req)
{
DEBUG_REQ(D_HA, req,
- "remove t%lld from %s because of duplicate update records are found.\n",
+ "remove t%lld from %s because duplicate update records found",
lustre_msg_get_transno(req->rq_reqmsg),
libcfs_nid2str(req->rq_peer.nid));
lustre_msg_set_transno(req->rq_repmsg, req->rq_transno);
target_send_reply(req, req->rq_status, 0);
} else {
- DEBUG_REQ(D_ERROR, req, "wrong opc from %s\n",
+ DEBUG_REQ(D_ERROR, req, "wrong opc from %s",
libcfs_nid2str(req->rq_peer.nid));
}
target_exp_dequeue_req_replay(req);
atomic_read(&obd->obd_lock_replay_clients));
while ((req = target_next_replay_lock(lut))) {
LASSERT(trd->trd_processing_task == current_pid());
- DEBUG_REQ(D_HA, req, "processing lock from %s: ",
+ DEBUG_REQ(D_HA, req, "processing lock from %s:",
libcfs_nid2str(req->rq_peer.nid));
handle_recovery_req(thread, req,
trd->trd_recovery_handler);
spin_unlock(&obd->obd_recovery_task_lock);
while ((req = target_next_final_ping(obd))) {
LASSERT(trd->trd_processing_task == current_pid());
- DEBUG_REQ(D_HA, req, "processing final ping from %s: ",
+ DEBUG_REQ(D_HA, req, "processing final ping from %s:",
libcfs_nid2str(req->rq_peer.nid));
handle_recovery_req(thread, req,
trd->trd_recovery_handler);
if (duplicate != NULL) {
DEBUG_REQ(D_HA, duplicate,
- "put prev final req\n");
+ "put prev final req");
target_request_copy_put(duplicate);
}
RETURN(0);
}
if (rc < 0) {
- DEBUG_REQ(D_ERROR, req, "bulk %s failed: rc %d",
+ DEBUG_REQ(D_ERROR, req, "bulk %s failed: rc = %d",
bulk2type(req), rc);
RETURN(rc);
}
} else {
if (ldlm_reclaim_full()) {
DEBUG_REQ(D_DLMTRACE, req,
- "Too many granted locks, reject current enqueue request and let the client retry later.\n");
+ "Too many granted locks, reject current enqueue request and let the client retry later");
GOTO(out, rc = -EINPROGRESS);
}
}
for (i = first; i < count; i++) {
lock = ldlm_handle2lock(&dlm_req->lock_handle[i]);
if (!lock) {
+ /* below message checked in replay-single.sh test_36 */
LDLM_DEBUG_NOLOCK("server-side cancel handler stale lock (cookie %llu)",
dlm_req->lock_handle[i].cookie);
continue;
ENTRY;
- DEBUG_REQ(D_HSM, req, "%s: handle setinfo\n", obd->obd_name);
+ DEBUG_REQ(D_HSM, req, "%s: handle setinfo", obd->obd_name);
req_capsule_set(&req->rq_pill, &RQF_OBD_SET_INFO);
KEY_HSM_COPYTOOL_SEND,
vallen, val, NULL);
else
- DEBUG_REQ(D_WARNING, req, "ignoring unknown key %s", key);
+ DEBUG_REQ(D_WARNING, req, "ignoring unknown key '%s'", key);
return rc;
}
const struct lustre_handle *handle)
{
DEBUG_REQ((req->rq_no_reply || rc) ? D_WARNING : D_DLMTRACE, req,
- "%s: [nid %s] [rc %d] [lock %#llx]",
- msg, libcfs_id2str(req->rq_peer), rc,
- handle ? handle->cookie : 0);
+ "%s, NID=%s lock=%#llx: rc = %d",
+ msg, libcfs_id2str(req->rq_peer),
+ handle ? handle->cookie : 0, rc);
if (req->rq_no_reply)
CWARN("No reply was sent, maybe cause b=21636.\n");
else if (rc)
if (lustre_handle_equal(&dlm_req->lock_handle[i],
&lockh)) {
DEBUG_REQ(D_RPCTRACE, req,
- "Prio raised by lock %#llx.", lockh.cookie);
+ "Prio raised by lock %#llx", lockh.cookie);
rc = 1;
break;
}
}
if (*flags & LDLM_FL_NDELAY) {
- DEBUG_REQ(D_DLMTRACE, req, "enque lock with no delay\n");
+ DEBUG_REQ(D_DLMTRACE, req, "enqueue lock with no delay");
req->rq_no_resend = req->rq_no_delay = 1;
/*
* probably set a shorter timeout value and handle ETIMEDOUT
if (lustre_msg_get_slv(req->rq_repmsg) == 0 ||
lustre_msg_get_limit(req->rq_repmsg) == 0) {
DEBUG_REQ(D_HA, req,
- "Zero SLV or Limit found (SLV: %llu, Limit: %u)",
+ "Zero SLV or limit found (SLV=%llu, limit=%u)",
lustre_msg_get_slv(req->rq_repmsg),
lustre_msg_get_limit(req->rq_repmsg));
RETURN(0);
path = ll_d_path(dentry, buf, PAGE_SIZE);
}
+ /* The below message is checked in recovery-small.sh test_24b */
CDEBUG(D_WARNING,
"%s: dirty page discard: %s/fid: "DFID"/%s may get corrupted "
"(rc %d)\n", ll_i2sbi(inode)->ll_fsname,
spin_lock(&req->rq_lock);
req->rq_replay = 0;
spin_unlock(&req->rq_lock);
- }
- if (rc && req->rq_transno != 0) {
- DEBUG_REQ(D_ERROR, req, "transno returned on error rc %d", rc);
- LBUG();
- }
+ }
+ if (rc && req->rq_transno != 0) {
+ DEBUG_REQ(D_ERROR, req, "transno returned on error: rc = %d",
+ rc);
+ LBUG();
+ }
}
/* Save a large LOV EA into the request buffer so that it is available
(!it_disposition(it, DISP_OPEN_OPEN) || it->it_status != 0))
mdc_clear_replay_flag(req, it->it_status);
- DEBUG_REQ(D_RPCTRACE, req, "op: %x disposition: %x, status: %d",
+ DEBUG_REQ(D_RPCTRACE, req, "op=%x disposition=%x, status=%d",
it->it_op, it->it_disposition, it->it_status);
/* We know what to expect, so we do any byte flipping required here */
LASSERT(obd_md_valid == OBD_MD_FLXATTR ||
obd_md_valid == OBD_MD_FLXATTRLS);
+ /* The below message is checked in sanity-selinux.sh test_20d */
CDEBUG(D_INFO, "%s: get xattr '%s' for "DFID"\n",
exp->exp_obd->obd_name, name, PFID(fid));
rc = mdc_xattr_common(exp, &RQF_MDS_GETXATTR, fid, MDS_GETXATTR,
if (mod == NULL) {
DEBUG_REQ(D_ERROR, req,
- "Can't properly replay without open data.");
+ "cannot properly replay without open data");
EXIT;
return;
}
/* Outgoing messages always in my byte order. */
LASSERT(body != NULL);
- /* Only if the import is replayable, we set replay_open data */
- if (och && imp->imp_replayable) {
- mod = obd_mod_alloc();
- if (mod == NULL) {
- DEBUG_REQ(D_ERROR, open_req,
- "Can't allocate md_open_data");
- RETURN(0);
- }
+ /* Only if the import is replayable, we set replay_open data */
+ if (och && imp->imp_replayable) {
+ mod = obd_mod_alloc();
+ if (mod == NULL) {
+ DEBUG_REQ(D_ERROR, open_req,
+ "cannot allocate md_open_data");
+ RETURN(0);
+ }
/**
* Take a reference on \var mod, to be freed on mdc_close().
* The worst thing is eviction if the client gets open lock
**/
- DEBUG_REQ(D_RPCTRACE, mod->mod_open_req, "free open request rq_replay"
- "= %d\n", mod->mod_open_req->rq_replay);
+ DEBUG_REQ(D_RPCTRACE, mod->mod_open_req,
+ "free open request, rq_replay=%d",
+ mod->mod_open_req->rq_replay);
ptlrpc_request_committed(mod->mod_open_req, committed);
if (mod->mod_close_req)
rc = ptlrpc_queue_wait(req);
mdc_put_mod_rpc_slot(req, NULL);
- if (req->rq_repmsg == NULL) {
- CDEBUG(D_RPCTRACE, "request failed to send: %p, %d\n", req,
- req->rq_status);
- if (rc == 0)
- rc = req->rq_status ?: -EIO;
- } else if (rc == 0 || rc == -EAGAIN) {
- struct mdt_body *body;
-
- rc = lustre_msg_get_status(req->rq_repmsg);
- if (lustre_msg_get_type(req->rq_repmsg) == PTL_RPC_MSG_ERR) {
- DEBUG_REQ(D_ERROR, req, "type == PTL_RPC_MSG_ERR, err "
- "= %d", rc);
- if (rc > 0)
- rc = -rc;
- }
- body = req_capsule_server_get(&req->rq_pill, &RMF_MDT_BODY);
- if (body == NULL)
- rc = -EPROTO;
- } else if (rc == -ESTALE) {
- /**
- * it can be allowed error after 3633 if open was committed and
- * server failed before close was sent. Let's check if mod
- * exists and return no error in that case
- */
- if (mod) {
- DEBUG_REQ(D_HA, req, "Reset ESTALE = %d", rc);
- LASSERT(mod->mod_open_req != NULL);
- if (mod->mod_open_req->rq_committed)
- rc = 0;
- }
- }
+ if (req->rq_repmsg == NULL) {
+ CDEBUG(D_RPCTRACE, "request %p failed to send: rc = %d\n", req,
+ req->rq_status);
+ if (rc == 0)
+ rc = req->rq_status ?: -EIO;
+ } else if (rc == 0 || rc == -EAGAIN) {
+ struct mdt_body *body;
+
+ rc = lustre_msg_get_status(req->rq_repmsg);
+ if (lustre_msg_get_type(req->rq_repmsg) == PTL_RPC_MSG_ERR) {
+ DEBUG_REQ(D_ERROR, req,
+ "type = PTL_RPC_MSG_ERR: rc = %d", rc);
+ if (rc > 0)
+ rc = -rc;
+ }
+ body = req_capsule_server_get(&req->rq_pill, &RMF_MDT_BODY);
+ if (body == NULL)
+ rc = -EPROTO;
+ } else if (rc == -ESTALE) {
+ /**
+ * it can be allowed error after 3633 if open was committed and
+ * server failed before close was sent. Let's check if mod
+ * exists and return no error in that case
+ */
+ if (mod) {
+ DEBUG_REQ(D_HA, req, "Reset ESTALE = %d", rc);
+ LASSERT(mod->mod_open_req != NULL);
+ if (mod->mod_open_req->rq_committed)
+ rc = 0;
+ }
+ }
out:
if (mod) {
if (mdo->mod_count == 0) {
CDEBUG(D_HA, "Found orphan "DFID", delete it\n", PFID(lf));
rc = mdd_orphan_destroy(env, mdo, key);
- if (rc) /* so replay-single.sh test_37 works */
+ if (rc) /* below message checked in replay-single.sh test_37 */
CERROR("%s: error unlinking orphan "DFID": rc = %d\n",
mdd2obd_dev(mdd)->obd_name, PFID(lf), rc);
} else {
if (rc < 0) {
GOTO(out_ucred, rc);
} else if (rc == 1) {
- DEBUG_REQ(D_INODE, mdt_info_req(info), "resent opt.");
+ DEBUG_REQ(D_INODE, mdt_info_req(info), "resent opt");
rc = lustre_msg_get_status(mdt_info_req(info)->rq_repmsg);
GOTO(out_ucred, rc);
}
ma->ma_valid = MA_FLAGS;
ma->ma_attr_flags |= MDS_KEEP_ORPHAN;
}
- mdt_mfd_close(info, mfd);
- }
- }
- info->mti_mdt = NULL;
- /* cleanup client slot early */
- /* Do not erase record for recoverable client. */
- if (!(exp->exp_flags & OBD_OPT_FAILOVER) || exp->exp_failed)
+ ma->ma_valid |= MA_FORCE_LOG;
+ mdt_mfd_close(info, mfd);
+ }
+ }
+ info->mti_mdt = NULL;
+ /* cleanup client slot early */
+ /* Do not erase record for recoverable client. */
+ if (!(exp->exp_flags & OBD_OPT_FAILOVER) || exp->exp_failed)
tgt_client_del(&env, exp);
lu_env_fini(&env);
if (opc == OST_READ)
pa.lpa_mode |= LCK_PR;
- DEBUG_REQ(D_RPCTRACE, req, "%s %s: refresh rw locks: "DFID"\n",
+ DEBUG_REQ(D_RPCTRACE, req, "%s %s: refresh rw locks for " DFID,
tgt_name(tsi->tsi_tgt), current->comm, PFID(&tsi->tsi_fid));
mdt_prolong_dom_lock(tsi, &pa);
if (pa.lpa_blocks_cnt > 0) {
CDEBUG(D_DLMTRACE,
- "%s: refreshed %u locks timeout for req %p.\n",
+ "%s: refreshed %u locks timeout for req %p",
tgt_name(tsi->tsi_tgt), pa.lpa_blocks_cnt, req);
RETURN(1);
}
* via a regular replay. */
if (!(open_flags & MDS_OPEN_CREAT)) {
DEBUG_REQ(D_ERROR, req,
- "OPEN & CREAT not in open replay/by_fid.");
+ "OPEN & CREAT not in open replay/by_fid");
GOTO(out, result = -EFAULT);
}
CDEBUG(D_INFO, "No object(1), continue as regular open.\n");
intent = ma->ma_attr_flags & MDS_CLOSE_INTENT;
*ofid = *mdt_object_fid(o);
- CDEBUG(D_INODE, "%s: close file "DFID" with intent: %llx\n",
- mdt_obd_name(info->mti_mdt), PFID(ofid), intent);
+ /* the below message is checked in replay-single.sh test_46 */
+ CDEBUG(D_INODE, "%s: %sclosing file handle "DFID" with intent: %llx\n",
+ mdt_obd_name(info->mti_mdt),
+ ma->ma_valid & MA_FORCE_LOG ? "force " : "", PFID(ofid), intent);
switch (intent) {
case MDS_HSM_RELEASE: {
int rc;
ENTRY;
- DEBUG_REQ(D_INODE, mdt_info_req(info), "Create ("DNAME"->"DFID") "
- "in "DFID,
+ DEBUG_REQ(D_INODE, mdt_info_req(info),
+ "Create ("DNAME"->"DFID") in "DFID,
PNAME(&rr->rr_name), PFID(rr->rr_fid2), PFID(rr->rr_fid1));
if (!fid_is_md_operative(rr->rr_fid1))
int rc, rc2;
ENTRY;
- DEBUG_REQ(D_INODE, req, DFID": FLR file resync\n", PFID(rr->rr_fid1));
+ DEBUG_REQ(D_INODE, req, DFID", FLR file resync", PFID(rr->rr_fid1));
if (info->mti_dlm_req)
ldlm_request_cancel(req, info->mti_dlm_req, 0, LATF_SKIP);
cl_global_fini();
lu_global_fini();
- obd_cleanup_caches();
+ obd_cleanup_caches();
- class_procfs_clean();
+ class_procfs_clean();
- class_handle_cleanup();
+ class_handle_cleanup();
class_del_uuid(NULL); /* Delete all UUIDs. */
- obd_zombie_impexp_stop();
+ obd_zombie_impexp_stop();
#ifdef CONFIG_PROC_FS
memory_leaked = obd_memory_sum();
memory_max = obd_memory_max();
lprocfs_free_stats(&obd_memory);
+ /* the below message is checked in test-framework.sh check_mem_leak() */
CDEBUG((memory_leaked) ? D_ERROR : D_INFO,
"obd_memory max: %llu, leaked: %llu\n",
memory_max, memory_leaked);
CERROR("9_sub: write recs failed at #1: %d\n", rc);
GOTO(out_close, rc);
}
+ /* The below message is checked in sanity.sh test_60a (run-llog.sh) */
CWARN("9_sub: record type %x in log "DFID_NOBRACE"\n",
llog_records.lrh.lrh_type, PFID(&fid));
out_close:
rnb += ioo->ioo_bufcnt - 1;
pa.lpa_extent.end = rnb->rnb_offset + rnb->rnb_len - 1;
- DEBUG_REQ(D_RPCTRACE, req, "%s %s: refresh rw locks: "DFID
- " (%llu->%llu)\n", tgt_name(tsi->tsi_tgt),
- current->comm, PFID(&tsi->tsi_fid), pa.lpa_extent.start,
- pa.lpa_extent.end);
+ DEBUG_REQ(D_RPCTRACE, req,
+ "%s %s: refresh rw locks for "DFID" (%llu->%llu)",
+ tgt_name(tsi->tsi_tgt), current->comm, PFID(&tsi->tsi_fid),
+ pa.lpa_extent.start, pa.lpa_extent.end);
ofd_prolong_extent_locks(tsi, &pa);
- CDEBUG(D_DLMTRACE, "%s: refreshed %u locks timeout for req %p.\n",
+ CDEBUG(D_DLMTRACE, "%s: refreshed %u locks timeout for req %p\n",
tgt_name(tsi->tsi_tgt), pa.lpa_blocks_cnt, req);
if (pa.lpa_blocks_cnt > 0)
&req->rq_import->imp_connection->c_peer;
struct ost_body *body;
u32 client_cksum = 0;
- ENTRY;
- if (rc < 0 && rc != -EDQUOT) {
- DEBUG_REQ(D_INFO, req, "Failed request with rc = %d\n", rc);
- RETURN(rc);
- }
+ ENTRY;
- LASSERTF(req->rq_repmsg != NULL, "rc = %d\n", rc);
- body = req_capsule_server_get(&req->rq_pill, &RMF_OST_BODY);
- if (body == NULL) {
- DEBUG_REQ(D_INFO, req, "Can't unpack body\n");
- RETURN(-EPROTO);
- }
+ if (rc < 0 && rc != -EDQUOT) {
+ DEBUG_REQ(D_INFO, req, "Failed request: rc = %d", rc);
+ RETURN(rc);
+ }
+
+ LASSERTF(req->rq_repmsg != NULL, "rc = %d\n", rc);
+ body = req_capsule_server_get(&req->rq_pill, &RMF_OST_BODY);
+ if (body == NULL) {
+ DEBUG_REQ(D_INFO, req, "cannot unpack body");
+ RETURN(-EPROTO);
+ }
/* set/clear over quota flag for a uid/gid/projid */
if (lustre_msg_get_opc(req->rq_reqmsg) == OST_WRITE &&
unsigned qid[LL_MAXQUOTAS] = {
body->oa.o_uid, body->oa.o_gid,
body->oa.o_projid };
- CDEBUG(D_QUOTA, "setdq for [%u %u %u] with valid %#llx, flags %x\n",
+ CDEBUG(D_QUOTA,
+ "setdq for [%u %u %u] with valid %#llx, flags %x\n",
body->oa.o_uid, body->oa.o_gid, body->oa.o_projid,
body->oa.o_valid, body->oa.o_flags);
osc_quota_setdq(cli, req->rq_xid, qid, body->oa.o_valid,
body->oa.o_flags);
- }
+ }
- osc_update_grant(cli, body);
+ osc_update_grant(cli, body);
- if (rc < 0)
- RETURN(rc);
+ if (rc < 0)
+ RETURN(rc);
- if (aa->aa_oa->o_valid & OBD_MD_FLCKSUM)
- client_cksum = aa->aa_oa->o_cksum; /* save for later */
+ if (aa->aa_oa->o_valid & OBD_MD_FLCKSUM)
+ client_cksum = aa->aa_oa->o_cksum; /* save for later */
- if (lustre_msg_get_opc(req->rq_reqmsg) == OST_WRITE) {
- if (rc > 0) {
- CERROR("Unexpected +ve rc %d\n", rc);
- RETURN(-EPROTO);
- }
+ if (lustre_msg_get_opc(req->rq_reqmsg) == OST_WRITE) {
+ if (rc > 0) {
+ CERROR("%s: unexpected positive size %d\n",
+ obd_name, rc);
+ RETURN(-EPROTO);
+ }
if (req->rq_bulk != NULL &&
sptlrpc_cli_unwrap_bulk_write(req, req->rq_bulk))
- RETURN(-EAGAIN);
+ RETURN(-EAGAIN);
- if ((aa->aa_oa->o_valid & OBD_MD_FLCKSUM) && client_cksum &&
- check_write_checksum(&body->oa, peer, client_cksum,
+ if ((aa->aa_oa->o_valid & OBD_MD_FLCKSUM) && client_cksum &&
+ check_write_checksum(&body->oa, peer, client_cksum,
body->oa.o_cksum, aa))
- RETURN(-EAGAIN);
+ RETURN(-EAGAIN);
- rc = check_write_rcs(req, aa->aa_requested_nob,aa->aa_nio_count,
- aa->aa_page_count, aa->aa_ppga);
- GOTO(out, rc);
- }
+ rc = check_write_rcs(req, aa->aa_requested_nob,
+ aa->aa_nio_count, aa->aa_page_count,
+ aa->aa_ppga);
+ GOTO(out, rc);
+ }
- /* The rest of this function executes only for OST_READs */
+ /* The rest of this function executes only for OST_READs */
if (req->rq_bulk == NULL) {
rc = req_capsule_get_size(&req->rq_pill, &RMF_SHORT_IO,
/* if unwrap_bulk failed, return -EAGAIN to retry */
rc = sptlrpc_cli_unwrap_bulk_read(req, req->rq_bulk, rc);
}
- if (rc < 0)
- GOTO(out, rc = -EAGAIN);
+ if (rc < 0)
+ GOTO(out, rc = -EAGAIN);
- if (rc > aa->aa_requested_nob) {
- CERROR("Unexpected rc %d (%d requested)\n", rc,
- aa->aa_requested_nob);
- RETURN(-EPROTO);
- }
+ if (rc > aa->aa_requested_nob) {
+ CERROR("%s: unexpected size %d, requested %d\n", obd_name,
+ rc, aa->aa_requested_nob);
+ RETURN(-EPROTO);
+ }
if (req->rq_bulk != NULL && rc != req->rq_bulk->bd_nob_transferred) {
- CERROR ("Unexpected rc %d (%d transferred)\n",
- rc, req->rq_bulk->bd_nob_transferred);
- return (-EPROTO);
- }
+ CERROR("%s: unexpected size %d, transferred %d\n", obd_name,
+ rc, req->rq_bulk->bd_nob_transferred);
+ RETURN(-EPROTO);
+ }
if (req->rq_bulk == NULL) {
/* short io */
CDEBUG(D_PAGE, "checksum %x confirmed\n", client_cksum);
rc = 0;
}
- } else if (unlikely(client_cksum)) {
- static int cksum_missed;
-
- cksum_missed++;
- if ((cksum_missed & (-cksum_missed)) == cksum_missed)
- CERROR("Checksum %u requested from %s but not sent\n",
- cksum_missed, libcfs_nid2str(peer->nid));
- } else {
- rc = 0;
- }
+ } else if (unlikely(client_cksum)) {
+ static int cksum_missed;
+
+ cksum_missed++;
+ if ((cksum_missed & (-cksum_missed)) == cksum_missed)
+ CERROR("%s: checksum %u requested from %s but not sent\n",
+ obd_name, cksum_missed,
+ libcfs_nid2str(peer->nid));
+ } else {
+ rc = 0;
+ }
out:
if (rc >= 0)
lustre_get_wire_obdo(&req->rq_import->imp_connect_data,
aa->aa_oa, &body->oa);
- RETURN(rc);
+ RETURN(rc);
}
static int osc_brw_redo_request(struct ptlrpc_request *request,
struct osc_brw_async_args *aa, int rc)
{
- struct ptlrpc_request *new_req;
- struct osc_brw_async_args *new_aa;
- struct osc_async_page *oap;
- ENTRY;
+ struct ptlrpc_request *new_req;
+ struct osc_brw_async_args *new_aa;
+ struct osc_async_page *oap;
+ ENTRY;
+ /* The below message is checked in replay-ost-single.sh test_8ae*/
DEBUG_REQ(rc == -EINPROGRESS ? D_RPCTRACE : D_ERROR, request,
"redo for recoverable error %d", rc);
}
spin_unlock(&cli->cl_loi_list_lock);
- DEBUG_REQ(D_INODE, req, "%d pages, aa %p. now %ur/%uw in flight",
+ DEBUG_REQ(D_INODE, req, "%d pages, aa %p, now %ur/%uw in flight",
page_count, aa, cli->cl_r_in_flight,
cli->cl_w_in_flight);
OBD_FAIL_TIMEOUT(OBD_FAIL_OSC_DELAY_IO, cfs_fail_val);
}
if (fid != NULL)
- CWARN("%s: directory (inode: %lu, FID: "DFID") %s "
- "maximum entry limit\n",
+ /* below message is checked in sanity.sh test_129 */
+ CWARN("%s: directory (inode: %lu, FID: "DFID") %s maximum entry limit\n",
osd_name(osd), parent->i_ino, PFID(fid),
rc == -ENOSPC ? "has reached" : "is approaching");
else
- CWARN("%s: directory (inode: %lu, FID: unknown) %s "
- "maximum entry limit\n",
+ /* below message is checked in sanity.sh test_129 */
+ CWARN("%s: directory (inode: %lu, FID: unknown) %s maximum entry limit\n",
osd_name(osd), parent->i_ino,
rc == -ENOSPC ? "has reached" : "is approaching");
OUT_UPDATE_REPLY_SIZE);
if (reply->ourp_magic != UPDATE_REPLY_MAGIC) {
DEBUG_REQ(D_ERROR, req,
- "%s: Wrong version %x expected %x "DFID": rc = %d\n",
+ "%s: Wrong version %x expected %x "DFID": rc = %d",
dname, reply->ourp_magic, UPDATE_REPLY_MAGIC,
PFID(lu_object_fid(&dt->do_lu)), -EPROTO);
struct osp_device *d = req->rq_cb_data;
if (jra->jra_magic != OSP_JOB_MAGIC) {
- DEBUG_REQ(D_ERROR, req, "bad magic %u\n", jra->jra_magic);
+ DEBUG_REQ(D_ERROR, req, "bad magic %u", jra->jra_magic);
LBUG();
}
LASSERT(d);
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;
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,
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);
* 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) {
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;
}
*/
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);
}
/**
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);
}
*/
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);
}
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);
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);
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);
}
/** 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);
/* 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)
goto out_wake;
}
- if ((ev->offset == 0) &&
- ((lustre_msghdr_get_flags(req->rq_reqmsg) & MSGHDR_AT_SUPPORT))) {
- /* Early reply */
- DEBUG_REQ(D_ADAPTTO, req,
- "Early reply received: mlen=%u offset=%d replen=%d "
- "replied=%d unlinked=%d", ev->mlength, ev->offset,
- req->rq_replen, req->rq_replied, ev->unlinked);
-
- req->rq_early_count++; /* number received, client side */
+ if ((ev->offset == 0) &&
+ ((lustre_msghdr_get_flags(req->rq_reqmsg) & MSGHDR_AT_SUPPORT))) {
+ /* Early reply */
+ DEBUG_REQ(D_ADAPTTO, req,
+ "Early reply received, mlen=%u offset=%d replen=%d replied=%d unlinked=%d",
+ ev->mlength, ev->offset,
+ req->rq_replen, req->rq_replied, ev->unlinked);
+
+ req->rq_early_count++; /* number received, client side */
/* already got the real reply or buffers are already unlinked */
if (req->rq_replied ||
imp->imp_conn_current = imp_conn;
}
+ /* The below message is checked in conf-sanity.sh test_35[ab] */
CDEBUG(D_HA, "%s: import %p using connection %s/%s\n",
imp->imp_obd->obd_name, imp, imp_conn->oic_uuid.uuid,
libcfs_nid2str(imp_conn->oic_conn->c_peer.nid));
req = list_entry(tmp, struct ptlrpc_request, rq_replay_list);
*transno = req->rq_transno;
if (req->rq_transno == 0) {
- DEBUG_REQ(D_ERROR, req, "zero transno in committed_list");
+ DEBUG_REQ(D_ERROR, req,
+ "zero transno in committed_list");
LBUG();
}
return 1;
!imp->imp_invalid) {
obd_import_event(imp->imp_obd, imp, IMP_EVENT_INVALIDATE);
+ /* The below message is checked in recovery-small.sh test_106 */
DEBUG_REQ(D_HA, request, "%s: lwp recover",
imp->imp_obd->obd_name);
imp->imp_remote_handle =
*lustre_msg_get_handle(request->rq_repmsg);
import_set_state(imp, LUSTRE_IMP_RECOVER);
} else {
- DEBUG_REQ(D_HA, request, "%s: evicting (reconnect/recover flags"
- " not set: %x)", imp->imp_obd->obd_name, msg_flags);
- imp->imp_remote_handle =
- *lustre_msg_get_handle(request->rq_repmsg);
+ DEBUG_REQ(D_HA, request,
+ "%s: evicting (reconnect/recover flags not set: %x)",
+ imp->imp_obd->obd_name, msg_flags);
+ imp->imp_remote_handle =
+ *lustre_msg_get_handle(request->rq_repmsg);
import_set_state(imp, LUSTRE_IMP_EVICTED);
- }
+ }
- /* Sanity checks for a reconnected import. */
- if (!(imp->imp_replayable) != !(msg_flags & MSG_CONNECT_REPLAYABLE)) {
- CERROR("imp_replayable flag does not match server "
- "after reconnect. We should LBUG right here.\n");
- }
+ /* Sanity checks for a reconnected import. */
+ if (!(imp->imp_replayable) != !(msg_flags & MSG_CONNECT_REPLAYABLE))
+ CERROR("imp_replayable flag does not match server after reconnect. We should LBUG right here.\n");
- if (lustre_msg_get_last_committed(request->rq_repmsg) > 0 &&
- lustre_msg_get_last_committed(request->rq_repmsg) <
- aa->pcaa_peer_committed) {
- CERROR("%s went back in time (transno %lld"
- " was previously committed, server now claims %lld"
- ")! See https://bugzilla.lustre.org/show_bug.cgi?"
- "id=9646\n",
+ if (lustre_msg_get_last_committed(request->rq_repmsg) > 0 &&
+ lustre_msg_get_last_committed(request->rq_repmsg) <
+ aa->pcaa_peer_committed) {
+ static bool printed;
+
+ /* The below message is checked in recovery-small.sh test_54 */
+ CERROR("%s: went back in time (transno %lld was previously committed, server now claims %lld)!\n",
obd2cli_tgt(imp->imp_obd), aa->pcaa_peer_committed,
lustre_msg_get_last_committed(request->rq_repmsg));
+ if (!printed) {
+ CERROR("For further information, see http://doc.lustre.org/lustre_manual.xhtml#went_back_in_time\n");
+ printed = true;
+ }
}
finish:
struct obd_import *imp = req->rq_import;
int connect = 0;
- DEBUG_REQ(D_HA, req, "inflight=%d, refcount=%d: rc = %d ",
+ DEBUG_REQ(D_HA, req, "inflight=%d, refcount=%d: rc = %d",
atomic_read(&imp->imp_inflight),
atomic_read(&imp->imp_refcount), rc);
*/
int req_capsule_server_pack(struct req_capsule *pill)
{
- const struct req_format *fmt;
- int count;
- int rc;
-
- LASSERT(pill->rc_loc == RCL_SERVER);
- fmt = pill->rc_fmt;
- LASSERT(fmt != NULL);
+ const struct req_format *fmt;
+ int count;
+ int rc;
- count = req_capsule_filled_sizes(pill, RCL_SERVER);
- rc = lustre_pack_reply(pill->rc_req, count,
- pill->rc_area[RCL_SERVER], NULL);
- if (rc != 0) {
- DEBUG_REQ(D_ERROR, pill->rc_req,
- "Cannot pack %d fields in format `%s': ",
- count, fmt->rf_name);
- }
- return rc;
+ LASSERT(pill->rc_loc == RCL_SERVER);
+ fmt = pill->rc_fmt;
+ LASSERT(fmt != NULL);
+
+ count = req_capsule_filled_sizes(pill, RCL_SERVER);
+ rc = lustre_pack_reply(pill->rc_req, count,
+ pill->rc_area[RCL_SERVER], NULL);
+ if (rc != 0) {
+ DEBUG_REQ(D_ERROR, pill->rc_req,
+ "Cannot pack %d fields in format '%s'",
+ count, fmt->rf_name);
+ }
+ return rc;
}
EXPORT_SYMBOL(req_capsule_server_pack);
if (value == NULL) {
DEBUG_REQ(D_ERROR, pill->rc_req,
- "Wrong buffer for field `%s' (%u of %u) "
- "in format `%s': %u vs. %u (%s)\n",
+ "Wrong buffer for field '%s' (%u of %u) in format '%s', %u vs. %u (%s)",
field->rmf_name, offset, lustre_msg_bufcount(msg),
fmt->rf_name, lustre_msg_buflen(msg, offset), len,
rcl_names[loc]);
*/
void __req_capsule_dump(struct req_capsule *pill, enum req_location loc)
{
- const struct req_format *fmt;
- const struct req_msg_field *field;
- __u32 len;
- size_t i;
-
- fmt = pill->rc_fmt;
+ const struct req_format *fmt;
+ const struct req_msg_field *field;
+ __u32 len;
+ size_t i;
- DEBUG_REQ(D_RPCTRACE, pill->rc_req, "BEGIN REQ CAPSULE DUMP\n");
- for (i = 0; i < fmt->rf_fields[loc].nr; ++i) {
- field = FMT_FIELD(fmt, loc, i);
- if (field->rmf_dumper == NULL) {
- /*
- * FIXME Add a default hex dumper for fields that don't
- * have a specific dumper
- */
- len = req_capsule_get_size(pill, field, loc);
+ fmt = pill->rc_fmt;
+
+ DEBUG_REQ(D_RPCTRACE, pill->rc_req, "BEGIN REQ CAPSULE DUMP");
+ for (i = 0; i < fmt->rf_fields[loc].nr; ++i) {
+ field = FMT_FIELD(fmt, loc, i);
+ if (field->rmf_dumper == NULL) {
+ /*
+ * FIXME Add a default hex dumper for fields that don't
+ * have a specific dumper
+ */
+ len = req_capsule_get_size(pill, field, loc);
CDEBUG(D_RPCTRACE, "Field %s has no dumper function;"
"field size is %u\n", field->rmf_name, len);
- } else {
- /* It's the dumping side-effect that we're interested in */
- (void) __req_capsule_get(pill, field, loc, NULL, 1);
- }
- }
- CDEBUG(D_RPCTRACE, "END REQ CAPSULE DUMP\n");
+ } else {
+ /* It's dumping side-effect that we're interested in */
+ (void) __req_capsule_get(pill, field, loc, NULL, 1);
+ }
+ }
+ CDEBUG(D_RPCTRACE, "END REQ CAPSULE DUMP\n");
}
/**
wait_queue_head_t *wq = (req->rq_set != NULL) ?
&req->rq_set->set_waitq :
&req->rq_reply_waitq;
- /* Network access will complete in finite time but the HUGE
- * timeout lets us CWARN for visibility of sluggish NALs */
- lwi = LWI_TIMEOUT_INTERVAL(cfs_time_seconds(LONG_UNLINK),
- cfs_time_seconds(1), NULL, NULL);
- rc = l_wait_event(*wq, !ptlrpc_client_bulk_active(req), &lwi);
- if (rc == 0) {
- ptlrpc_rqphase_move(req, req->rq_next_phase);
- RETURN(1);
- }
+ /*
+ * Network access will complete in finite time but the HUGE
+ * timeout lets us CWARN for visibility of sluggish NALs.
+ */
+ lwi = LWI_TIMEOUT_INTERVAL(cfs_time_seconds(LONG_UNLINK),
+ cfs_time_seconds(1), NULL, NULL);
+ rc = l_wait_event(*wq, !ptlrpc_client_bulk_active(req), &lwi);
+ if (rc == 0) {
+ ptlrpc_rqphase_move(req, req->rq_next_phase);
+ RETURN(1);
+ }
- LASSERT(rc == -ETIMEDOUT);
- DEBUG_REQ(D_WARNING, req, "Unexpectedly long timeout: desc %p",
- desc);
- }
- RETURN(0);
+ LASSERT(rc == -ETIMEDOUT);
+ DEBUG_REQ(D_WARNING, req, "Unexpectedly long timeout: desc %p",
+ desc);
+ }
+ RETURN(0);
}
static void ptlrpc_at_set_reply(struct ptlrpc_request *req, int flags)
spin_unlock(&imp->imp_lock);
lustre_msg_set_last_xid(request->rq_reqmsg, min_xid);
- DEBUG_REQ(D_RPCTRACE, request, "Allocating new xid for "
- "resend on EINPROGRESS");
+ DEBUG_REQ(D_RPCTRACE, request,
+ "Allocating new XID for resend on EINPROGRESS");
}
if (request->rq_bulk != NULL) {
if (list_empty(&request->rq_unreplied_list) ||
request->rq_xid <= imp->imp_known_replied_xid) {
- DEBUG_REQ(D_ERROR, request, "xid: %llu, replied: %llu, "
- "list_empty:%d\n", request->rq_xid,
- imp->imp_known_replied_xid,
+ DEBUG_REQ(D_ERROR, request,
+ "xid=%llu, replied=%llu, list_empty=%d",
+ request->rq_xid, imp->imp_known_replied_xid,
list_empty(&request->rq_unreplied_list));
LBUG();
}
ptlrpc_pinger_sending_on_import(imp);
- DEBUG_REQ(D_INFO, request, "send flg=%x",
+ DEBUG_REQ(D_INFO, request, "send flags=%x",
lustre_msg_get_flags(request->rq_reqmsg));
rc = ptl_send_buf(&request->rq_req_md_h,
request->rq_reqbuf, request->rq_reqdata_len,
pc = ptlrpcd_select_pc(req);
- DEBUG_REQ(D_INFO, req, "add req [%p] to pc [%s:%d]",
+ DEBUG_REQ(D_INFO, req, "add req [%p] to pc [%s+%d]",
req, pc->pc_name, pc->pc_index);
ptlrpc_set_add_new_req(pc, req);
* exception is that resend replay could have been removed from the
* unreplied list. */
if (req != NULL && list_empty(&req->rq_unreplied_list)) {
- DEBUG_REQ(D_HA, req, "resend_replay: %d, last_transno: %llu\n",
+ DEBUG_REQ(D_HA, req, "resend_replay=%d, last_transno=%llu",
imp->imp_resend_replay, last_transno);
ptlrpc_add_unreplied(req);
imp->imp_known_replied_xid = ptlrpc_known_replied_xid(imp);
rc = do_cli_unwrap_reply(early_req);
if (rc) {
DEBUG_REQ(D_ADAPTTO, early_req,
- "error %d unwrap early reply", rc);
+ "unwrap early reply: rc = %d", rc);
GOTO(err_ctx, rc);
}
switch (req->rq_sp_from) {
case LUSTRE_SP_CLI:
if (req->rq_auth_usr_mdt || req->rq_auth_usr_ost) {
+ /* The below message is checked in sanity-sec test_33 */
DEBUG_REQ(D_ERROR, req, "faked source CLI");
svc_rc = SECSVC_DROP;
}
break;
case LUSTRE_SP_MDT:
if (!req->rq_auth_usr_mdt) {
+ /* The below message is checked in sanity-sec test_33 */
DEBUG_REQ(D_ERROR, req, "faked source MDT");
svc_rc = SECSVC_DROP;
}
break;
case LUSTRE_SP_OST:
if (!req->rq_auth_usr_ost) {
+ /* The below message is checked in sanity-sec test_33 */
DEBUG_REQ(D_ERROR, req, "faked source OST");
svc_rc = SECSVC_DROP;
}
case LUSTRE_SP_MGC:
if (!req->rq_auth_usr_root && !req->rq_auth_usr_mdt &&
!req->rq_auth_usr_ost) {
+ /* The below message is checked in sanity-sec test_33 */
DEBUG_REQ(D_ERROR, req, "faked source MGC/MGS");
svc_rc = SECSVC_DROP;
}
RETURN(0);
if (olddl < 0) {
+ /* below message is checked in replay-ost-single.sh test_9 */
DEBUG_REQ(D_WARNING, req,
"Already past deadline (%+llds), not sending early reply. Consider increasing at_early_margin (%d)?",
(s64)olddl, at_early_margin);
* we may be past adaptive_max
*/
if (req->rq_deadline >= newdl) {
- DEBUG_REQ(D_WARNING, req, "Couldn't add any time (%lld/%lld), not sending early reply\n",
+ DEBUG_REQ(D_WARNING, req,
+ "Could not add any time (%lld/%lld), not sending early reply",
(s64)olddl, (s64)(newdl - ktime_get_real_seconds()));
RETURN(-ETIMEDOUT);
}
GOTO(out, rc = -ETIMEDOUT);
LASSERT(atomic_read(&req->rq_refcount));
- /** if it is last refcount then early reply isn't needed */
+ /* if it is last refcount then early reply isn't needed */
if (atomic_read(&req->rq_refcount) == 1) {
DEBUG_REQ(D_ADAPTTO, reqcopy,
- "Normal reply already sent out, abort sending early reply\n");
+ "Normal reply already sent, abort early reply");
GOTO(out, rc = -EINVAL);
}
req->rq_deadline = newdl;
req->rq_early_count++; /* number sent, server side */
} else {
- DEBUG_REQ(D_ERROR, req, "Early reply send failed %d", rc);
+ DEBUG_REQ(D_ERROR, req, "Early reply send failed: rc = %d", rc);
}
/*
rc = sptlrpc_target_export_check(req->rq_export, req);
if (rc)
DEBUG_REQ(D_ERROR, req,
- "DROPPING req with illegal security flavor,");
+ "DROPPING req with illegal security flavor");
}
if (rc)
* The deadline is increased if we send an early reply.
*/
if (ktime_get_real_seconds() > request->rq_deadline) {
- DEBUG_REQ(D_ERROR, request, "Dropping timed-out request from %s: deadline %lld:%llds ago\n",
+ DEBUG_REQ(D_ERROR, request,
+ "Dropping timed-out request from %s: deadline %lld/%llds ago",
libcfs_id2str(request->rq_peer),
request->rq_deadline -
request->rq_arrival_time.tv_sec,
put_conn:
if (unlikely(ktime_get_real_seconds() > request->rq_deadline)) {
DEBUG_REQ(D_WARNING, request,
- "Request took longer than estimated (%lld:%llds); "
- "client may timeout.",
+ "Request took longer than estimated (%lld/%llds); client may timeout",
request->rq_deadline -
request->rq_arrival_time.tv_sec,
ktime_get_real_seconds() - request->rq_deadline);
u32 ms_frac = do_div(ms_lapse, MSEC_PER_SEC);
if (!__ratelimit(&watchdog_limit)) {
+ /* below message is checked in sanity-quota.sh test_6,18 */
LCONSOLE_WARN("%s: service thread pid %u was inactive for %llu.%03u seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:\n",
thread->t_task->comm, thread->t_task->pid,
ms_lapse, ms_frac);
libcfs_debug_dumpstack(thread->t_task);
} else {
+ /* below message is checked in sanity-quota.sh test_6,18 */
LCONSOLE_WARN("%s: service thread pid %u was inactive for %llu.%03u seconds. Watchdog stack traces are limited to 3 per %u seconds, skipping this one.\n",
thread->t_task->comm, thread->t_task->pid,
ms_lapse, ms_frac, libcfs_watchdog_ratelimit);
tot_granted - tgd->tgd_tot_pending) ?
D_ERROR : D_CACHE;
- CDEBUG_LIMIT(mask, "%s: cli %s/%p left %llu < tot_grant "
- "%llu unstable %llu pending %llu "
- "dirty %llu\n",
+ /* the below message is checked in sanityn.sh test_15 */
+ CDEBUG_LIMIT(mask,
+ "%s: cli %s/%p left=%llu < tot_grant=%llu unstable=%llu pending=%llu dirty=%llu\n",
obd->obd_name, exp->exp_client_uuid.uuid, exp,
left, tot_granted, unstable,
tgd->tgd_tot_pending,
/* Align left on block size */
left &= ~((1ULL << tgd->tgd_blockbits) - 1);
- CDEBUG(D_CACHE, "%s: cli %s/%p avail %llu left %llu unstable "
- "%llu tot_grant %llu pending %llu\n", obd->obd_name,
- exp->exp_client_uuid.uuid, exp, avail, left, unstable,
- tot_granted, tgd->tgd_tot_pending);
+ CDEBUG(D_CACHE,
+ "%s: cli %s/%p avail=%llu left=%llu unstable=%llu tot_grant=%llu pending=%llu\n",
+ obd->obd_name, exp->exp_client_uuid.uuid, exp, avail, left,
+ unstable, tot_granted, tgd->tgd_tot_pending);
RETURN(left);
}
rc = h->th_act(tsi);
if (!is_serious(rc) &&
!req->rq_no_reply && req->rq_reply_state == NULL) {
- DEBUG_REQ(D_ERROR, req, "%s \"handler\" %s did not "
- "pack reply and returned 0 error\n",
+ DEBUG_REQ(D_ERROR, req,
+ "%s: %s handler did not pack reply but returned no error",
tgt_name(tsi->tsi_tgt), h->th_name);
LBUG();
}
if (req_can_reconstruct(req, NULL)) {
if (!(lustre_msg_get_flags(req->rq_reqmsg) &
(MSG_RESENT | MSG_REPLAY))) {
- DEBUG_REQ(D_WARNING, req, "rq_xid %llu matches "
- "saved xid, expected REPLAY or RESENT flag "
- "(%x)", req->rq_xid,
+ DEBUG_REQ(D_WARNING, req,
+ "rq_xid=%llu matches saved XID, expected REPLAY or RESENT flag (%x)",
+ req->rq_xid,
lustre_msg_get_flags(req->rq_reqmsg));
req->rq_status = -ENOTCONN;
RETURN(-ENOTCONN);
tgt = class_exp2tgt(req->rq_export);
if (unlikely(tgt == NULL)) {
- DEBUG_REQ(D_ERROR, req, "%s: No target for connected export\n",
+ DEBUG_REQ(D_ERROR, req, "%s: no target for connected export",
class_exp2obd(req->rq_export)->obd_name);
RETURN(ERR_PTR(-EINVAL));
}
if (req->rq_xid == 0 ||
(req->rq_xid <= req->rq_export->exp_last_xid)) {
- DEBUG_REQ(D_ERROR, req, "Unexpected xid %llx vs. "
- "last_xid %llx\n", req->rq_xid,
- req->rq_export->exp_last_xid);
+ DEBUG_REQ(D_WARNING, req,
+ "unexpected rq_xid=%llx != exp_last_xid=%llx",
+ req->rq_xid, req->rq_export->exp_last_xid);
/* Some request is allowed to be sent during replay,
* such as OUT update requests, FLD requests, so it
* is possible that replay requests has smaller XID
tsi->tsi_jobid = NULL;
if (tgt == NULL) {
- DEBUG_REQ(D_ERROR, req, "%s: No target for connected export\n",
+ DEBUG_REQ(D_ERROR, req, "%s: No target for connected export",
class_exp2obd(req->rq_export)->obd_name);
req->rq_status = -EINVAL;
rc = ptlrpc_error(req);
rc = lustre_msg_check_version(msg, h->th_version);
if (unlikely(rc)) {
- DEBUG_REQ(D_ERROR, req, "%s: drop mal-formed request, version"
- " %08x, expecting %08x\n", tgt_name(tgt),
- lustre_msg_get_version(msg), h->th_version);
+ DEBUG_REQ(D_ERROR, req,
+ "%s: drop malformed request version=%08x expect=%08x",
+ tgt_name(tgt), lustre_msg_get_version(msg),
+ h->th_version);
req->rq_status = -EINVAL;
rc = ptlrpc_error(req);
GOTO(out, rc);
pr_err(PREFIX " inode numbers are different: %llu %llu\n",
run_id, stbuf1.ino, stbuf2.ino);
else
+ /* below message is checked in sanity.sh test_129 */
pr_err(PREFIX " inode numbers are identical: %llu\n",
run_id, stbuf1.ino);
run_test 53 "touch: drop rep"
test_54() {
- zconf_mount `hostname` $MOUNT2
- touch $DIR/$tfile
- touch $DIR2/$tfile.1
- sleep 10
- cat $DIR2/$tfile.missing # save transno = 0, rc != 0 into last_rcvd
- fail $SINGLEMDS
- umount $MOUNT2
- ERROR=`dmesg | egrep "(test 54|went back in time)" | tail -n1 | grep "went back in time"`
- [ x"$ERROR" == x ] || error "back in time occured"
+ zconf_mount $(hostname) $MOUNT2
+ touch $DIR/$tfile
+ touch $DIR2/$tfile.1
+ sleep 10
+ cat $DIR2/$tfile.missing # save transno = 0, rc != 0 into last_rcvd
+ fail $SINGLEMDS
+ umount $MOUNT2
+ ERROR=$(dmesg | egrep "(test 54|went back in time)" | tail -n1 |
+ grep "went back in time")
+ [ x"$ERROR" == x ] || error "back in time occured"
}
run_test 54 "back in time"
# lightweight goes through LUSTRE_IMP_RECOVER during failover
touch -c $DIR2/$tfile || true
$LCTL dk $TMP/lustre-log-$TESTNAME.log
- recovered=`awk '/MDT0000-mdc-[0-9a-f]*: lwp recover/ {
- print;
- }' $TMP/lustre-log-$TESTNAME.log`
+ recovered=$(awk '/MDT0000-mdc-[0-9a-f]*. lwp recover/ { print }' \
+ $TMP/lustre-log-$TESTNAME.log)
[ -z "$recovered" ] && error "lightweight client was not recovered"
# and all operations performed by lightweight client should be
fail ost1
do_facet ost1 $LCTL set_param fail_loc=0
do_facet ost1 "dmesg | tail -n 100" |
- sed -n '/no req deadline/,$ p' | grep -q 'Already past' &&
+ sed -n '/no req deadline/,$ p' | grep -qi 'Already past' &&
return 1
return 0
}
checkstat $DIR/$tfile
facet_failover $SINGLEMDS
cancel_lru_locks mdc
- if dmesg | grep "unknown lock cookie"; then
+ if $LCTL dk | grep "stale lock .*cookie"; then
error "cancel after replay failed"
fi
}
do_facet $SINGLEMDS dmesg -c >/dev/null
fail_abort $SINGLEMDS
kill -USR1 $pid || error "multiop $pid not running"
- do_facet $SINGLEMDS dmesg | grep "error .* unlinking .* from PENDING" &&
+ do_facet $SINGLEMDS dmesg | grep "error unlinking orphan" &&
error "error unlinking files"
wait $pid || error "multiop $pid failed"
sync
run_test 45 "Handle failed close"
test_46() {
- dmesg -c >/dev/null
drop_reply "touch $DIR/$tfile"
fail $SINGLEMDS
# ironically, the previous test, 45, will cause a real forced close,
# so just look for one for this test
- dmesg | grep -i "force closing client file handle for $tfile" &&
+ local FID=$($LFS path2fid $tfile)
+ $LCTL dk | grep -i "force closing file handle $FID" &&
error "found force closing in dmesg"
return 0
}
createmany -o $DIR/$tfile 10 > /dev/null
unlinkmany $DIR/$tfile 10 > /dev/null
# check for log message
- $LCTL dk | grep "Early reply #" || error "No early reply"
+ $LCTL dk | grep -i "Early reply #" || error "No early reply"
debugrestore
# client should show REQ_DELAY estimates
lctl get_param -n mdc.${FSNAME}-MDT0000-mdc-*.timeouts | grep portal
do_facet ost1 $LCTL set_param fail_loc=0
# check for log message
- $LCTL dk | grep "Early reply #" || error "No early reply"
+ $LCTL dk | grep -i "Early reply #" || error "No early reply"
debugrestore
# client should show REQ_DELAY estimates
lctl get_param -n osc.${FSNAME}-OST0000-osc-*.timeouts | grep portal
do_facet $SINGLEMDS $LCTL set_param fail_loc=0
wait $TOUCHPID || error "touch should have succeeded"
- $LCTL dk | grep "Early reply #" || error "No early reply"
+ $LCTL dk | grep -i "Early reply #" || error "No early reply"
debugrestore
do_facet $SINGLEMDS "echo $ATOLDBASE >> $ATHISTORY" || true
do_facet $SINGLEMDS $LCTL set_param fail_loc=0
wait $TOUCHPID || error "touch should have succeeded"
- $LCTL dk | grep "Early reply #" || error "No early reply"
+ $LCTL dk | grep -i "Early reply #" || error "No early reply"
debugrestore
do_facet $SINGLEMDS "echo $ATOLDBASE >> $ATHISTORY" || true
# no watchdog is triggered
do_facet ost1 dmesg > $TMP/lustre-log-${TESTNAME}.log
- watchdog=$(awk '/Service thread pid/ && /was inactive/ \
+ watchdog=$(awk '/[Ss]ervice thread pid/ && /was inactive/ \
{ print; }' $TMP/lustre-log-${TESTNAME}.log)
[ -z "$watchdog" ] || error "$watchdog"
# check if watchdog is triggered
do_facet ost1 dmesg > $TMP/lustre-log-${TESTNAME}.log
- local watchdog=$(awk '/Service thread pid/ && /was inactive/ \
+ local watchdog=$(awk '/[Ss]ervice thread pid/ && /was inactive/ \
{ print; }' $TMP/lustre-log-${TESTNAME}.log)
[ -z "$watchdog" ] || error "$watchdog"
rm -f $TMP/lustre-log-${TESTNAME}.log
local pass=true
#get fid and record list
- fid_list=($(awk '/9_sub.*record/ { print $NF }' /$TMP/$tfile |
+ fid_list=($(awk '/9_sub.*record/ { print $NF }' $TMP/$tfile |
tail -n 4))
- rec_list=($(awk '/9_sub.*record/ { print $((NF-3)) }' /$TMP/$tfile |
+ rec_list=($(awk '/9_sub.*record/ { print $((NF-3)) }' $TMP/$tfile |
tail -n 4))
#remount mgs as ldiskfs or zfs type
stop mgs || error "stop mgs failed"
echo "PATH=$PATH"
sh oos2.sh $MOUNT1 $MOUNT2
wait_delete_completed
- grant_error=`dmesg | grep "> available"`
+ grant_error=$(dmesg | grep "< tot_grant")
[ -z "$grant_error" ] || error "$grant_error"
}
run_test 15 "test out-of-space with multiple writers ==========="
git://git.whamcloud.com / fs / lustre-release.git / commitdiff