Skip to content

Commit

Permalink
librbd: improve journaling debug log messages
Browse files Browse the repository at this point in the history 
Signed-off-by: Jason Dillaman <[email protected]>
  • Loading branch information
Jason Dillaman committed Jul 19, 2016
1 parent 57cd75e commit 270cb74
Show file tree
Hide file tree
Showing 2 changed files with 123 additions and 82 deletions.
124 changes: 82 additions & 42 deletions src/librbd/Journal.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,8 @@ struct C_DecodeTag : public Context {

int process(int r) {
if (r < 0) {
lderr(cct) << "failed to allocate tag: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to allocate tag: " << cpp_strerror(r) << dendl;
return r;
}

Expand All @@ -60,11 +61,13 @@ struct C_DecodeTag : public Context {
bufferlist::iterator data_it = tag.data.begin();
r = decode(&data_it, tag_data);
if (r < 0) {
lderr(cct) << "failed to decode allocated tag" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode allocated tag" << dendl;
return r;
}

ldout(cct, 20) << "allocated journal tag: "
ldout(cct, 20) << this << " " << __func__ << ": "
<< "allocated journal tag: "
<< "tid=" << tag.tid << ", "
<< "data=" << *tag_data << dendl;
return 0;
Expand Down Expand Up @@ -106,13 +109,15 @@ struct C_DecodeTags : public Context {

int process(int r) {
if (r < 0) {
lderr(cct) << "failed to retrieve journal tags: " << cpp_strerror(r)
lderr(cct) << this << " " << __func__ << ": "
<< "failed to retrieve journal tags: " << cpp_strerror(r)
<< dendl;
return r;
}

if (tags.empty()) {
lderr(cct) << "no journal tags retrieved" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "no journal tags retrieved" << dendl;
return -ENOENT;
}

Expand All @@ -122,11 +127,13 @@ struct C_DecodeTags : public Context {
bufferlist::iterator data_it = tags.back().data.begin();
r = C_DecodeTag::decode(&data_it, tag_data);
if (r < 0) {
lderr(cct) << "failed to decode journal tag" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode journal tag" << dendl;
return r;
}

ldout(cct, 20) << "most recent journal tag: "
ldout(cct, 20) << this << " " << __func__ << ": "
<< "most recent journal tag: "
<< "tid=" << *tag_tid << ", "
<< "data=" << *tag_data << dendl;
return 0;
Expand Down Expand Up @@ -232,7 +239,8 @@ int allocate_journaler_tag(CephContext *cct, J *journaler,

int r = allocate_tag_ctx.wait();
if (r < 0) {
lderr(cct) << "failed to allocate tag: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to allocate tag: " << cpp_strerror(r) << dendl;
return r;
}
return 0;
Expand Down Expand Up @@ -357,7 +365,8 @@ int Journal<I>::create(librados::IoCtx &io_ctx, const std::string &image_id,
IoCtx data_io_ctx;
int r = rados.ioctx_create(object_pool.c_str(), data_io_ctx);
if (r != 0) {
lderr(cct) << "failed to create journal: "
lderr(cct) << __func__ << ": "
<< "failed to create journal: "
<< "error opening journal objects pool '" << object_pool
<< "': " << cpp_strerror(r) << dendl;
return r;
Expand All @@ -370,7 +379,8 @@ int Journal<I>::create(librados::IoCtx &io_ctx, const std::string &image_id,

int r = journaler.create(order, splay_width, pool_id);
if (r < 0) {
lderr(cct) << "failed to create journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to create journal: " << cpp_strerror(r) << dendl;
return r;
}

Expand All @@ -391,7 +401,8 @@ int Journal<I>::create(librados::IoCtx &io_ctx, const std::string &image_id,

r = journaler.register_client(client_data);
if (r < 0) {
lderr(cct) << "failed to register client: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to register client: " << cpp_strerror(r) << dendl;
return r;
}
return 0;
Expand All @@ -408,7 +419,8 @@ int Journal<I>::remove(librados::IoCtx &io_ctx, const std::string &image_id) {
bool journal_exists;
int r = journaler.exists(&journal_exists);
if (r < 0) {
lderr(cct) << "failed to stat journal header: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to stat journal header: " << cpp_strerror(r) << dendl;
return r;
} else if (!journal_exists) {
return 0;
Expand All @@ -424,13 +436,15 @@ int Journal<I>::remove(librados::IoCtx &io_ctx, const std::string &image_id) {
if (r == -ENOENT) {
return 0;
} else if (r < 0) {
lderr(cct) << "failed to initialize journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to initialize journal: " << cpp_strerror(r) << dendl;
return r;
}

r = journaler.remove(true);
if (r < 0) {
lderr(cct) << "failed to remove journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to remove journal: " << cpp_strerror(r) << dendl;
return r;
}
return 0;
Expand All @@ -454,7 +468,8 @@ int Journal<I>::reset(librados::IoCtx &io_ctx, const std::string &image_id) {
if (r == -ENOENT) {
return 0;
} else if (r < 0) {
lderr(cct) << "failed to initialize journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to initialize journal: " << cpp_strerror(r) << dendl;
return r;
}

Expand All @@ -467,20 +482,23 @@ int Journal<I>::reset(librados::IoCtx &io_ctx, const std::string &image_id) {
librados::Rados rados(io_ctx);
r = rados.pool_reverse_lookup(pool_id, &pool_name);
if (r < 0) {
lderr(cct) << "failed to lookup data pool: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to lookup data pool: " << cpp_strerror(r) << dendl;
return r;
}
}

r = journaler.remove(true);
if (r < 0) {
lderr(cct) << "failed to reset journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to reset journal: " << cpp_strerror(r) << dendl;
return r;
}

r = create(io_ctx, image_id, order, splay_width, pool_name, false, "");
if (r < 0) {
lderr(cct) << "failed to create journal: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to create journal: " << cpp_strerror(r) << dendl;
return r;
}
return 0;
Expand Down Expand Up @@ -562,7 +580,8 @@ int Journal<I>::request_resync(I *image_ctx) {

r = update_client_ctx.wait();
if (r < 0) {
lderr(cct) << "failed to update client: " << cpp_strerror(r) << dendl;
lderr(cct) << __func__ << ": "
<< "failed to update client: " << cpp_strerror(r) << dendl;
return r;
}
return 0;
Expand Down Expand Up @@ -688,7 +707,8 @@ int Journal<I>::demote() {
cls::journal::Client client;
int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client);
if (r < 0) {
lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to retrieve client: " << cpp_strerror(r) << dendl;
return r;
}

Expand All @@ -702,7 +722,8 @@ int Journal<I>::demote() {
bufferlist::iterator tag_data_bl_it = new_tag.data.begin();
r = C_DecodeTag::decode(&tag_data_bl_it, &m_tag_data);
if (r < 0) {
lderr(cct) << "failed to decode newly allocated tag" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode newly allocated tag" << dendl;
return r;
}

Expand All @@ -717,7 +738,8 @@ int Journal<I>::demote() {

r = ctx.wait();
if (r < 0) {
lderr(cct) << "failed to append demotion journal event: " << cpp_strerror(r)
lderr(cct) << this << " " << __func__ << ": "
<< "failed to append demotion journal event: " << cpp_strerror(r)
<< dendl;
return r;
}
Expand All @@ -728,7 +750,8 @@ int Journal<I>::demote() {

r = flush_ctx.wait();
if (r < 0) {
lderr(cct) << "failed to flush demotion commit position: "
lderr(cct) << this << " " << __func__ << ": "
<< "failed to flush demotion commit position: "
<< cpp_strerror(r) << dendl;
return r;
}
Expand All @@ -751,7 +774,8 @@ void Journal<I>::allocate_local_tag(Context *on_finish) {
cls::journal::Client client;
int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client);
if (r < 0) {
lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to retrieve client: " << cpp_strerror(r) << dendl;
m_image_ctx.op_work_queue->queue(on_finish, r);
return;
}
Expand Down Expand Up @@ -947,7 +971,8 @@ void Journal<I>::commit_io_event_extent(uint64_t tid, uint64_t offset,

event.pending_extents.subtract(intersect);
if (!event.pending_extents.empty()) {
ldout(cct, 20) << "pending extents: " << event.pending_extents << dendl;
ldout(cct, 20) << this << " " << __func__ << ": "
<< "pending extents: " << event.pending_extents << dendl;
return;
}
complete_event(it, event.ret_val);
Expand Down Expand Up @@ -1069,7 +1094,8 @@ typename Journal<I>::Future Journal<I>::wait_event(Mutex &lock, uint64_t tid,
Event &event = it->second;
if (event.safe) {
// journal entry already safe
ldout(cct, 20) << "journal entry already safe" << dendl;
ldout(cct, 20) << this << " " << __func__ << ": "
<< "journal entry already safe" << dendl;
m_image_ctx.op_work_queue->queue(on_safe, event.ret_val);
return Future();
}
Expand Down Expand Up @@ -1115,7 +1141,8 @@ void Journal<I>::handle_start_external_replay(int r,
assert(m_journal_replay == nullptr);

if (r < 0) {
lderr(cct) << "failed to stop recording: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to stop recording: " << cpp_strerror(r) << dendl;
*journal_replay = nullptr;

if (m_on_replay_close_request != nullptr) {
Expand Down Expand Up @@ -1227,7 +1254,8 @@ void Journal<I>::complete_event(typename Events::iterator it, int r) {
// event recorded to journal but failed to update disk, we cannot
// commit this IO event. this event must be replayed.
assert(event.safe);
lderr(cct) << "failed to commit IO to disk, replay required: "
lderr(cct) << this << " " << __func__ << ": "
<< "failed to commit IO to disk, replay required: "
<< cpp_strerror(r) << dendl;
}

Expand Down Expand Up @@ -1275,7 +1303,8 @@ void Journal<I>::handle_initialized(int r) {
r = m_journaler->get_cached_client(Journal<ImageCtx>::IMAGE_CLIENT_ID,
&client);
if (r < 0) {
lderr(cct) << "failed to locate master image client" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to locate master image client" << dendl;
destroy_journaler(r);
return;
}
Expand All @@ -1285,7 +1314,8 @@ void Journal<I>::handle_initialized(int r) {
try {
::decode(client_data, bl);
} catch (const buffer::error &err) {
lderr(cct) << "failed to decode client meta data: " << err.what()
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode client meta data: " << err.what()
<< dendl;
destroy_journaler(-EINVAL);
return;
Expand All @@ -1294,13 +1324,15 @@ void Journal<I>::handle_initialized(int r) {
journal::ImageClientMeta *image_client_meta =
boost::get<journal::ImageClientMeta>(&client_data.client_meta);
if (image_client_meta == nullptr) {
lderr(cct) << "failed to extract client meta data" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to extract client meta data" << dendl;
destroy_journaler(-EINVAL);
return;
}

m_tag_class = image_client_meta->tag_class;
ldout(cct, 20) << "client: " << client << ", "
ldout(cct, 20) << this << " " << __func__ << ": "
<< "client: " << client << ", "
<< "image meta: " << *image_client_meta << dendl;

C_DecodeTags *tags_ctx = new C_DecodeTags(
Expand Down Expand Up @@ -1356,8 +1388,8 @@ void Journal<I>::handle_replay_ready() {
journal::EventEntry event_entry;
int r = m_journal_replay->decode(&it, &event_entry);
if (r < 0) {
lderr(cct) << this << " " << __func__
<< ": failed to decode journal event entry" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode journal event entry" << dendl;
handle_replay_process_safe(replay_entry, r);
return;
}
Expand Down Expand Up @@ -1441,7 +1473,8 @@ void Journal<I>::handle_replay_process_safe(ReplayEntry replay_entry, int r) {

ldout(cct, 20) << this << " " << __func__ << ": r=" << r << dendl;
if (r < 0) {
lderr(cct) << "failed to commit journal event to disk: " << cpp_strerror(r)
lderr(cct) << this << " " << __func__ << ": "
<< "failed to commit journal event to disk: " << cpp_strerror(r)
<< dendl;

if (m_state == STATE_REPLAYING) {
Expand Down Expand Up @@ -1561,7 +1594,8 @@ void Journal<I>::handle_io_event_safe(int r, uint64_t tid) {
// journal will be flushed before closing
assert(m_state == STATE_READY || m_state == STATE_STOPPING);
if (r < 0) {
lderr(cct) << "failed to commit IO event: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to commit IO event: " << cpp_strerror(r) << dendl;
}

AioObjectRequests aio_object_requests;
Expand Down Expand Up @@ -1591,7 +1625,8 @@ void Journal<I>::handle_io_event_safe(int r, uint64_t tid) {
}
}

ldout(cct, 20) << "completing tid=" << tid << dendl;
ldout(cct, 20) << this << " " << __func__ << ": "
<< "completing tid=" << tid << dendl;
for (AioObjectRequests::iterator it = aio_object_requests.begin();
it != aio_object_requests.end(); ++it) {
if (r < 0) {
Expand Down Expand Up @@ -1622,7 +1657,8 @@ void Journal<I>::handle_op_event_safe(int r, uint64_t tid,
// journal will be flushed before closing
assert(m_state == STATE_READY || m_state == STATE_STOPPING);
if (r < 0) {
lderr(cct) << "failed to commit op event: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to commit op event: " << cpp_strerror(r) << dendl;
}

m_journaler->committed(op_start_future);
Expand Down Expand Up @@ -1712,7 +1748,8 @@ int Journal<I>::check_resync_requested_internal(bool *do_resync) {
cls::journal::Client client;
int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client);
if (r < 0) {
lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to retrieve client: " << cpp_strerror(r) << dendl;
return r;
}

Expand All @@ -1721,14 +1758,16 @@ int Journal<I>::check_resync_requested_internal(bool *do_resync) {
try {
::decode(client_data, bl_it);
} catch (const buffer::error &err) {
lderr(cct) << "failed to decode client data: " << err << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to decode client data: " << err << dendl;
return -EINVAL;
}

journal::ImageClientMeta *image_client_meta =
boost::get<journal::ImageClientMeta>(&client_data.client_meta);
if (image_client_meta == nullptr) {
lderr(cct) << "failed to access image client meta struct" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to access image client meta struct" << dendl;
return -EINVAL;
}

Expand All @@ -1755,7 +1794,8 @@ void Journal<I>::handle_metadata_updated() {
bool do_resync = false;
int r = check_resync_requested_internal(&do_resync);
if (r < 0) {
lderr(cct) << "failed to check if a resync was requested" << dendl;
lderr(cct) << this << " " << __func__ << ": "
<< "failed to check if a resync was requested" << dendl;
return;
}

Expand Down
Loading

0 comments on commit 270cb74

Please sign in to comment.