Skip to content

spring-util: SHiP log inspection/repair/split/merge tooling + nodeos state-history-force-write #1895

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
heifner wants to merge 1 commit into
base: main
Choose a base branch
from
Open

spring-util: SHiP log inspection/repair/split/merge tooling + nodeos state-history-force-write #1895

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions libraries/state_history/CMakeLists.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ file(GLOB HEADERS "include/eosio/state-history/*.hpp")
add_library( state_history
abi.cpp
create_deltas.cpp
log_utils.cpp
trace_converter.cpp
${HEADERS}
)
Expand Down
56 changes: 49 additions & 7 deletions libraries/state_history/include/eosio/state_history/log.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,9 +118,14 @@ class state_history_log {
state_history_log(state_history_log&&) = default;
state_history_log& operator=(state_history_log&&) = default;

/**
* @param force_write when set, an index that disagrees with its log is regenerated instead of
* being a fatal error (the log itself still auto-recovers exactly as before)
*/
state_history_log(const std::filesystem::path& log_dir_and_stem,
non_local_get_block_id_func non_local_get_block_id = no_non_local_get_block_id_func,
const std::optional<state_history::prune_config>& prune_conf = std::nullopt) :
const std::optional<state_history::prune_config>& prune_conf = std::nullopt,
bool force_write = false) :
prune_config(prune_conf), non_local_get_block_id(non_local_get_block_id),
log(std::filesystem::path(log_dir_and_stem).replace_extension("log")),
index(std::filesystem::path(log_dir_and_stem).replace_extension("index")) {
Expand All @@ -135,7 +140,19 @@ class state_history_log {

check_log_on_init();
check_index_on_init();
check_log_and_index_on_init();
try {
check_log_and_index_on_init();
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
if(!force_write)
throw;
wlog("${name} disagrees with its log (${e}); force-write is set so it will be regenerated",
("name", index.display_path())("e", e.what()));
index.resize(0);
check_index_on_init();
check_log_and_index_on_init();
}

//check for conversions to/from pruned log, as long as log contains something
if(!empty()) {
Expand Down Expand Up @@ -171,8 +188,18 @@ class state_history_log {

const size_t first_data_pos = get_pos(_begin_block);
const size_t last_data_pos = log.size();
if(last_data_pos - first_data_pos < *prune_config->vacuum_on_close)
vacuum();
//vacuum-on-close is a best-effort space reclamation; the log is fully valid whether or not it
// runs. Never let it throw out of the destructor (which would std::terminate): this also keeps
// force-write's head_log.reset() safe when it sets a damaged pruned log aside.
try {
if(last_data_pos - first_data_pos < *prune_config->vacuum_on_close)
vacuum();
} catch(const std::exception& e) {
wlog("vacuum-on-close of ${name} failed (${e}); leaving the log un-vacuumed",
("name", log.display_path())("e", e.what()));
} catch(...) {
wlog("vacuum-on-close of ${name} failed; leaving the log un-vacuumed", ("name", log.display_path()));
}
}

// begin end
Expand Down Expand Up @@ -221,14 +248,29 @@ class state_history_log {
EOS_ASSERT(block_num <= _end_block, chain::plugin_exception, "block ${b} skips over block ${e} in ${name}", ("b", block_num)("e", _end_block)("name", log.display_path()));
EOS_ASSERT(block_num >= _index_begin_block, chain::plugin_exception, "block ${b} is before start block ${s} of ${name}", ("b", block_num)("s", _begin_block)("name", log.display_path()));
if(block_num == _end_block) //appending at the end of known blocks; can shortcut some checks since we have last_block_id readily available
EOS_ASSERT(prev_id == last_block_id, chain::plugin_exception, "missed a fork change in ${name}", ("name", log.display_path()));
EOS_ASSERT(prev_id == last_block_id, chain::plugin_exception,
"missed a fork change in ${name}; appending block ${b} with previous id ${pid} but the log's last "
"entry is block ${lb} with id ${lid}",
("name", log.display_path())("b", block_num)("pid", prev_id)("lb", _end_block - 1)("lid", last_block_id));
else { //seeing a block num we've seen before OR first block in the log; prepare some extra checks
//find the previous block id as a sanity check. This might not be in our log due to log splitting. It also might not be present at all if this is the first
// block written, so don't require this lookup to succeed, just require the id to match if the lookup succeeded.
if(std::optional<chain::block_id_type> local_id_found = get_block_id(block_num-1))
EOS_ASSERT(local_id_found == prev_id, chain::plugin_exception, "missed a fork change in ${name}", ("name", log.display_path()));
//spelling out both ids and the recorded id's own block number makes a damaged index distinguishable
// from a genuine fork at a glance: an id for some unrelated block means the index is misdirecting reads
EOS_ASSERT(local_id_found == prev_id, chain::plugin_exception,
"missed a fork change in ${name}; block ${b} has previous id ${pid} but the index resolves "
"block ${pb} to id ${fid}, an id for block ${fb} (a block number mismatch means a corrupt "
"index, not a fork; verify with 'spring-util ship-log block-id' and rebuild with "
"'spring-util ship-log make-index')",
("name", log.display_path())("b", block_num)("pid", prev_id)("pb", block_num - 1)
("fid", *local_id_found)("fb", chain::block_header::num_from_id(*local_id_found)));
else if(std::optional<chain::block_id_type> non_local_id_found = non_local_get_block_id(block_num-1))
EOS_ASSERT(non_local_id_found == prev_id, chain::plugin_exception, "missed a fork change in ${name}", ("name", log.display_path()));
EOS_ASSERT(non_local_id_found == prev_id, chain::plugin_exception,
"missed a fork change in ${name}; block ${b} has previous id ${pid} but block ${pb} is "
"recorded as ${fid} elsewhere in the catalog or chain",
("name", log.display_path())("b", block_num)("pid", prev_id)("pb", block_num - 1)
("fid", *non_local_id_found));
//we don't want to re-write blocks that we already have, so check if the existing block_id recorded in the log matches and if so, bail
if(get_block_id(block_num) == id)
return;
Expand Down
163 changes: 149 additions & 14 deletions libraries/state_history/include/eosio/state_history/log_catalog.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

#include <filesystem>
#include <regex>
#include <string_view>

#include <boost/multi_index_container.hpp>
#include <boost/multi_index/ordered_index.hpp>
Expand All @@ -16,6 +17,10 @@ namespace eosio::state_history {

using namespace boost::multi_index;

/// suffix given to bundles force-write moves aside; deliberately matches neither the retained-file
/// regex nor any name this code opens, so orphaned bundles are inert until an operator acts on them
inline constexpr std::string_view orphaned_bundle_infix = "-corrupt-";

struct catalogued_log_file {
chain::block_num_type begin_block_num = 0;
chain::block_num_type end_block_num = 0;
Expand Down Expand Up @@ -44,6 +49,13 @@ class log_catalog {

const state_history_log::non_local_get_block_id_func non_local_get_block_id;

//when set, conditions that would otherwise prevent the node from running -- a head log that
// fails its startup checks or cannot accept the next block, or an inconsistent retained set --
// are handled by moving the offending bundle aside (never deleting data) and continuing with a
// fresh log. see the state-history-force-write option.
const bool force_write = false;
std::optional<state_history::prune_config> head_log_prune_conf;

struct by_mru {};
typedef multi_index_container<
catalogued_log_file,
Expand All @@ -63,14 +75,17 @@ class log_catalog {
log_catalog& operator=(log_catalog&) = delete;

log_catalog(const std::filesystem::path& log_dir, const state_history::state_history_log_config& config, const std::string& log_name,
state_history_log::non_local_get_block_id_func non_local_get_block_id = state_history_log::no_non_local_get_block_id_func) :
non_local_get_block_id(non_local_get_block_id), head_log_path_and_basename(log_dir / log_name) {
state_history_log::non_local_get_block_id_func non_local_get_block_id = state_history_log::no_non_local_get_block_id_func,
bool force_write = false) :
non_local_get_block_id(non_local_get_block_id), force_write(force_write),
head_log_path_and_basename(log_dir / log_name) {
std::visit(chain::overloaded {
[this](const std::monostate&) {
open_head_log();
},
[this](const state_history::prune_config& prune) {
open_head_log(prune);
head_log_prune_conf = prune;
open_head_log();
},
[this, &log_dir, &log_name](const state_history::partition_config& partition_config) {
open_head_log();
Expand All @@ -83,6 +98,62 @@ class log_catalog {

template <typename F>
void pack_and_write_entry(const chain::block_id_type& id, const chain::block_id_type& prev_id, F&& pack_to) {
if(!force_write)
return do_pack_and_write_entry(id, prev_id, pack_to);

//force-write: never let the existing logs stop the node from running. First try the normal
// write; if the head log cannot accept the block (a gap after a snapshot restore, a missed
// fork change from divergent history, ...), move the head bundle aside and retry with a fresh
// one. The retry can unrotate a retained bundle into the head and fail on it for the same
// reason; in that case the whole catalog is moved aside and writing restarts from scratch.
// Bundles are renamed (kept on disk), never deleted.
try {
return do_pack_and_write_entry(id, prev_id, pack_to);
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
elog("Failed to write block ${b} to ${name}.log (${e}); state-history-force-write is set: moving the head "
"log aside and retrying with a fresh one",
("b", chain::block_header::num_from_id(id))("name", head_log_path_and_basename.string())("e", e.what()));
}
head_log.reset();
orphan_bundle(head_log_path_and_basename);
open_head_log();
try {
return do_pack_and_write_entry(id, prev_id, pack_to);
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
elog("Still failed to write block ${b} (${e}); moving all retained logs aside and starting over",
("b", chain::block_header::num_from_id(id))("e", e.what()));
}
while(!retained_log_files.empty()) {
catalog_t::node_type n = retained_log_files.extract(retained_log_files.begin());
n.value().log.reset();
orphan_bundle(n.value().path_and_basename);
}
head_log.reset();
orphan_bundle(head_log_path_and_basename);
open_head_log();
//With no retained logs and an empty head log there is nothing left in the catalog for the write
// to conflict with. It can still be rejected by a disagreement with the chain itself -- the
// non-local block-id lookup says block-1 has an id other than prev_id -- which no amount of log
// rewriting can resolve. Honor force-write's promise to keep the node running by skipping the
// block (it cannot be represented in the state history) rather than throwing.
try {
do_pack_and_write_entry(id, prev_id, pack_to);
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
elog("state-history-force-write could not write block ${b} even into a fresh empty log (${e}); the block "
"conflicts with the chain rather than the log, so it is skipped and will not be served in the state "
"history", ("b", chain::block_header::num_from_id(id))("e", e.what()));
}
}

private:
template <typename F>
void do_pack_and_write_entry(const chain::block_id_type& id, const chain::block_id_type& prev_id, F&& pack_to) {
const uint32_t block_num = chain::block_header::num_from_id(id);

if(!retained_log_files.empty()) {
Expand Down Expand Up @@ -120,6 +191,7 @@ class log_catalog {
rotate_logs();
}

public:
std::optional<ship_log_entry> get_entry(uint32_t block_num) {
return call_for_log(block_num, [&](state_history_log&& l) {
return l.get_entry(block_num);
Expand Down Expand Up @@ -206,25 +278,50 @@ class log_catalog {

const std::filesystem::path path_and_basename = dir_entry.path().parent_path() / dir_entry.path().stem();

state_history_log log(path_and_basename, [](chain::block_num_type) {return std::nullopt;});
if(log.empty())
continue;
const auto [begin_bnum, end_bnum] = log.block_range();
retained_log_files.emplace(begin_bnum, end_bnum, path_and_basename);
try {
state_history_log log(path_and_basename, [](chain::block_num_type) {return std::nullopt;});
if(log.empty())
continue;
const auto [begin_bnum, end_bnum] = log.block_range();
retained_log_files.emplace(begin_bnum, end_bnum, path_and_basename);
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
if(!force_write)
throw;
elog("Failed to open retained log ${name}.log (${e}); state-history-force-write is set: leaving it out "
"of the catalog, its blocks will not be served",
("name", path_and_basename.string())("e", e.what()));
}
}

//a gap or overlap between retained files is normally fatal; with force-write the files stay in
// place and the catalog simply cannot serve the missing blocks
if(retained_log_files.size() > 1)
for(catalog_t::iterator it = retained_log_files.begin(); it != std::prev(retained_log_files.end()); ++it)
EOS_ASSERT(it->end_block_num == std::next(it)->begin_block_num, chain::plugin_exception,
for(catalog_t::iterator it = retained_log_files.begin(); it != std::prev(retained_log_files.end()); ++it) {
if(it->end_block_num == std::next(it)->begin_block_num)
continue;
EOS_ASSERT(force_write, chain::plugin_exception,
"retained log file ${sf}.log has block range ${sb}-${se} but ${ef}.log has range ${eb}-${ee} which results in a hole",
("sf", it->path_and_basename.native())("sb", it->begin_block_num)("se", it->end_block_num-1)
("ef", std::next(it)->path_and_basename.native())("eb", std::next(it)->begin_block_num)("ee", std::next(it)->end_block_num-1));
elog("retained log file ${sf}.log has block range ${sb}-${se} but ${ef}.log has range ${eb}-${ee} which "
"results in a hole; state-history-force-write is set: blocks in the hole will not be served",
("sf", it->path_and_basename.native())("sb", it->begin_block_num)("se", it->end_block_num-1)
("ef", std::next(it)->path_and_basename.native())("eb", std::next(it)->begin_block_num)("ee", std::next(it)->end_block_num-1));
}

if(!retained_log_files.empty() && !head_log->empty())
EOS_ASSERT(retained_log_files.rbegin()->end_block_num == head_log->block_range().first, chain::plugin_exception,
if(!retained_log_files.empty() && !head_log->empty() &&
retained_log_files.rbegin()->end_block_num != head_log->block_range().first) {
EOS_ASSERT(force_write, chain::plugin_exception,
"retained log file ${sf}.log has block range ${sb}-${se} but head log has range ${eb}-${ee} which results in a hole",
("sf", retained_log_files.rbegin()->path_and_basename.native())("sb", retained_log_files.rbegin()->begin_block_num)("se", retained_log_files.rbegin()->end_block_num-1)
("eb", head_log->block_range().first)("ee", head_log->block_range().second-1));
elog("retained log file ${sf}.log has block range ${sb}-${se} but head log has range ${eb}-${ee} which "
"results in a hole; state-history-force-write is set: blocks in the hole will not be served",
("sf", retained_log_files.rbegin()->path_and_basename.native())("sb", retained_log_files.rbegin()->begin_block_num)("se", retained_log_files.rbegin()->end_block_num-1)
("eb", head_log->block_range().first)("ee", head_log->block_range().second-1));
}
}

void unrotate_log() {
Expand Down Expand Up @@ -276,8 +373,46 @@ class log_catalog {
}
}

void open_head_log(std::optional<state_history::prune_config> prune_config = std::nullopt) {
head_log.emplace(head_log_path_and_basename, non_local_get_block_id, prune_config);
void open_head_log() {
try {
head_log.emplace(head_log_path_and_basename, non_local_get_block_id, head_log_prune_conf, force_write);
} catch(const std::bad_alloc&) {
throw;
} catch(const std::exception& e) {
if(!force_write)
throw;
elog("Failed to open ${name}.log (${e}); state-history-force-write is set: moving it aside and starting a "
"fresh log", ("name", head_log_path_and_basename.string())("e", e.what()));
head_log.reset();
orphan_bundle(head_log_path_and_basename);
head_log.emplace(head_log_path_and_basename, non_local_get_block_id, head_log_prune_conf, force_write);
}
}

/**
* Move a bundle out of the way to `<stem>-corrupt-<n>` (a name neither the retained-file scan
* nor this class will ever pick up) so a fresh log can take its place without destroying data.
* An empty bundle has nothing worth keeping and is simply deleted.
*/
void orphan_bundle(const std::filesystem::path& path_and_basename) {
const std::filesystem::path log_file = std::filesystem::path(path_and_basename).replace_extension("log");
if(!std::filesystem::exists(log_file) || std::filesystem::file_size(log_file) == 0) {
delete_bundle(path_and_basename);
return;
}
unsigned n = 0;
std::filesystem::path orphan_base;
do {
orphan_base = path_and_basename;
orphan_base += std::string(orphaned_bundle_infix) + std::to_string(++n);
} while(std::filesystem::exists(std::filesystem::path(orphan_base).replace_extension("log")));
wlog("Moving ${from}.log aside to ${to}.log",
("from", path_and_basename.string())("to", orphan_base.string()));
for(const char* ext : {"log", "index"}) {
const std::filesystem::path from = std::filesystem::path(path_and_basename).replace_extension(ext);
if(std::filesystem::exists(from))
std::filesystem::rename(from, std::filesystem::path(orphan_base).replace_extension(ext));
}
}

void delete_head_log() {
Expand Down
3 changes: 2 additions & 1 deletion libraries/state_history/include/eosio/state_history/log_config.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,8 @@ struct partition_config {

using state_history_log_config = std::variant<std::monostate, prune_config, partition_config>;

std::ostream& boost_test_print_type(std::ostream& os, const state_history_log_config& conf) {
//defined in a header included by more than one translation unit, so it must be inline
inline std::ostream& boost_test_print_type(std::ostream& os, const state_history_log_config& conf) {
std::visit(chain::overloaded {
[&os](const std::monostate&) {
os << "flat";
Expand Down
Loading
Loading