You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pegasus.apache.org by la...@apache.org on 2023/01/12 13:06:59 UTC
[incubator-pegasus] branch master updated: refactor(log): use LOG_INFO_F instead of LOG_INFO (1/3) (#1307)
This is an automated email from the ASF dual-hosted git repository.
laiyingchun pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-pegasus.git
The following commit(s) were added to refs/heads/master by this push:
new 948682211 refactor(log): use LOG_INFO_F instead of LOG_INFO (1/3) (#1307)
948682211 is described below
commit 948682211ab080279882b6089cdbc855a10de5d4
Author: Yingchun Lai <la...@apache.org>
AuthorDate: Thu Jan 12 21:06:52 2023 +0800
refactor(log): use LOG_INFO_F instead of LOG_INFO (1/3) (#1307)
---
src/replica/backup/replica_backup_server.cpp | 8 +-
src/replica/mutation_log.cpp | 229 ++++++-------
src/replica/mutation_log_replay.cpp | 15 +-
src/replica/replica.cpp | 2 +-
src/replica/replica_2pc.cpp | 7 +-
src/replica/replica_backup.cpp | 174 +++++-----
src/replica/replica_check.cpp | 9 +-
src/replica/replica_chkpt.cpp | 73 ++--
src/replica/replica_config.cpp | 117 +++----
src/replica/replica_failover.cpp | 9 +-
src/replica/replica_init.cpp | 45 ++-
src/replica/replica_learn.cpp | 486 ++++++++++++---------------
src/replica/replica_restore.cpp | 6 +-
src/replica/test/mock_utils.h | 6 +-
14 files changed, 541 insertions(+), 645 deletions(-)
diff --git a/src/replica/backup/replica_backup_server.cpp b/src/replica/backup/replica_backup_server.cpp
index 6edb01a14..bf154a7b2 100644
--- a/src/replica/backup/replica_backup_server.cpp
+++ b/src/replica/backup/replica_backup_server.cpp
@@ -40,10 +40,10 @@ void replica_backup_server::on_cold_backup(backup_rpc rpc)
const backup_request &request = rpc.request();
backup_response &response = rpc.response();
- LOG_INFO("received cold backup request: backup{%s.%s.%" PRId64 "}",
- request.pid.to_string(),
- request.policy.policy_name.c_str(),
- request.backup_id);
+ LOG_INFO_F("received cold backup request: backup[{}.{}.{}]",
+ request.pid,
+ request.policy.policy_name,
+ request.backup_id);
response.pid = request.pid;
response.policy_name = request.policy.policy_name;
response.backup_id = request.backup_id;
diff --git a/src/replica/mutation_log.cpp b/src/replica/mutation_log.cpp
index c55cc696d..17fb5a0d1 100644
--- a/src/replica/mutation_log.cpp
+++ b/src/replica/mutation_log.cpp
@@ -550,21 +550,19 @@ error_code mutation_log::open(replay_callback read_callback,
}
if (_is_private) {
- LOG_INFO("open private log %s succeed, start_offset = %" PRId64
- ", end_offset = %" PRId64 ", size = %" PRId64
- ", previous_max_decree = %" PRId64,
- fpath.c_str(),
- log->start_offset(),
- log->end_offset(),
- log->end_offset() - log->start_offset(),
- log->previous_log_max_decree(_private_gpid));
+ LOG_INFO_F("open private log {} succeed, start_offset = {}, end_offset = {}, size = "
+ "{}, previous_max_decree = {}",
+ fpath,
+ log->start_offset(),
+ log->end_offset(),
+ log->end_offset() - log->start_offset(),
+ log->previous_log_max_decree(_private_gpid));
} else {
- LOG_INFO("open shared log %s succeed, start_offset = %" PRId64 ", end_offset = %" PRId64
- ", size = %" PRId64 "",
- fpath.c_str(),
- log->start_offset(),
- log->end_offset(),
- log->end_offset() - log->start_offset());
+ LOG_INFO_F("open shared log {} succeed, start_offset = {}, end_offset = {}, size = {}",
+ fpath,
+ log->start_offset(),
+ log->end_offset(),
+ log->end_offset() - log->start_offset());
}
CHECK(_log_files.find(log->index()) == _log_files.end(),
@@ -645,7 +643,7 @@ error_code mutation_log::open(replay_callback read_callback,
}
for (auto it = _log_files.begin(); it != replay_begin; it++) {
- LOG_INFO("ignore log %s", it->second->path().c_str());
+ LOG_INFO_F("ignore log {}", it->second->path());
}
}
@@ -732,9 +730,8 @@ error_code mutation_log::create_new_log_file()
}
CHECK_EQ(logf->end_offset(), logf->start_offset());
CHECK_EQ(_global_end_offset, logf->end_offset());
- LOG_INFO("create new log file %s succeed, time_used = %" PRIu64 " ns",
- logf->path().c_str(),
- dsn_now_ns() - start);
+ LOG_INFO_F(
+ "create new log file {} succeed, time_used = {} ns", logf->path(), dsn_now_ns() - start);
// update states
_last_file_index++;
@@ -815,10 +812,10 @@ std::pair<log_file_ptr, int64_t> mutation_log::mark_new_offset(size_t size,
}
if (create_file) {
- LOG_INFO("switch log file by %s, old_file = %s, size = %" PRId64,
- reason,
- _current_log_file->path().c_str(),
- file_size);
+ LOG_INFO_F("switch log file by {}, old_file = {}, size = {}",
+ reason,
+ _current_log_file->path(),
+ file_size);
}
}
@@ -1149,25 +1146,22 @@ bool mutation_log::get_learn_state(gpid gpid, decree start, /*out*/ learn_state
bool ret = (learned_file_start_offset >= _private_log_info.valid_start_offset &&
last_max_decree > 0 && last_max_decree < start);
- LOG_INFO("gpid(%d.%d) get_learn_state returns %s, "
- "private logs count %d (%d => %d), learned files count %d (%d => %d): "
- "learned_file_start_offset(%" PRId64 ") >= valid_start_offset(%" PRId64 ") && "
- "last_max_decree(%" PRId64 ") > 0 && last_max_decree(%" PRId64
- ") < learn_start_decree(%" PRId64 ")",
- gpid.get_app_id(),
- gpid.get_partition_index(),
- ret ? "true" : "false",
- (int)files.size(),
- files.empty() ? 0 : files.begin()->first,
- files.empty() ? 0 : files.rbegin()->first,
- (int)learn_files.size(),
- learned_file_head_index,
- learned_file_tail_index,
- learned_file_start_offset,
- _private_log_info.valid_start_offset,
- last_max_decree,
- last_max_decree,
- start);
+ LOG_INFO_F("gpid({}) get_learn_state returns {}, private logs count {} ({} => {}), learned "
+ "files count {} ({} => {}): learned_file_start_offset({}) >= valid_start_offset({}) "
+ "&& last_max_decree({}) > 0 && last_max_decree({}) < learn_start_decree({})",
+ gpid,
+ ret ? "true" : "false",
+ files.size(),
+ files.empty() ? 0 : files.begin()->first,
+ files.empty() ? 0 : files.rbegin()->first,
+ learn_files.size(),
+ learned_file_head_index,
+ learned_file_tail_index,
+ learned_file_start_offset,
+ _private_log_info.valid_start_offset,
+ last_max_decree,
+ last_max_decree,
+ start);
return ret;
}
@@ -1416,12 +1410,12 @@ int mutation_log::garbage_collection(const replica_log_info_map &gc_condition,
if (files.size() <= 1) {
// nothing to do
- LOG_INFO("gc_shared: too few files to delete, file_count_limit = %d, "
- "reserved_log_count = %d, reserved_log_size = %" PRId64 ", current_log_index = %d",
- file_count_limit,
- (int)files.size(),
- total_log_size,
- current_log_index);
+ LOG_INFO_F("gc_shared: too few files to delete, file_count_limit = {}, reserved_log_count "
+ "= {}, reserved_log_size = {}, current_log_index = {}",
+ file_count_limit,
+ files.size(),
+ total_log_size,
+ current_log_index);
return (int)files.size();
} else {
// the last one should be the current log file
@@ -1570,34 +1564,32 @@ int mutation_log::garbage_collection(const replica_log_info_map &gc_condition,
if (mark_it == files.rend()) {
// no file to delete
if (stop_gc_decree_gap > 0) {
- LOG_INFO("gc_shared: no file can be deleted, file_count_limit = %d, "
- "reserved_log_count = %d, reserved_log_size = %" PRId64 ", "
- "reserved_smallest_log = %d, reserved_largest_log = %d, "
- "stop_gc_log_index = %d, stop_gc_replica_count = %d, "
- "stop_gc_replica = %d.%d, stop_gc_decree_gap = %" PRId64 ", "
- "stop_gc_garbage_max_decree = %" PRId64 ", stop_gc_log_max_decree = %" PRId64
- "",
- file_count_limit,
- reserved_log_count,
- reserved_log_size,
- reserved_smallest_log,
- reserved_largest_log,
- stop_gc_log_index,
- (int)prevent_gc_replicas.size(),
- stop_gc_replica.get_app_id(),
- stop_gc_replica.get_partition_index(),
- stop_gc_decree_gap,
- stop_gc_garbage_max_decree,
- stop_gc_log_max_decree);
+ LOG_INFO_F("gc_shared: no file can be deleted, file_count_limit = {}, "
+ "reserved_log_count = {}, reserved_log_size = {}, "
+ "reserved_smallest_log = {}, reserved_largest_log = {}, "
+ "stop_gc_log_index = {}, stop_gc_replica_count = {}, "
+ "stop_gc_replica = {}, stop_gc_decree_gap = {}, "
+ "stop_gc_garbage_max_decree = {}, stop_gc_log_max_decree = {}",
+ file_count_limit,
+ reserved_log_count,
+ reserved_log_size,
+ reserved_smallest_log,
+ reserved_largest_log,
+ stop_gc_log_index,
+ prevent_gc_replicas.size(),
+ stop_gc_replica,
+ stop_gc_decree_gap,
+ stop_gc_garbage_max_decree,
+ stop_gc_log_max_decree);
} else {
- LOG_INFO("gc_shared: no file can be deleted, file_count_limit = %d, "
- "reserved_log_count = %d, reserved_log_size = %" PRId64 ", "
- "reserved_smallest_log = %d, reserved_largest_log = %d, ",
- file_count_limit,
- reserved_log_count,
- reserved_log_size,
- reserved_smallest_log,
- reserved_largest_log);
+ LOG_INFO_F("gc_shared: no file can be deleted, file_count_limit = {}, "
+ "reserved_log_count = {}, reserved_log_size = {}, "
+ "reserved_smallest_log = {}, reserved_largest_log = {}",
+ file_count_limit,
+ reserved_log_count,
+ reserved_log_size,
+ reserved_smallest_log,
+ reserved_largest_log);
}
return reserved_log_count;
@@ -1630,7 +1622,7 @@ int mutation_log::garbage_collection(const replica_log_info_map &gc_condition,
}
// delete succeed
- LOG_INFO("gc_shared: log file %s is removed", fpath.c_str());
+ LOG_INFO_F("gc_shared: log file {} is removed", fpath);
deleted_log_count++;
deleted_log_size += log->end_offset() - log->start_offset();
if (deleted_smallest_log == 0)
@@ -1656,51 +1648,50 @@ int mutation_log::garbage_collection(const replica_log_info_map &gc_condition,
}
if (stop_gc_decree_gap > 0) {
- LOG_INFO("gc_shared: deleted some files, file_count_limit = %d, "
- "reserved_log_count = %d, reserved_log_size = %" PRId64 ", "
- "reserved_smallest_log = %d, reserved_largest_log = %d, "
- "to_delete_log_count = %d, to_delete_log_size = %" PRId64 ", "
- "deleted_log_count = %d, deleted_log_size = %" PRId64 ", "
- "deleted_smallest_log = %d, deleted_largest_log = %d, "
- "stop_gc_log_index = %d, stop_gc_replica_count = %d, "
- "stop_gc_replica = %d.%d, stop_gc_decree_gap = %" PRId64 ", "
- "stop_gc_garbage_max_decree = %" PRId64 ", stop_gc_log_max_decree = %" PRId64 "",
- file_count_limit,
- reserved_log_count,
- reserved_log_size,
- reserved_smallest_log,
- reserved_largest_log,
- to_delete_log_count,
- to_delete_log_size,
- deleted_log_count,
- deleted_log_size,
- deleted_smallest_log,
- deleted_largest_log,
- stop_gc_log_index,
- (int)prevent_gc_replicas.size(),
- stop_gc_replica.get_app_id(),
- stop_gc_replica.get_partition_index(),
- stop_gc_decree_gap,
- stop_gc_garbage_max_decree,
- stop_gc_log_max_decree);
+ LOG_INFO_F("gc_shared: deleted some files, file_count_limit = {}, "
+ "reserved_log_count = {}, reserved_log_size = {}, "
+ "reserved_smallest_log = {}, reserved_largest_log = {}, "
+ "to_delete_log_count = {}, to_delete_log_size = {}, "
+ "deleted_log_count = {}, deleted_log_size = {}, "
+ "deleted_smallest_log = {}, deleted_largest_log = {}, "
+ "stop_gc_log_index = {}, stop_gc_replica_count = {}, "
+ "stop_gc_replica = {}, stop_gc_decree_gap = {}, "
+ "stop_gc_garbage_max_decree = {}, stop_gc_log_max_decree = {}",
+ file_count_limit,
+ reserved_log_count,
+ reserved_log_size,
+ reserved_smallest_log,
+ reserved_largest_log,
+ to_delete_log_count,
+ to_delete_log_size,
+ deleted_log_count,
+ deleted_log_size,
+ deleted_smallest_log,
+ deleted_largest_log,
+ stop_gc_log_index,
+ prevent_gc_replicas.size(),
+ stop_gc_replica,
+ stop_gc_decree_gap,
+ stop_gc_garbage_max_decree,
+ stop_gc_log_max_decree);
} else {
- LOG_INFO("gc_shared: deleted some files, file_count_limit = %d, "
- "reserved_log_count = %d, reserved_log_size = %" PRId64 ", "
- "reserved_smallest_log = %d, reserved_largest_log = %d, "
- "to_delete_log_count = %d, to_delete_log_size = %" PRId64 ", "
- "deleted_log_count = %d, deleted_log_size = %" PRId64 ", "
- "deleted_smallest_log = %d, deleted_largest_log = %d",
- file_count_limit,
- reserved_log_count,
- reserved_log_size,
- reserved_smallest_log,
- reserved_largest_log,
- to_delete_log_count,
- to_delete_log_size,
- deleted_log_count,
- deleted_log_size,
- deleted_smallest_log,
- deleted_largest_log);
+ LOG_INFO_F("gc_shared: deleted some files, file_count_limit = {}, "
+ "reserved_log_count = {}, reserved_log_size = {}, "
+ "reserved_smallest_log = {}, reserved_largest_log = {}, "
+ "to_delete_log_count = {}, to_delete_log_size = {}, "
+ "deleted_log_count = {}, deleted_log_size = {}, "
+ "deleted_smallest_log = {}, deleted_largest_log = {}",
+ file_count_limit,
+ reserved_log_count,
+ reserved_log_size,
+ reserved_smallest_log,
+ reserved_largest_log,
+ to_delete_log_count,
+ to_delete_log_size,
+ deleted_log_count,
+ deleted_log_size,
+ deleted_smallest_log,
+ deleted_largest_log);
}
return reserved_log_count;
diff --git a/src/replica/mutation_log_replay.cpp b/src/replica/mutation_log_replay.cpp
index dbad94f10..42397d6bb 100644
--- a/src/replica/mutation_log_replay.cpp
+++ b/src/replica/mutation_log_replay.cpp
@@ -29,12 +29,11 @@ namespace replication {
/*out*/ int64_t &end_offset)
{
end_offset = log->start_offset();
- LOG_INFO("start to replay mutation log %s, offset = [%" PRId64 ", %" PRId64
- "), size = %" PRId64,
- log->path().c_str(),
- log->start_offset(),
- log->end_offset(),
- log->end_offset() - log->start_offset());
+ LOG_INFO_F("start to replay mutation log {}, offset = [{}, {}), size = {}",
+ log->path(),
+ log->start_offset(),
+ log->end_offset(),
+ log->end_offset() - log->start_offset());
::dsn::blob bb;
log->reset_stream();
@@ -50,9 +49,7 @@ namespace replication {
start_offset = static_cast<size_t>(end_offset - log->start_offset());
}
- LOG_INFO("finish to replay mutation log (%s) [err: %s]",
- log->path().c_str(),
- err.description().c_str());
+ LOG_INFO_F("finish to replay mutation log ({}) [err: {}]", log->path(), err);
return err.code();
}
diff --git a/src/replica/replica.cpp b/src/replica/replica.cpp
index 5d0f546d7..7a3123871 100644
--- a/src/replica/replica.cpp
+++ b/src/replica/replica.cpp
@@ -485,7 +485,7 @@ void replica::close()
_split_mgr.reset();
- LOG_INFO("%s: replica closed, time_used = %" PRIu64 "ms", name(), dsn_now_ms() - start_time);
+ LOG_INFO_PREFIX("replica closed, time_used = {} ms", dsn_now_ms() - start_time);
}
std::string replica::query_manual_compact_state() const
diff --git a/src/replica/replica_2pc.cpp b/src/replica/replica_2pc.cpp
index 8f3508348..cc666cb91 100644
--- a/src/replica/replica_2pc.cpp
+++ b/src/replica/replica_2pc.cpp
@@ -670,11 +670,8 @@ void replica::on_prepare_reply(std::pair<mutation_ptr, partition_status::type> p
prepare_timeout_ms,
dsn_now_ms());
} else {
- LOG_INFO("%s: mutation %s retry prepare to %s after %d ms",
- name(),
- mu->name(),
- node.to_string(),
- delay_time_ms);
+ LOG_INFO_PREFIX(
+ "mutation {} retry prepare to {} after {} ms", mu->name(), node, delay_time_ms);
int64_t learn_signature = invalid_signature;
if (target_status == partition_status::PS_POTENTIAL_SECONDARY) {
auto it = _primary_states.learners.find(node);
diff --git a/src/replica/replica_backup.cpp b/src/replica/replica_backup.cpp
index a4168b579..6c5134f25 100644
--- a/src/replica/replica_backup.cpp
+++ b/src/replica/replica_backup.cpp
@@ -86,9 +86,10 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
if (backup_context->request.backup_id < backup_id || backup_status == ColdBackupCanceled) {
if (backup_status == ColdBackupCheckpointing) {
- LOG_INFO("%s: delay clearing obsoleted cold backup context, cause backup_status == "
- "ColdBackupCheckpointing",
- new_context->name);
+ LOG_INFO_F(
+ "{}: delay clearing obsoleted cold backup context, cause backup_status == "
+ "ColdBackupCheckpointing",
+ new_context->name);
tasking::enqueue(LPC_REPLICATION_COLD_BACKUP,
&_tracker,
[this, request]() {
@@ -101,11 +102,11 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
// TODO(wutao1): deleting cold backup context should be
// extracted as a function like try_delete_cold_backup_context;
// clear obsoleted backup context firstly
- LOG_INFO("%s: clear obsoleted cold backup context, old_backup_id = %" PRId64
- ", old_backup_status = %s",
- new_context->name,
- backup_context->request.backup_id,
- cold_backup_status_to_string(backup_status));
+ LOG_INFO_F("{}: clear obsoleted cold backup context, old_backup_id = {}, "
+ "old_backup_status = {}",
+ new_context->name,
+ backup_context->request.backup_id,
+ cold_backup_status_to_string(backup_status));
backup_context->cancel();
_cold_backup_contexts.erase(policy_name);
// go to another round
@@ -153,22 +154,22 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
if (backup_status == ColdBackupChecking || backup_status == ColdBackupCheckpointing ||
backup_status == ColdBackupUploading) {
// do nothing
- LOG_INFO("%s: backup is busy, status = %s, progress = %d, response ERR_BUSY",
- backup_context->name,
- cold_backup_status_to_string(backup_status),
- backup_context->progress());
+ LOG_INFO_F("{}: backup is busy, status = {}, progress = {}, response ERR_BUSY",
+ backup_context->name,
+ cold_backup_status_to_string(backup_status),
+ backup_context->progress());
response.err = ERR_BUSY;
} else if (backup_status == ColdBackupInvalid && backup_context->start_check()) {
_stub->_counter_cold_backup_recent_start_count->increment();
- LOG_INFO("%s: start checking backup on remote, response ERR_BUSY",
- backup_context->name);
+ LOG_INFO_F("{}: start checking backup on remote, response ERR_BUSY",
+ backup_context->name);
tasking::enqueue(LPC_BACKGROUND_COLD_BACKUP, nullptr, [backup_context]() {
backup_context->check_backup_on_remote();
});
response.err = ERR_BUSY;
} else if (backup_status == ColdBackupChecked && backup_context->start_checkpoint()) {
// start generating checkpoint
- LOG_INFO("%s: start generating checkpoint, response ERR_BUSY", backup_context->name);
+ LOG_INFO_F("{}: start generating checkpoint, response ERR_BUSY", backup_context->name);
tasking::enqueue(LPC_BACKGROUND_COLD_BACKUP, &_tracker, [this, backup_context]() {
generate_backup_checkpoint(backup_context);
});
@@ -176,7 +177,7 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
} else if ((backup_status == ColdBackupCheckpointed || backup_status == ColdBackupPaused) &&
backup_context->start_upload()) {
// start uploading checkpoint
- LOG_INFO("%s: start uploading checkpoint, response ERR_BUSY", backup_context->name);
+ LOG_INFO_F("{}: start uploading checkpoint, response ERR_BUSY", backup_context->name);
tasking::enqueue(LPC_BACKGROUND_COLD_BACKUP, nullptr, [backup_context]() {
backup_context->upload_checkpoint_to_remote();
});
@@ -189,7 +190,7 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
backup_context->cancel();
_cold_backup_contexts.erase(policy_name);
} else if (backup_status == ColdBackupCompleted) {
- LOG_INFO("%s: upload checkpoint completed, response ERR_OK", backup_context->name);
+ LOG_INFO_F("{}: upload checkpoint completed, response ERR_OK", backup_context->name);
_backup_mgr->send_clear_request_to_secondaries(backup_context->request.pid,
policy_name);
@@ -207,7 +208,7 @@ void replica::on_cold_backup(const backup_request &request, /*out*/ backup_respo
response.progress = backup_context->progress();
response.checkpoint_total_size = backup_context->get_checkpoint_total_size();
- LOG_INFO("%s: backup progress is %d", backup_context->name, response.progress);
+ LOG_INFO_F("{}: backup progress is {}", backup_context->name, response.progress);
} else {
LOG_ERROR(
"%s: invalid state for cold backup, partition_status = %s, response ERR_INVALID_STATE",
@@ -395,9 +396,9 @@ static bool backup_parse_dir_name(const char *name,
void replica::generate_backup_checkpoint(cold_backup_context_ptr backup_context)
{
if (backup_context->status() != ColdBackupCheckpointing) {
- LOG_INFO("%s: ignore generating backup checkpoint because backup_status = %s",
- backup_context->name,
- cold_backup_status_to_string(backup_context->status()));
+ LOG_INFO_F("{}: ignore generating backup checkpoint because backup_status = {}",
+ backup_context->name,
+ cold_backup_status_to_string(backup_context->status()));
backup_context->ignore_checkpoint();
return;
}
@@ -444,12 +445,12 @@ void replica::generate_backup_checkpoint(cold_backup_context_ptr backup_context)
backup_context->checkpoint_file_total_size = total_size;
backup_context->complete_checkpoint();
- LOG_INFO("%s: backup checkpoint aleady exist, dir = %s, file_count = %d, total_size = "
- "%" PRId64,
- backup_context->name,
- backup_context->checkpoint_dir.c_str(),
- (int)file_infos.size(),
- total_size);
+ LOG_INFO_F(
+ "{}: backup checkpoint aleady exist, dir = {}, file_count = {}, total_size = {}",
+ backup_context->name,
+ backup_context->checkpoint_dir,
+ file_infos.size(),
+ total_size);
// TODO: in primary, this will make the request send to secondary again
tasking::enqueue(LPC_REPLICATION_COLD_BACKUP,
&_tracker,
@@ -463,8 +464,8 @@ void replica::generate_backup_checkpoint(cold_backup_context_ptr backup_context)
return;
}
} else {
- LOG_INFO("%s: backup checkpoint not exist, start to trigger async checkpoint",
- backup_context->name);
+ LOG_INFO_F("{}: backup checkpoint not exist, start to trigger async checkpoint",
+ backup_context->name);
tasking::enqueue(
LPC_REPLICATION_COLD_BACKUP,
&_tracker,
@@ -475,9 +476,9 @@ void replica::generate_backup_checkpoint(cold_backup_context_ptr backup_context)
// clear related but not valid checkpoint
for (const std::string &dirname : related_backup_chkpt_dirname) {
std::string full_path = utils::filesystem::path_combine(backup_dir, dirname);
- LOG_INFO("%s: found obsolete backup checkpoint dir(%s), remove it",
- backup_context->name,
- full_path.c_str());
+ LOG_INFO_F("{}: found obsolete backup checkpoint dir({}), remove it",
+ backup_context->name,
+ full_path);
if (!utils::filesystem::remove_path(full_path)) {
LOG_WARNING("%s: remove obsolete backup checkpoint dir(%s) failed",
backup_context->name,
@@ -496,17 +497,17 @@ void replica::trigger_async_checkpoint_for_backup(cold_backup_context_ptr backup
_checker.only_one_thread_access();
if (backup_context->status() != ColdBackupCheckpointing) {
- LOG_INFO("%s: ignore triggering async checkpoint because backup_status = %s",
- backup_context->name,
- cold_backup_status_to_string(backup_context->status()));
+ LOG_INFO_F("{}: ignore triggering async checkpoint because backup_status = {}",
+ backup_context->name,
+ cold_backup_status_to_string(backup_context->status()));
backup_context->ignore_checkpoint();
return;
}
if (status() != partition_status::PS_PRIMARY && status() != partition_status::PS_SECONDARY) {
- LOG_INFO("%s: ignore triggering async checkpoint because partition_status = %s",
- backup_context->name,
- enum_to_string(status()));
+ LOG_INFO_F("{}: ignore triggering async checkpoint because partition_status = {}",
+ backup_context->name,
+ enum_to_string(status()));
backup_context->ignore_checkpoint();
return;
}
@@ -520,14 +521,14 @@ void replica::trigger_async_checkpoint_for_backup(cold_backup_context_ptr backup
// already triggered, just wait
char time_buf[20];
dsn::utils::time_ms_to_date_time(backup_context->checkpoint_timestamp, time_buf, 20);
- LOG_INFO("%s: do not trigger async checkpoint because it is already triggered, "
- "checkpoint_decree = %" PRId64 ", checkpoint_timestamp = %" PRId64 " (%s), "
- "durable_decree_when_checkpoint = %" PRId64,
- backup_context->name,
- backup_context->checkpoint_decree,
- backup_context->checkpoint_timestamp,
- time_buf,
- backup_context->durable_decree_when_checkpoint);
+ LOG_INFO_F("{}: do not trigger async checkpoint because it is already triggered, "
+ "checkpoint_decree = {}, checkpoint_timestamp = {} ({}), "
+ "durable_decree_when_checkpoint = {}",
+ backup_context->name,
+ backup_context->checkpoint_decree,
+ backup_context->checkpoint_timestamp,
+ time_buf,
+ backup_context->durable_decree_when_checkpoint);
} else { // backup_context->checkpoint_decree == 0 ||
// backup_context->durable_decree_when_checkpoint != durable_decree
if (backup_context->checkpoint_decree == 0) {
@@ -536,20 +537,20 @@ void replica::trigger_async_checkpoint_for_backup(cold_backup_context_ptr backup
} else { // backup_context->durable_decree_when_checkpoint != durable_decree
// checkpoint generated, but is behind checkpoint_decree, need trigger again
CHECK_LT(backup_context->durable_decree_when_checkpoint, durable_decree);
- LOG_INFO("%s: need trigger async checkpoint again", backup_context->name);
+ LOG_INFO_F("{}: need trigger async checkpoint again", backup_context->name);
}
backup_context->checkpoint_timestamp = dsn_now_ms();
backup_context->durable_decree_when_checkpoint = durable_decree;
char time_buf[20];
dsn::utils::time_ms_to_date_time(backup_context->checkpoint_timestamp, time_buf, 20);
- LOG_INFO("%s: trigger async checkpoint, "
- "checkpoint_decree = %" PRId64 ", checkpoint_timestamp = %" PRId64 " (%s), "
- "durable_decree_when_checkpoint = %" PRId64,
- backup_context->name,
- backup_context->checkpoint_decree,
- backup_context->checkpoint_timestamp,
- time_buf,
- backup_context->durable_decree_when_checkpoint);
+ LOG_INFO_F("{}: trigger async checkpoint, "
+ "checkpoint_decree = {}, checkpoint_timestamp = {} ({}), "
+ "durable_decree_when_checkpoint = {}",
+ backup_context->name,
+ backup_context->checkpoint_decree,
+ backup_context->checkpoint_timestamp,
+ time_buf,
+ backup_context->durable_decree_when_checkpoint);
init_checkpoint(true);
}
@@ -568,28 +569,28 @@ void replica::wait_async_checkpoint_for_backup(cold_backup_context_ptr backup_co
_checker.only_one_thread_access();
if (backup_context->status() != ColdBackupCheckpointing) {
- LOG_INFO("%s: ignore waiting async checkpoint because backup_status = %s",
- backup_context->name,
- cold_backup_status_to_string(backup_context->status()));
+ LOG_INFO_F("{}: ignore waiting async checkpoint because backup_status = {}",
+ backup_context->name,
+ cold_backup_status_to_string(backup_context->status()));
backup_context->ignore_checkpoint();
return;
}
if (status() != partition_status::PS_PRIMARY && status() != partition_status::PS_SECONDARY) {
- LOG_INFO("%s: ignore waiting async checkpoint because partition_status = %s",
- backup_context->name,
- enum_to_string(status()));
+ LOG_INFO_F("{}: ignore waiting async checkpoint because partition_status = {}",
+ backup_context->name,
+ enum_to_string(status()));
backup_context->ignore_checkpoint();
return;
}
decree du = last_durable_decree();
if (du < backup_context->checkpoint_decree) {
- LOG_INFO("%s: async checkpoint not done, we just wait it done, "
- "last_durable_decree = %" PRId64 ", backup_checkpoint_decree = %" PRId64,
- backup_context->name,
- du,
- backup_context->checkpoint_decree);
+ LOG_INFO_F("{}: async checkpoint not done, we just wait it done, "
+ "last_durable_decree = {}, backup_checkpoint_decree = {}",
+ backup_context->name,
+ du,
+ backup_context->checkpoint_decree);
tasking::enqueue(
LPC_REPLICATION_COLD_BACKUP,
&_tracker,
@@ -597,11 +598,11 @@ void replica::wait_async_checkpoint_for_backup(cold_backup_context_ptr backup_co
get_gpid().thread_hash(),
std::chrono::seconds(10));
} else {
- LOG_INFO("%s: async checkpoint done, last_durable_decree = %" PRId64
- ", backup_context->checkpoint_decree = %" PRId64,
- backup_context->name,
- du,
- backup_context->checkpoint_decree);
+ LOG_INFO_F("{}: async checkpoint done, last_durable_decree = {}, "
+ "backup_context->checkpoint_decree = {}",
+ backup_context->name,
+ du,
+ backup_context->checkpoint_decree);
tasking::enqueue(LPC_BACKGROUND_COLD_BACKUP, &_tracker, [this, backup_context]() {
local_create_backup_checkpoint(backup_context);
});
@@ -617,9 +618,9 @@ void replica::wait_async_checkpoint_for_backup(cold_backup_context_ptr backup_co
void replica::local_create_backup_checkpoint(cold_backup_context_ptr backup_context)
{
if (backup_context->status() != ColdBackupCheckpointing) {
- LOG_INFO("%s: ignore generating backup checkpoint because backup_status = %s",
- backup_context->name,
- cold_backup_status_to_string(backup_context->status()));
+ LOG_INFO_F("{}: ignore generating backup checkpoint because backup_status = {}",
+ backup_context->name,
+ cold_backup_status_to_string(backup_context->status()));
backup_context->ignore_checkpoint();
return;
}
@@ -636,10 +637,10 @@ void replica::local_create_backup_checkpoint(cold_backup_context_ptr backup_cont
_app->copy_checkpoint_to_dir(backup_checkpoint_tmp_dir_path.c_str(), &last_decree);
if (err != ERR_OK) {
// try local_create_backup_checkpoint 10s later
- LOG_INFO("%s: create backup checkpoint failed with err = %s, try call "
- "local_create_backup_checkpoint 10s later",
- backup_context->name,
- err.to_string());
+ LOG_INFO_F("{}: create backup checkpoint failed with err = {}, try call "
+ "local_create_backup_checkpoint 10s later",
+ backup_context->name,
+ err);
utils::filesystem::remove_path(backup_checkpoint_tmp_dir_path);
tasking::enqueue(
LPC_BACKGROUND_COLD_BACKUP,
@@ -678,12 +679,12 @@ void replica::local_create_backup_checkpoint(cold_backup_context_ptr backup_cont
return;
}
- LOG_INFO("%s: generate backup checkpoint succeed, dir = %s, file_count = %d, total_size = "
- "%" PRId64,
- backup_context->name,
- backup_checkpoint_dir_path.c_str(),
- (int)file_infos.size(),
- total_size);
+ LOG_INFO_F(
+ "{}: generate backup checkpoint succeed, dir = {}, file_count = {}, total_size = {}",
+ backup_context->name,
+ backup_checkpoint_dir_path,
+ file_infos.size(),
+ total_size);
backup_context->checkpoint_dir = backup_checkpoint_dir_path;
for (std::pair<std::string, int64_t> &pair : file_infos) {
backup_context->checkpoint_files.emplace_back(std::move(pair.first));
@@ -705,9 +706,8 @@ void replica::set_backup_context_cancel()
{
for (auto &pair : _cold_backup_contexts) {
pair.second->cancel();
- LOG_INFO("%s: cancel backup progress, backup_request = %s",
- name(),
- boost::lexical_cast<std::string>(pair.second->request).c_str());
+ LOG_INFO_PREFIX("cancel backup progress, backup_request = {}",
+ boost::lexical_cast<std::string>(pair.second->request));
}
}
diff --git a/src/replica/replica_check.cpp b/src/replica/replica_check.cpp
index 9aba434f2..222394328 100644
--- a/src/replica/replica_check.cpp
+++ b/src/replica/replica_check.cpp
@@ -55,7 +55,7 @@ void replica::init_group_check()
_checker.only_one_thread_access();
- LOG_INFO("%s: init group check", name());
+ LOG_INFO_PREFIX("init group check");
if (partition_status::PS_PRIMARY != status() || _options->group_check_disabled)
return;
@@ -75,7 +75,7 @@ void replica::broadcast_group_check()
CHECK_NOTNULL(_primary_states.group_check_task, "");
- LOG_INFO("%s: start to broadcast group check", name());
+ LOG_INFO_PREFIX("start to broadcast group check");
if (_primary_states.group_check_pending_replies.size() > 0) {
LOG_WARNING(
@@ -119,10 +119,7 @@ void replica::broadcast_group_check()
request->config.learner_signature = it->second.signature;
}
- LOG_INFO("%s: send group check to %s with state %s",
- name(),
- addr.to_string(),
- enum_to_string(it->second));
+ LOG_INFO_PREFIX("send group check to {} with state {}", addr, enum_to_string(it->second));
dsn::task_ptr callback_task =
rpc::call(addr,
diff --git a/src/replica/replica_chkpt.cpp b/src/replica/replica_chkpt.cpp
index 83f9f3aba..244a580f8 100644
--- a/src/replica/replica_chkpt.cpp
+++ b/src/replica/replica_chkpt.cpp
@@ -62,17 +62,15 @@ void replica::on_checkpoint_timer()
if (dsn_now_ms() > _next_checkpoint_interval_trigger_time_ms) {
// we trigger emergency checkpoint if no checkpoint generated for a long time
- LOG_INFO("%s: trigger emergency checkpoint by checkpoint_max_interval_hours, "
- "config_interval = %dh (%" PRIu64 "ms), random_interval = %" PRIu64 "ms",
- name(),
- _options->checkpoint_max_interval_hours,
- _options->checkpoint_max_interval_hours * 3600000UL,
- _next_checkpoint_interval_trigger_time_ms - _last_checkpoint_generate_time_ms);
+ LOG_INFO_PREFIX("trigger emergency checkpoint by checkpoint_max_interval_hours, "
+ "config_interval = {}h ({}ms), random_interval = {}ms",
+ _options->checkpoint_max_interval_hours,
+ _options->checkpoint_max_interval_hours * 3600000UL,
+ _next_checkpoint_interval_trigger_time_ms -
+ _last_checkpoint_generate_time_ms);
init_checkpoint(true);
} else {
- LOG_INFO("%s: trigger non-emergency checkpoint",
- name(),
- _options->checkpoint_max_interval_hours);
+ LOG_INFO_PREFIX("trigger non-emergency checkpoint");
init_checkpoint(false);
}
@@ -177,10 +175,9 @@ void replica::init_checkpoint(bool is_emergency)
{
// only applicable to primary and secondary replicas
if (status() != partition_status::PS_PRIMARY && status() != partition_status::PS_SECONDARY) {
- LOG_INFO("%s: ignore doing checkpoint for status = %s, is_emergency = %s",
- name(),
- enum_to_string(status()),
- (is_emergency ? "true" : "false"));
+ LOG_INFO_PREFIX("ignore doing checkpoint for status = {}, is_emergency = {}",
+ enum_to_string(status()),
+ is_emergency ? "true" : "false");
return;
}
@@ -240,14 +237,12 @@ error_code replica::background_async_checkpoint(bool is_emergency)
if (old_durable != _app->last_durable_decree()) {
// if no need to generate new checkpoint, async_checkpoint() also returns ERR_OK,
// so we should check if a new checkpoint has been generated.
- LOG_INFO("%s: call app.async_checkpoint() succeed, time_used_ns = %" PRIu64 ", "
- "app_last_committed_decree = %" PRId64 ", app_last_durable_decree = (%" PRId64
- " => %" PRId64 ")",
- name(),
- used_time,
- _app->last_committed_decree(),
- old_durable,
- _app->last_durable_decree());
+ LOG_INFO_PREFIX("call app.async_checkpoint() succeed, time_used_ns = {}, "
+ "app_last_committed_decree = {}, app_last_durable_decree = ({} => {})",
+ used_time,
+ _app->last_committed_decree(),
+ old_durable,
+ _app->last_durable_decree());
update_last_checkpoint_generate_time();
}
@@ -263,10 +258,9 @@ error_code replica::background_async_checkpoint(bool is_emergency)
if (err == ERR_TRY_AGAIN) {
// already triggered memory flushing on async_checkpoint(), then try again later.
- LOG_INFO("%s: call app.async_checkpoint() returns ERR_TRY_AGAIN, time_used_ns = %" PRIu64
- ", schedule later checkpoint after 10 seconds",
- name(),
- used_time);
+ LOG_INFO_PREFIX("call app.async_checkpoint() returns ERR_TRY_AGAIN, time_used_ns = {}"
+ ", schedule later checkpoint after 10 seconds",
+ used_time);
tasking::enqueue(LPC_PER_REPLICA_CHECKPOINT_TIMER,
&_tracker,
[this] { init_checkpoint(false); },
@@ -283,10 +277,9 @@ error_code replica::background_async_checkpoint(bool is_emergency)
}
if (err == ERR_WRONG_TIMING) {
// do nothing
- LOG_INFO("%s: call app.async_checkpoint() returns ERR_WRONG_TIMING, time_used_ns = %" PRIu64
- ", just ignore",
- name(),
- used_time);
+ LOG_INFO_PREFIX(
+ "call app.async_checkpoint() returns ERR_WRONG_TIMING, time_used_ns = {}, just ignore",
+ used_time);
} else {
LOG_ERROR("%s: call app.async_checkpoint() failed, time_used_ns = %" PRIu64 ", err = %s",
name(),
@@ -308,22 +301,20 @@ error_code replica::background_sync_checkpoint()
if (old_durable != _app->last_durable_decree()) {
// if no need to generate new checkpoint, sync_checkpoint() also returns ERR_OK,
// so we should check if a new checkpoint has been generated.
- LOG_INFO("%s: call app.sync_checkpoint() succeed, time_used_ns = %" PRIu64 ", "
- "app_last_committed_decree = %" PRId64 ", app_last_durable_decree = (%" PRId64
- " => %" PRId64 ")",
- name(),
- used_time,
- _app->last_committed_decree(),
- old_durable,
- _app->last_durable_decree());
+ LOG_INFO_PREFIX("call app.sync_checkpoint() succeed, time_used_ns = {}, "
+ "app_last_committed_decree = {}, "
+ "app_last_durable_decree = ({} => {})",
+ used_time,
+ _app->last_committed_decree(),
+ old_durable,
+ _app->last_durable_decree());
update_last_checkpoint_generate_time();
}
} else if (err == ERR_WRONG_TIMING) {
// do nothing
- LOG_INFO("%s: call app.sync_checkpoint() returns ERR_WRONG_TIMING, time_used_ns = %" PRIu64
- ", just ignore",
- name(),
- used_time);
+ LOG_INFO_PREFIX(
+ "call app.sync_checkpoint() returns ERR_WRONG_TIMING, time_used_ns = {}, just ignore",
+ used_time);
} else {
LOG_ERROR("%s: call app.sync_checkpoint() failed, time_used_ns = %" PRIu64 ", err = %s",
name(),
diff --git a/src/replica/replica_config.cpp b/src/replica/replica_config.cpp
index 48bc034d9..80d4b79ad 100644
--- a/src/replica/replica_config.cpp
+++ b/src/replica/replica_config.cpp
@@ -67,10 +67,8 @@ void replica::on_config_proposal(configuration_update_request &proposal)
{
_checker.only_one_thread_access();
- LOG_INFO("%s: process config proposal %s for %s",
- name(),
- enum_to_string(proposal.type),
- proposal.node.to_string());
+ LOG_INFO_PREFIX(
+ "process config proposal {} for {}", enum_to_string(proposal.type), proposal.node);
if (proposal.config.ballot < get_ballot()) {
LOG_WARNING("%s: on_config_proposal out-dated, %" PRId64 " vs %" PRId64,
@@ -171,21 +169,18 @@ void replica::add_potential_secondary(configuration_update_request &proposal)
if (potential_secondaries_count >= _primary_states.membership.max_replica_count - 1) {
if (proposal.type == config_type::CT_ADD_SECONDARY) {
if (_primary_states.learners.find(proposal.node) == _primary_states.learners.end()) {
- LOG_INFO("%s: already have enough secondaries or potential secondaries, ignore new "
- "potential secondary proposal",
- name());
+ LOG_INFO_PREFIX(
+ "already have enough secondaries or potential secondaries, ignore new "
+ "potential secondary proposal");
return;
}
} else if (proposal.type == config_type::CT_ADD_SECONDARY_FOR_LB) {
if (potential_secondaries_count >= _primary_states.membership.max_replica_count) {
- LOG_INFO("%s: only allow one extra (potential) secondary, ingnore new potential "
- "secondary proposal",
- name());
+ LOG_INFO_PREFIX("only allow one extra (potential) secondary, ingnore new potential "
+ "secondary proposal");
return;
} else {
- LOG_INFO("%s: add a new secondary(%s) for future load balancer",
- name(),
- proposal.node.to_string());
+ LOG_INFO_PREFIX("add a new secondary({}) for future load balancer", proposal.node);
}
} else {
CHECK(false, "invalid config_type, type = {}", enum_to_string(proposal.type));
@@ -212,10 +207,9 @@ void replica::add_potential_secondary(configuration_update_request &proposal)
partition_status::PS_POTENTIAL_SECONDARY, request.config, state.signature);
request.last_committed_decree = last_committed_decree();
- LOG_INFO("%s: call one way %s to start learning with signature [%016" PRIx64 "]",
- name(),
- proposal.node.to_string(),
- state.signature);
+ LOG_INFO_PREFIX("call one way {} to start learning with signature [{:#018x}]",
+ proposal.node,
+ state.signature);
rpc::call_one_way_typed(
proposal.node, RPC_LEARN_ADD_LEARNER, request, get_gpid().thread_hash());
@@ -223,7 +217,7 @@ void replica::add_potential_secondary(configuration_update_request &proposal)
void replica::upgrade_to_secondary_on_primary(::dsn::rpc_address node)
{
- LOG_INFO("%s: upgrade potential secondary %s to secondary", name(), node.to_string());
+ LOG_INFO_PREFIX("upgrade potential secondary {} to secondary", node);
partition_configuration newConfig = _primary_states.membership;
@@ -373,12 +367,11 @@ void replica::update_configuration_on_meta_server(config_type::type type,
_primary_states.reconfiguration_task->cancel(true);
}
- LOG_INFO("%s: send update configuration request to meta server, ballot = %" PRId64
- ", type = %s, node = %s",
- name(),
- request->config.ballot,
- enum_to_string(request->type),
- request->node.to_string());
+ LOG_INFO_PREFIX(
+ "send update configuration request to meta server, ballot = {}, type = {}, node = {}",
+ request->config.ballot,
+ enum_to_string(request->type),
+ request->node);
rpc_address target(_stub->_failure_detector->get_servers());
_primary_states.reconfiguration_task =
@@ -411,10 +404,8 @@ void replica::on_update_configuration_on_meta_server_reply(
}
if (err != ERR_OK) {
- LOG_INFO("%s: update configuration reply with err %s, request ballot %" PRId64,
- name(),
- err.to_string(),
- req->config.ballot);
+ LOG_INFO_PREFIX(
+ "update configuration reply with err {}, request ballot {}", err, req->config.ballot);
if (err != ERR_INVALID_VERSION) {
// when the rpc call timeout, we would delay to do the recall
@@ -443,14 +434,13 @@ void replica::on_update_configuration_on_meta_server_reply(
}
}
- LOG_INFO("%s: update configuration %s, reply with err %s, ballot %" PRId64
- ", local ballot %" PRId64 ", local status %s",
- name(),
- enum_to_string(req->type),
- resp.err.to_string(),
- resp.config.ballot,
- get_ballot(),
- enum_to_string(status()));
+ LOG_INFO_PREFIX(
+ "update configuration {}, reply with err {}, ballot {}, local ballot {}, local status {}",
+ enum_to_string(req->type),
+ resp.err,
+ resp.config.ballot,
+ get_ballot(),
+ enum_to_string(status()));
if (resp.config.ballot < get_ballot()) {
_primary_states.reconfiguration_task = nullptr;
@@ -742,10 +732,8 @@ bool replica::update_local_configuration(const replica_configuration &config,
if (_config.ballot > old_ballot) {
dsn::error_code result = _app->update_init_info_ballot_and_decree(this);
if (result == dsn::ERR_OK) {
- LOG_INFO("%s: update ballot to init file from %" PRId64 " to %" PRId64 " OK",
- name(),
- old_ballot,
- _config.ballot);
+ LOG_INFO_PREFIX(
+ "update ballot to init file from {} to {} OK", old_ballot, _config.ballot);
} else {
LOG_WARNING("%s: update ballot to init file from %" PRId64 " to %" PRId64 " %s",
name(),
@@ -956,19 +944,18 @@ bool replica::update_local_configuration(const replica_configuration &config,
CHECK(false, "invalid execution path");
}
- LOG_INFO("%s: status change %s @ %" PRId64 " => %s @ %" PRId64 ", pre(%" PRId64 ", %" PRId64
- "), app(%" PRId64 ", %" PRId64 "), duration = %" PRIu64 " ms, %s",
- name(),
- enum_to_string(old_status),
- old_ballot,
- enum_to_string(status()),
- get_ballot(),
- _prepare_list->max_decree(),
- _prepare_list->last_committed_decree(),
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- _last_config_change_time_ms - oldTs,
- boost::lexical_cast<std::string>(_config).c_str());
+ LOG_INFO_PREFIX(
+ "status change {} @ {} => {} @ {}, pre({}, {}), app({}, {}), duration = {} ms, {}",
+ enum_to_string(old_status),
+ old_ballot,
+ enum_to_string(status()),
+ get_ballot(),
+ _prepare_list->max_decree(),
+ _prepare_list->last_committed_decree(),
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ _last_config_change_time_ms - oldTs,
+ boost::lexical_cast<std::string>(_config));
if (status() != old_status) {
bool is_closing =
@@ -977,7 +964,7 @@ bool replica::update_local_configuration(const replica_configuration &config,
_stub->notify_replica_state_update(config, is_closing);
if (is_closing) {
- LOG_INFO("%s: being close ...", name());
+ LOG_INFO_PREFIX("being close ...");
_stub->begin_close_replica(this);
return false;
}
@@ -1059,13 +1046,11 @@ void replica::on_config_sync(const app_info &info,
||
config.primary.is_invalid() // primary is dead (otherwise let primary remove this)
) {
- LOG_INFO("%s: downgrade myself as inactive is not transient, remote_config(%s)",
- name(),
- boost::lexical_cast<std::string>(config).c_str());
+ LOG_INFO_PREFIX("downgrade myself as inactive is not transient, remote_config({})",
+ boost::lexical_cast<std::string>(config));
_stub->remove_replica_on_meta_server(_app_info, config);
} else {
- LOG_INFO("%s: state is non-transient inactive, waiting primary to remove me",
- name());
+ LOG_INFO_PREFIX("state is non-transient inactive, waiting primary to remove me");
}
}
}
@@ -1113,11 +1098,7 @@ void replica::replay_prepare_list()
decree start = last_committed_decree() + 1;
decree end = _prepare_list->max_decree();
- LOG_INFO("%s: replay prepare list from %" PRId64 " to %" PRId64 ", ballot = %" PRId64,
- name(),
- start,
- end,
- get_ballot());
+ LOG_INFO_PREFIX("replay prepare list from {} to {}, ballot = {}", start, end, get_ballot());
for (decree decree = start; decree <= end; decree++) {
mutation_ptr old = _prepare_list->get_mutation_by_decree(decree);
@@ -1130,11 +1111,9 @@ void replica::replay_prepare_list()
} else {
mu->add_client_request(RPC_REPLICATION_WRITE_EMPTY, nullptr);
- LOG_INFO("%s: emit empty mutation %s with mutation_tid=%" PRIu64
- " when replay prepare list",
- name(),
- mu->name(),
- mu->tid());
+ LOG_INFO_PREFIX("emit empty mutation {} with mutation_tid={} when replay prepare list",
+ mu->name(),
+ mu->tid());
}
init_prepare(mu, true);
diff --git a/src/replica/replica_failover.cpp b/src/replica/replica_failover.cpp
index a00e62057..55beccc01 100644
--- a/src/replica/replica_failover.cpp
+++ b/src/replica/replica_failover.cpp
@@ -43,10 +43,7 @@ namespace replication {
void replica::handle_local_failure(error_code error)
{
- LOG_INFO("%s: handle local failure error %s, status = %s",
- name(),
- error.to_string(),
- enum_to_string(status()));
+ LOG_INFO_PREFIX("handle local failure error {}, status = {}", error, enum_to_string(status()));
if (status() == partition_status::PS_PRIMARY) {
_stub->remove_replica_on_meta_server(_app_info, _primary_states.membership);
@@ -85,7 +82,7 @@ void replica::handle_remote_failure(partition_status::type st,
}
break;
case partition_status::PS_POTENTIAL_SECONDARY: {
- LOG_INFO("%s: remove learner %s for remote failure", name(), node.to_string());
+ LOG_INFO_PREFIX("remove learner {} for remote failure", node);
// potential secondary failure does not lead to ballot change
// therefore, it is possible to have multiple exec here
_primary_states.learners.erase(node);
@@ -102,7 +99,7 @@ void replica::handle_remote_failure(partition_status::type st,
void replica::on_meta_server_disconnected()
{
- LOG_INFO("%s: meta server disconnected", name());
+ LOG_INFO_PREFIX("meta server disconnected");
auto old_status = status();
update_local_configuration_with_no_ballot_change(partition_status::PS_INACTIVE);
diff --git a/src/replica/replica_init.cpp b/src/replica/replica_init.cpp
index d54fe6fff..e9686572c 100644
--- a/src/replica/replica_init.cpp
+++ b/src/replica/replica_init.cpp
@@ -123,7 +123,7 @@ error_code replica::initialize_on_new()
error_code replica::initialize_on_load()
{
- LOG_INFO("%s: initialize replica on load, dir = %s", name(), _dir.c_str());
+ LOG_INFO_PREFIX("initialize replica on load, dir = {}", _dir);
if (!dsn::utils::filesystem::directory_exists(_dir)) {
LOG_ERROR("%s: cannot load replica, because dir %s is not exist", name(), _dir.c_str());
@@ -184,7 +184,7 @@ error_code replica::initialize_on_load()
err = rep->initialize_on_load();
if (err == ERR_OK) {
- LOG_INFO("%s: load replica succeed", rep->name());
+ LOG_INFO_F("{}: load replica succeed", rep->name());
return rep;
} else {
LOG_ERROR("%s: load replica failed, err = %s", rep->name(), err.to_string());
@@ -248,7 +248,7 @@ error_code replica::init_app_and_prepare_list(bool create_new)
_private_log = new mutation_log_private(
log_dir, _options->log_private_file_size_mb, get_gpid(), this);
- LOG_INFO("%s: plog_dir = %s", name(), log_dir.c_str());
+ LOG_INFO_PREFIX("plog_dir = {}", log_dir);
// sync valid_start_offset between app and logs
_stub->_log->set_valid_start_offset_on_open(
@@ -275,22 +275,18 @@ error_code replica::init_app_and_prepare_list(bool create_new)
uint64_t finish_time = dsn_now_ms();
if (err == ERR_OK) {
- LOG_INFO("%s: replay private log succeed, durable = %" PRId64
- ", committed = %" PRId64 ", "
- "max_prepared = %" PRId64 ", ballot = %" PRId64
- ", valid_offset_in_plog = %" PRId64 ", "
- "max_decree_in_plog = %" PRId64
- ", max_commit_on_disk_in_plog = %" PRId64 ", "
- "time_used = %" PRIu64 " ms",
- name(),
- _app->last_durable_decree(),
- _app->last_committed_decree(),
- max_prepared_decree(),
- get_ballot(),
- _app->init_info().init_offset_in_private_log,
- _private_log->max_decree(get_gpid()),
- _private_log->max_commit_on_disk(),
- finish_time - start_time);
+ LOG_INFO_PREFIX("replay private log succeed, durable = {}, committed = {}, "
+ "max_prepared = {}, ballot = {}, valid_offset_in_plog = {}, "
+ "max_decree_in_plog = {}, max_commit_on_disk_in_plog = {}, "
+ "time_used = {} ms",
+ _app->last_durable_decree(),
+ _app->last_committed_decree(),
+ max_prepared_decree(),
+ get_ballot(),
+ _app->init_info().init_offset_in_private_log,
+ _private_log->max_decree(get_gpid()),
+ _private_log->max_commit_on_disk(),
+ finish_time - start_time);
_private_log->check_valid_start_offset(
get_gpid(), _app->init_info().init_offset_in_private_log);
@@ -331,7 +327,7 @@ error_code replica::init_app_and_prepare_list(bool create_new)
_app->set_partition_version(_app_info.partition_count - 1);
if (nullptr == _private_log) {
- LOG_INFO("%s: clear private log, dir = %s", name(), log_dir.c_str());
+ LOG_INFO_PREFIX("clear private log, dir = {}", log_dir);
CHECK(dsn::utils::filesystem::remove_path(log_dir),
"Fail to delete directory {}",
log_dir);
@@ -341,7 +337,7 @@ error_code replica::init_app_and_prepare_list(bool create_new)
_private_log = new mutation_log_private(
log_dir, _options->log_private_file_size_mb, get_gpid(), this);
- LOG_INFO("%s: plog_dir = %s", name(), log_dir.c_str());
+ LOG_INFO_PREFIX("plog_dir = {}", log_dir);
err = _private_log->open(nullptr, [this](error_code err) {
tasking::enqueue(LPC_REPLICATION_ERROR,
@@ -450,10 +446,9 @@ bool replica::replay_mutation(mutation_ptr &mu, bool is_private)
void replica::set_inactive_state_transient(bool t)
{
if (status() == partition_status::PS_INACTIVE) {
- LOG_INFO("%s: set inactive_is_transient from %s to %s",
- name(),
- _inactive_is_transient ? "true" : "false",
- t ? "true" : "false");
+ LOG_INFO_PREFIX("set inactive_is_transient from {} to {}",
+ _inactive_is_transient ? "true" : "false",
+ t ? "true" : "false");
_inactive_is_transient = t;
}
}
diff --git a/src/replica/replica_learn.cpp b/src/replica/replica_learn.cpp
index 65e9143d1..3eecb9517 100644
--- a/src/replica/replica_learn.cpp
+++ b/src/replica/replica_learn.cpp
@@ -202,23 +202,21 @@ void replica::init_learn(uint64_t signature)
request.signature = _potential_secondary_states.learning_version;
_app->prepare_get_checkpoint(request.app_specific_learn_request);
- LOG_INFO("%s: init_learn[%016" PRIx64 "]: learnee = %s, learn_duration = %" PRIu64
- " ms, max_gced_decree = %" PRId64 ", local_committed_decree = %" PRId64 ", "
- "app_committed_decree = %" PRId64 ", app_durable_decree = %" PRId64
- ", current_learning_status = %s, total_copy_file_count = %" PRIu64
- ", total_copy_file_size = %" PRIu64 ", total_copy_buffer_size = %" PRIu64,
- name(),
- request.signature,
- _config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- request.max_gced_decree,
- last_committed_decree(),
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- enum_to_string(_potential_secondary_states.learning_status),
- _potential_secondary_states.learning_copy_file_count,
- _potential_secondary_states.learning_copy_file_size,
- _potential_secondary_states.learning_copy_buffer_size);
+ LOG_INFO_PREFIX("init_learn[{:#018x}]: learnee = {}, learn_duration = {} ms, max_gced_decree = "
+ "{}, local_committed_decree = {}, app_committed_decree = {}, "
+ "app_durable_decree = {}, current_learning_status = {}, total_copy_file_count "
+ "= {}, total_copy_file_size = {}, total_copy_buffer_size = {}",
+ request.signature,
+ _config.primary,
+ _potential_secondary_states.duration_ms(),
+ request.max_gced_decree,
+ last_committed_decree(),
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ enum_to_string(_potential_secondary_states.learning_status),
+ _potential_secondary_states.learning_copy_file_count,
+ _potential_secondary_states.learning_copy_file_size,
+ _potential_secondary_states.learning_copy_buffer_size);
dsn::message_ex *msg = dsn::message_ex::create_request(RPC_LEARN, 0, get_gpid().thread_hash());
dsn::marshall(msg, request);
@@ -412,22 +410,20 @@ void replica::on_learn(dsn::message_ex *msg, const learn_request &request)
response.state.__set_learn_start_decree(learn_start_decree);
bool delayed_replay_prepare_list = false;
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, remote_committed_decree = %" PRId64 ", "
- "remote_app_committed_decree = %" PRId64 ", local_committed_decree = %" PRId64 ", "
- "app_committed_decree = %" PRId64 ", app_durable_decree = %" PRId64 ", "
- "prepare_min_decree = %" PRId64
- ", prepare_list_count = %d, learn_start_decree = %" PRId64,
- name(),
- request.signature,
- request.learner.to_string(),
- request.last_committed_decree_in_prepare_list,
- request.last_committed_decree_in_app,
- local_committed_decree,
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- _prepare_list->min_decree(),
- _prepare_list->count(),
- learn_start_decree);
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, remote_committed_decree = {}, "
+ "remote_app_committed_decree = {}, local_committed_decree = {}, "
+ "app_committed_decree = {}, app_durable_decree = {}, "
+ "prepare_min_decree = {}, prepare_list_count = {}, learn_start_decree = {}",
+ request.signature,
+ request.learner,
+ request.last_committed_decree_in_prepare_list,
+ request.last_committed_decree_in_app,
+ local_committed_decree,
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ _prepare_list->min_decree(),
+ _prepare_list->count(),
+ learn_start_decree);
response.address = _stub->_primary_address;
response.prepare_start_decree = invalid_decree;
@@ -443,40 +439,34 @@ void replica::on_learn(dsn::message_ex *msg, const learn_request &request)
delayed_replay_prepare_list);
if (!should_learn_cache) {
if (learn_start_decree > _app->last_durable_decree()) {
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, choose to learn private logs, "
- "because learn_start_decree(%" PRId64 ") > _app->last_durable_decree(%" PRId64
- ")",
- name(),
- request.signature,
- request.learner.to_string(),
- learn_start_decree,
- _app->last_durable_decree());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, choose to learn private logs, "
+ "because learn_start_decree({}) > _app->last_durable_decree({})",
+ request.signature,
+ request.learner,
+ learn_start_decree,
+ _app->last_durable_decree());
_private_log->get_learn_state(get_gpid(), learn_start_decree, response.state);
response.type = learn_type::LT_LOG;
} else if (_private_log->get_learn_state(get_gpid(), learn_start_decree, response.state)) {
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, choose to learn private logs, "
- "because mutation_log::get_learn_state() returns true",
- name(),
- request.signature,
- request.learner.to_string());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, choose to learn private logs, "
+ "because mutation_log::get_learn_state() returns true",
+ request.signature,
+ request.learner);
response.type = learn_type::LT_LOG;
} else if (learn_start_decree < request.last_committed_decree_in_app + 1) {
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, choose to learn private logs, "
- "because learn_start_decree steps back for duplication",
- name(),
- request.signature,
- request.learner.to_string());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, choose to learn private logs, "
+ "because learn_start_decree steps back for duplication",
+ request.signature,
+ request.learner);
response.type = learn_type::LT_LOG;
} else {
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, choose to learn app, "
- "beacuse learn_start_decree(%" PRId64 ") <= _app->last_durable_decree(%" PRId64
- "), "
- "and mutation_log::get_learn_state() returns false",
- name(),
- request.signature,
- request.learner.to_string(),
- learn_start_decree,
- _app->last_durable_decree());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, choose to learn app, beacuse "
+ "learn_start_decree({}) <= _app->last_durable_decree({}), and "
+ "mutation_log::get_learn_state() returns false",
+ request.signature,
+ request.learner,
+ learn_start_decree,
+ _app->last_durable_decree());
response.type = learn_type::LT_APP;
response.state = learn_state();
}
@@ -486,13 +476,11 @@ void replica::on_learn(dsn::message_ex *msg, const learn_request &request)
if (response.state.files.size() > 0) {
auto &last_file = response.state.files.back();
if (last_file == learner_state.last_learn_log_file) {
- LOG_INFO(
- "%s: on_learn[%016" PRIx64
- "]: learner = %s, learn the same file %s repeatedly, hint to switch file",
- name(),
- request.signature,
- request.learner.to_string(),
- last_file.c_str());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, learn the same file {} "
+ "repeatedly, hint to switch file",
+ request.signature,
+ request.learner,
+ last_file);
_private_log->hint_switch_file();
} else {
learner_state.last_learn_log_file = last_file;
@@ -500,15 +488,14 @@ void replica::on_learn(dsn::message_ex *msg, const learn_request &request)
}
// it is safe to commit to last_committed_decree() now
response.state.to_decree_included = last_committed_decree();
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, learn private logs succeed, "
- "learned_meta_size = %u, learned_file_count = %u, "
- "to_decree_included = %" PRId64,
- name(),
- request.signature,
- request.learner.to_string(),
- response.state.meta.length(),
- static_cast<uint32_t>(response.state.files.size()),
- response.state.to_decree_included);
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, learn private logs succeed, "
+ "learned_meta_size = {}, learned_file_count = {}, to_decree_included = "
+ "{}",
+ request.signature,
+ request.learner,
+ response.state.meta.length(),
+ response.state.files.size(),
+ response.state.to_decree_included);
} else {
::dsn::error_code err = _app->get_checkpoint(
learn_start_decree, request.app_specific_learn_request, response.state);
@@ -524,14 +511,13 @@ void replica::on_learn(dsn::message_ex *msg, const learn_request &request)
} else {
response.base_local_dir = _app->data_dir();
response.__set_replica_disk_tag(get_replica_disk_tag());
- LOG_INFO(
- "%s: on_learn[%016" PRIx64 "]: learner = %s, get app learn state succeed, "
- "learned_meta_size = %u, learned_file_count = %u, learned_to_decree = %" PRId64,
- name(),
+ LOG_INFO_PREFIX(
+ "on_learn[{:#018x}]: learner = {}, get app learn state succeed, "
+ "learned_meta_size = {}, learned_file_count = {}, learned_to_decree = {}",
request.signature,
- request.learner.to_string(),
+ request.learner,
response.state.meta.length(),
- static_cast<uint32_t>(response.state.files.size()),
+ response.state.files.size(),
response.state.to_decree_included);
}
}
@@ -607,11 +593,10 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
}
if (resp.config.ballot > get_ballot()) {
- LOG_INFO("%s: on_learn_reply[%016" PRIx64
- "]: learnee = %s, update configuration because ballot have changed",
- name(),
- req.signature,
- resp.config.primary.to_string());
+ LOG_INFO_PREFIX("on_learn_reply[{:#018x}]: learnee = {}, update configuration because "
+ "ballot have changed",
+ req.signature,
+ resp.config.primary);
CHECK(update_local_configuration(resp.config), "");
}
@@ -721,12 +706,11 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
return;
} else {
_potential_secondary_states.learn_app_concurrent_count_increased = true;
- LOG_INFO("%s: on_learn_reply[%016" PRIx64
- "]: learnee = %s, ++learn_app_concurrent_count = %d",
- name(),
- _potential_secondary_states.learning_version,
- _config.primary.to_string(),
- _stub->_learn_app_concurrent_count.load());
+ LOG_INFO_PREFIX(
+ "on_learn_reply[{:#018x}]: learnee = {}, ++learn_app_concurrent_count = {}",
+ _potential_secondary_states.learning_version,
+ _config.primary,
+ _stub->_learn_app_concurrent_count.load());
}
}
@@ -770,14 +754,12 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
// reset preparelist
_potential_secondary_states.learning_start_prepare_decree = resp.prepare_start_decree;
_prepare_list->truncate(_app->last_committed_decree());
- LOG_INFO("%s: on_learn_reply[%016" PRIx64
- "]: learnee = %s, truncate prepare list, local_committed_decree = %" PRId64
- ", current_learning_status = %s",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _app->last_committed_decree(),
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("on_learn_reply[{:#018x}]: learnee = {}, truncate prepare list, "
+ "local_committed_decree = {}, current_learning_status = {}",
+ req.signature,
+ resp.config.primary,
+ _app->last_committed_decree(),
+ enum_to_string(_potential_secondary_states.learning_status));
// persist incoming mutations into private log and apply them to prepare-list
std::pair<decree, decree> cache_range;
@@ -803,13 +785,12 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
_prepare_list->get_mutation_by_decree(mu->data.header.decree);
if (existing_mutation != nullptr &&
existing_mutation->data.header.ballot > mu->data.header.ballot) {
- LOG_INFO("%s: on_learn_reply[%016" PRIx64 "]: learnee = %s, "
- "mutation(%s) exist on the learner with larger ballot %" PRId64 "",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- mu->name(),
- existing_mutation->data.header.ballot);
+ LOG_INFO_PREFIX("on_learn_reply[{:#018x}]: learnee = {}, mutation({}) exist on "
+ "the learner with larger ballot {}",
+ req.signature,
+ resp.config.primary,
+ mu->name(),
+ existing_mutation->data.header.ballot);
} else {
_prepare_list->prepare(mu, partition_status::PS_POTENTIAL_SECONDARY);
}
@@ -821,20 +802,17 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
}
}
- LOG_INFO("%s: on_learn_reply[%016" PRIx64 "]: learnee = %s, learn_duration = %" PRIu64
- " ms, "
- "apply cache done, prepare_cache_range = <%" PRId64 ", %" PRId64 ">, "
- "local_committed_decree = %" PRId64 ", app_committed_decree = %" PRId64
- ", current_learning_status = %s",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- cache_range.first,
- cache_range.second,
- last_committed_decree(),
- _app->last_committed_decree(),
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("on_learn_reply[{:#018x}]: learnee = {}, learn_duration = {} ms, apply "
+ "cache done, prepare_cache_range = <{}, {}>, local_committed_decree = {}, "
+ "app_committed_decree = {}, current_learning_status = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ cache_range.first,
+ cache_range.second,
+ last_committed_decree(),
+ _app->last_committed_decree(),
+ enum_to_string(_potential_secondary_states.learning_status));
// further states are synced using 2pc, and we must commit now as those later 2pc messages
// thinks they should
@@ -894,14 +872,13 @@ void replica::on_learn_reply(error_code err, learn_request &&req, learn_response
}
bool high_priority = (resp.type == learn_type::LT_APP ? false : true);
- LOG_INFO("%s: on_learn_reply[%016" PRIx64 "]: learnee = %s, learn_duration = %" PRIu64
- " ms, start to copy remote files, copy_file_count = %d, priority = %s",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- static_cast<int>(resp.state.files.size()),
- high_priority ? "high" : "low");
+ LOG_INFO_PREFIX("on_learn_reply[{:#018x}]: learnee = {}, learn_duration = {} ms, start to "
+ "copy remote files, copy_file_count = {}, priority = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ resp.state.files.size(),
+ high_priority ? "high" : "low");
_potential_secondary_states.learn_remote_files_task = _stub->_nfs->copy_remote_files(
resp.config.primary,
@@ -960,12 +937,10 @@ bool replica::prepare_cached_learn_state(const learn_request &request,
// learning response msg.
delayed_replay_prepare_list = true;
- LOG_INFO("%s: on_learn[%016" PRIx64
- "]: learner = %s, set prepare_start_decree = %" PRId64,
- name(),
- request.signature,
- request.learner.to_string(),
- local_committed_decree + 1);
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, set prepare_start_decree = {}",
+ request.signature,
+ request.learner,
+ local_committed_decree + 1);
}
response.prepare_start_decree = learner_state.prepare_start_decree;
@@ -986,16 +961,15 @@ bool replica::prepare_cached_learn_state(const learn_request &request,
}
response.type = learn_type::LT_CACHE;
response.state.meta = writer.get_buffer();
- LOG_INFO("%s: on_learn[%016" PRIx64 "]: learner = %s, learn mutation cache succeed, "
- "learn_start_decree = %" PRId64 ", prepare_start_decree = %" PRId64 ", "
- "learn_mutation_count = %d, learn_data_size = %d",
- name(),
- request.signature,
- request.learner.to_string(),
- learn_start_decree,
- response.prepare_start_decree,
- count,
- response.state.meta.length());
+ LOG_INFO_PREFIX("on_learn[{:#018x}]: learner = {}, learn mutation cache succeed, "
+ "learn_start_decree = {}, prepare_start_decree = {}, learn_mutation_count "
+ "= {}, learn_data_size = {}",
+ request.signature,
+ request.learner,
+ learn_start_decree,
+ response.prepare_start_decree,
+ count,
+ response.state.meta.length());
return true;
}
return false;
@@ -1012,36 +986,32 @@ void replica::on_copy_remote_state_completed(error_code err,
decree old_app_committed = _app->last_committed_decree();
decree old_app_durable = _app->last_durable_decree();
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, "
- "copy remote state done, err = %s, copy_file_count = %d, "
- "copy_file_size = %" PRIu64 ", copy_time_used = %" PRIu64 " ms, "
- "local_committed_decree = %" PRId64 ", app_committed_decree = %" PRId64
- ", app_durable_decree = %" PRId64 ", "
- "prepare_start_decree = %" PRId64 ", current_learning_status = %s",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- err.to_string(),
- static_cast<int>(resp.state.files.size()),
- static_cast<uint64_t>(size),
- _potential_secondary_states.duration_ms() - copy_start_time,
- last_committed_decree(),
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- resp.prepare_start_decree,
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, learn_duration = {} "
+ "ms, copy remote state done, err = {}, copy_file_count = {}, copy_file_size = "
+ "{}, copy_time_used = {} ms, local_committed_decree = {}, app_committed_decree "
+ "= {}, app_durable_decree = {}, prepare_start_decree = {}, "
+ "current_learning_status = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ err,
+ resp.state.files.size(),
+ size,
+ _potential_secondary_states.duration_ms() - copy_start_time,
+ last_committed_decree(),
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ resp.prepare_start_decree,
+ enum_to_string(_potential_secondary_states.learning_status));
if (resp.type == learn_type::LT_APP) {
--_stub->_learn_app_concurrent_count;
_potential_secondary_states.learn_app_concurrent_count_increased = false;
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, --learn_app_concurrent_count = %d",
- name(),
- _potential_secondary_states.learning_version,
- _config.primary.to_string(),
- _stub->_learn_app_concurrent_count.load());
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, "
+ "--learn_app_concurrent_count = {}",
+ _potential_secondary_states.learning_version,
+ _config.primary,
+ _stub->_learn_app_concurrent_count.load());
}
if (err == ERR_OK) {
@@ -1084,16 +1054,14 @@ void replica::on_copy_remote_state_completed(error_code err,
// the learn_start_decree will be set to 0, which makes learner to learn from
// scratch
CHECK_LE(_app->last_committed_decree(), resp.last_committed_decree);
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, "
- "checkpoint duration = %" PRIu64
- " ns, apply checkpoint succeed, app_committed_decree = %" PRId64,
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- dsn_now_ns() - start_ts,
- _app->last_committed_decree());
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, "
+ "learn_duration = {} ms, checkpoint duration = {} ns, apply "
+ "checkpoint succeed, app_committed_decree = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ dsn_now_ns() - start_ts,
+ _app->last_committed_decree());
} else {
LOG_ERROR("%s: on_copy_remote_state_completed[%016" PRIx64
"]: learnee = %s, learn_duration = %" PRIu64 " ms, "
@@ -1112,17 +1080,14 @@ void replica::on_copy_remote_state_completed(error_code err,
auto start_ts = dsn_now_ns();
err = apply_learned_state_from_private_log(lstate);
if (err == ERR_OK) {
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, "
- "apply_log_duration = %" PRIu64
- " ns, apply learned state from private log "
- "succeed, app_committed_decree = %" PRId64,
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- dsn_now_ns() - start_ts,
- _app->last_committed_decree());
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, "
+ "learn_duration = {} ms, apply_log_duration = {} ns, apply learned "
+ "state from private log succeed, app_committed_decree = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ dsn_now_ns() - start_ts,
+ _app->last_committed_decree());
} else {
LOG_ERROR("%s: on_copy_remote_state_completed[%016" PRIx64
"]: learnee = %s, learn_duration = %" PRIu64 " ms, "
@@ -1140,32 +1105,26 @@ void replica::on_copy_remote_state_completed(error_code err,
// reset prepare list to make it catch with app
_prepare_list->reset(_app->last_committed_decree());
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64
- " ms, apply checkpoint/log done, err = %s, "
- "last_prepared_decree = (%" PRId64 " => %" PRId64 "), "
- "last_committed_decree = (%" PRId64 " => %" PRId64 "), "
- "app_committed_decree = (%" PRId64 " => %" PRId64 "), "
- "app_durable_decree = (%" PRId64 " => %" PRId64 "), "
- "remote_committed_decree = %" PRId64 ", "
- "prepare_start_decree = %" PRId64 ", "
- "current_learning_status = %s",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- err.to_string(),
- old_prepared,
- last_prepared_decree(),
- old_committed,
- last_committed_decree(),
- old_app_committed,
- _app->last_committed_decree(),
- old_app_durable,
- _app->last_durable_decree(),
- resp.last_committed_decree,
- resp.prepare_start_decree,
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, learn_duration = "
+ "{} ms, apply checkpoint/log done, err = {}, last_prepared_decree = ({} => "
+ "{}), last_committed_decree = ({} => {}), app_committed_decree = ({} => "
+ "{}), app_durable_decree = ({} => {}), remote_committed_decree = {}, "
+ "prepare_start_decree = {}, current_learning_status = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ err,
+ old_prepared,
+ last_prepared_decree(),
+ old_committed,
+ last_committed_decree(),
+ old_app_committed,
+ _app->last_committed_decree(),
+ old_app_durable,
+ _app->last_durable_decree(),
+ resp.last_committed_decree,
+ resp.prepare_start_decree,
+ enum_to_string(_potential_secondary_states.learning_status));
}
// if catch-up done, do flush to enable all learned state is durable
@@ -1175,16 +1134,15 @@ void replica::on_copy_remote_state_completed(error_code err,
_app->last_committed_decree() > _app->last_durable_decree()) {
err = background_sync_checkpoint();
- LOG_INFO("%s: on_copy_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, flush done, err = %s, "
- "app_committed_decree = %" PRId64 ", app_durable_decree = %" PRId64 "",
- name(),
- req.signature,
- resp.config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- err.to_string(),
- _app->last_committed_decree(),
- _app->last_durable_decree());
+ LOG_INFO_PREFIX("on_copy_remote_state_completed[{:#018x}]: learnee = {}, learn_duration = "
+ "{} ms, flush done, err = {}, app_committed_decree = {}, "
+ "app_durable_decree = {}",
+ req.signature,
+ resp.config.primary,
+ _potential_secondary_states.duration_ms(),
+ err,
+ _app->last_committed_decree(),
+ _app->last_durable_decree());
if (err == ERR_OK) {
CHECK_EQ(_app->last_committed_decree(), _app->last_durable_decree());
@@ -1223,19 +1181,17 @@ void replica::on_learn_remote_state_completed(error_code err)
return;
}
- LOG_INFO("%s: on_learn_remote_state_completed[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, err = %s, "
- "local_committed_decree = %" PRId64 ", app_committed_decree = %" PRId64
- ", app_durable_decree = %" PRId64 ", current_learning_status = %s",
- name(),
- _potential_secondary_states.learning_version,
- _config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- err.to_string(),
- last_committed_decree(),
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("on_learn_remote_state_completed[{:#018x}]: learnee = {}, learn_duration = {} "
+ "ms, err = {}, local_committed_decree = {}, app_committed_decree = {}, "
+ "app_durable_decree = {}, current_learning_status = {}",
+ _potential_secondary_states.learning_version,
+ _config.primary,
+ _potential_secondary_states.duration_ms(),
+ err,
+ last_committed_decree(),
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ enum_to_string(_potential_secondary_states.learning_status));
_potential_secondary_states.learning_round_is_running = false;
@@ -1305,18 +1261,16 @@ void replica::notify_learn_completion()
report.learner_status_ = _potential_secondary_states.learning_status;
report.node = _stub->_primary_address;
- LOG_INFO("%s: notify_learn_completion[%016" PRIx64 "]: learnee = %s, "
- "learn_duration = %" PRIu64 " ms, local_committed_decree = %" PRId64 ", "
- "app_committed_decree = %" PRId64 ", app_durable_decree = %" PRId64
- ", current_learning_status = %s",
- name(),
- _potential_secondary_states.learning_version,
- _config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- last_committed_decree(),
- _app->last_committed_decree(),
- _app->last_durable_decree(),
- enum_to_string(_potential_secondary_states.learning_status));
+ LOG_INFO_PREFIX("notify_learn_completion[{:#018x}]: learnee = {}, learn_duration = {} ms, "
+ "local_committed_decree = {}, app_committed_decree = {}, app_durable_decree = "
+ "{}, current_learning_status = {}",
+ _potential_secondary_states.learning_version,
+ _config.primary,
+ _potential_secondary_states.duration_ms(),
+ last_committed_decree(),
+ _app->last_committed_decree(),
+ _app->last_durable_decree(),
+ enum_to_string(_potential_secondary_states.learning_status));
if (_potential_secondary_states.completion_notify_task != nullptr) {
_potential_secondary_states.completion_notify_task->cancel(false);
@@ -1340,12 +1294,11 @@ void replica::on_learn_completion_notification(const group_check_response &repor
{
_checker.only_one_thread_access();
- LOG_INFO("%s: on_learn_completion_notification[%016" PRIx64
- "]: learner = %s, learning_status = %s",
- name(),
- report.learner_signature,
- report.node.to_string(),
- enum_to_string(report.learner_status_));
+ LOG_INFO_PREFIX(
+ "on_learn_completion_notification[{:#018x}]: learner = {}, learning_status = {}",
+ report.learner_signature,
+ report.node,
+ enum_to_string(report.learner_status_));
if (status() != partition_status::PS_PRIMARY) {
response.err = (partition_status::PS_INACTIVE == status() && _inactive_is_transient)
@@ -1407,13 +1360,12 @@ void replica::on_learn_completion_notification_reply(error_code err,
return;
}
- LOG_INFO("%s: on_learn_completion_notification_reply[%016" PRIx64
- "]: learnee = %s, learn_duration = %" PRIu64 " ms, response_err = %s",
- name(),
- report.learner_signature,
- _config.primary.to_string(),
- _potential_secondary_states.duration_ms(),
- resp.err.to_string());
+ LOG_INFO_PREFIX("on_learn_completion_notification_reply[{:#018x}]: learnee = {}, "
+ "learn_duration = {} ms, response_err = {}",
+ report.learner_signature,
+ _config.primary,
+ _potential_secondary_states.duration_ms(),
+ resp.err);
if (resp.err != ERR_OK) {
if (resp.err == ERR_INACTIVE_STATE) {
diff --git a/src/replica/replica_restore.cpp b/src/replica/replica_restore.cpp
index a40a10733..a39ed483f 100644
--- a/src/replica/replica_restore.cpp
+++ b/src/replica/replica_restore.cpp
@@ -66,7 +66,7 @@ bool replica::remove_useless_file_under_chkpt(const std::string &chkpt_dir,
LOG_ERROR("%s: remove useless file(%s) failed", name(), pair.second.c_str());
return false;
}
- LOG_INFO("%s: remove useless file(%s) succeed", name(), pair.second.c_str());
+ LOG_INFO_PREFIX("remove useless file({}) succeed", pair.second);
}
return true;
}
@@ -400,7 +400,7 @@ dsn::error_code replica::skip_restore_partition(const std::string &restore_dir)
// it because we use restore_dir to tell storage engine that start an app from restore
if (utils::filesystem::remove_path(restore_dir) &&
utils::filesystem::create_directory(restore_dir)) {
- LOG_INFO("%s: clear restore_dir(%s) succeed", name(), restore_dir.c_str());
+ LOG_INFO_PREFIX("clear restore_dir({}) succeed", restore_dir);
_restore_progress.store(cold_backup_constant::PROGRESS_FINISHED);
return ERR_OK;
} else {
@@ -430,7 +430,7 @@ void replica::tell_meta_to_restore_rollback()
configuration_drop_app_response response;
::dsn::unmarshall(resp, response);
if (response.err == ERR_OK) {
- LOG_INFO("restore rolling backup succeed");
+ LOG_INFO_PREFIX("restore rolling backup succeed");
return;
} else {
tell_meta_to_restore_rollback();
diff --git a/src/replica/test/mock_utils.h b/src/replica/test/mock_utils.h
index 10f9d2a82..c51746b17 100644
--- a/src/replica/test/mock_utils.h
+++ b/src/replica/test/mock_utils.h
@@ -204,9 +204,9 @@ public:
void generate_backup_checkpoint(cold_backup_context_ptr backup_context) override
{
if (backup_context->status() != ColdBackupCheckpointing) {
- LOG_INFO("%s: ignore generating backup checkpoint because backup_status = %s",
- backup_context->name,
- cold_backup_status_to_string(backup_context->status()));
+ LOG_INFO_F("{}: ignore generating backup checkpoint because backup_status = {}",
+ backup_context->name,
+ cold_backup_status_to_string(backup_context->status()));
backup_context->ignore_checkpoint();
return;
}
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pegasus.apache.org
For additional commands, e-mail: commits-help@pegasus.apache.org