Skip to content
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

Log improvements #4580

Merged
merged 7 commits into from
Apr 22, 2024
Merged

Log improvements #4580

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
da622a4
Remove noisy logs
pwojcikdev Apr 16, 2024
7a28035
Log connecting nodes
pwojcikdev Apr 17, 2024
445f845
Formatters for nano primitives
pwojcikdev Apr 22, 2024
254a8f6
Logging started and stopped elections
pwojcikdev Apr 22, 2024
55a4f52
Rename to `election_state`
pwojcikdev Apr 22, 2024
d43e1d2
Log election state
pwojcikdev Apr 22, 2024
e536ca4
Thread runner logs
pwojcikdev Apr 22, 2024
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
46 changes: 43 additions & 3 deletions nano/lib/numbers.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,8 @@
#include <array>
#include <ostream>

#include <fmt/ostream.h>

namespace nano
{
using uint128_t = boost::multiprecision::uint128_t;
Expand Down Expand Up @@ -268,9 +270,9 @@ std::string to_string_hex (uint16_t const);
bool from_string_hex (std::string const &, uint64_t &);

/* Printing adapters */
std::ostream & operator<< (std::ostream & os, const uint128_union & val);
std::ostream & operator<< (std::ostream & os, const uint256_union & val);
std::ostream & operator<< (std::ostream & os, const uint512_union & val);
std::ostream & operator<< (std::ostream &, const uint128_union &);
std::ostream & operator<< (std::ostream &, const uint256_union &);
std::ostream & operator<< (std::ostream &, const uint512_union &);

/**
* Convert a double to string in fixed format
Expand All @@ -285,6 +287,10 @@ namespace difficulty
}
}

/*
* Hashing
*/

namespace std
{
template <>
Expand Down Expand Up @@ -398,3 +404,37 @@ struct hash<::nano::root>
}
};
}

/*
* Formatters
*/

template <>
struct fmt::formatter<nano::uint128_union> : fmt::ostream_formatter
{
};

template <>
struct fmt::formatter<nano::uint256_union> : fmt::ostream_formatter
{
};

template <>
struct fmt::formatter<nano::uint512_union> : fmt::ostream_formatter
{
};

template <>
struct fmt::formatter<nano::block_hash> : fmt::formatter<nano::uint256_union>
{
};

template <>
struct fmt::formatter<nano::public_key> : fmt::formatter<nano::uint256_union>
{
};

template <>
struct fmt::formatter<nano::qualified_root> : fmt::formatter<nano::uint512_union>
{
};
9 changes: 6 additions & 3 deletions nano/lib/thread_runner.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,19 +23,22 @@ nano::thread_runner::thread_runner (std::shared_ptr<boost::asio::io_context> io_
nano::thread_role::set (role);
try
{
logger.debug (nano::log::type::thread_runner, "Thread #{} ({}) started", i, to_string (role));
logger.debug (nano::log::type::thread_runner, "Started thread #{} ({})", i, to_string (role));
run ();
logger.debug (nano::log::type::thread_runner, "Thread #{} ({}) stopped", i, to_string (role));
logger.debug (nano::log::type::thread_runner, "Stopped thread #{} ({})", i, to_string (role));
}
catch (std::exception const & ex)
{
std::cerr << ex.what () << std::endl;
logger.critical (nano::log::type::thread_runner, "Error: {}", ex.what ());

#ifndef NDEBUG
throw; // Re-throw to debugger in debug mode
#endif
}
catch (...)
{
logger.critical (nano::log::type::thread_runner, "Unknown error");

#ifndef NDEBUG
throw; // Re-throw to debugger in debug mode
#endif
Expand Down
12 changes: 11 additions & 1 deletion nano/node/active_transactions.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
#include <nano/lib/blocks.hpp>
#include <nano/lib/numbers.hpp>
#include <nano/lib/threading.hpp>
#include <nano/node/active_transactions.hpp>
#include <nano/node/confirmation_solicitor.hpp>
Expand All @@ -11,7 +12,7 @@
#include <nano/secure/ledger.hpp>
#include <nano/store/component.hpp>

#include <boost/format.hpp>
#include <ranges>

using namespace std::chrono;

Expand Down Expand Up @@ -278,6 +279,11 @@ void nano::active_transactions::cleanup_election (nano::unique_lock<nano::mutex>
node.stats.inc (completion_type (*election), to_stat_detail (election->behavior ()));
node.logger.trace (nano::log::type::active_transactions, nano::log::detail::active_stopped, nano::log::arg{ "election", election });

node.logger.debug (nano::log::type::active_transactions, "Erased election for blocks: {} (behavior: {}, state: {})",
fmt::join (std::views::keys (blocks_l), ", "),
to_string (election->behavior ()),
to_string (election->state ()));

lock_a.unlock ();

vacancy_update ();
Expand Down Expand Up @@ -405,6 +411,10 @@ nano::election_insertion_result nano::active_transactions::insert (std::shared_p
node.logger.trace (nano::log::type::active_transactions, nano::log::detail::active_started,
nano::log::arg{ "behavior", election_behavior_a },
nano::log::arg{ "election", result.election });

node.logger.debug (nano::log::type::active_transactions, "Started new election for block: {} (behavior: {})",
hash.to_string (),
to_string (election_behavior_a));
}
else
{
Expand Down
88 changes: 53 additions & 35 deletions nano/node/election.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,8 +8,6 @@
#include <nano/node/vote_generator.hpp>
#include <nano/secure/ledger.hpp>

#include <boost/format.hpp>

#include <magic_enum.hpp>

using namespace std::chrono;
Expand Down Expand Up @@ -43,8 +41,8 @@ void nano::election::confirm_once (nano::unique_lock<nano::mutex> & lock_a)

// This must be kept above the setting of election state, as dependent confirmed elections require up to date changes to election_winner_details
nano::unique_lock<nano::mutex> election_winners_lk{ node.active.election_winner_details_mutex };
auto just_confirmed = state_m != nano::election::state_t::confirmed;
state_m = nano::election::state_t::confirmed;
auto just_confirmed = state_m != nano::election_state::confirmed;
state_m = nano::election_state::confirmed;
if (just_confirmed && (node.active.election_winner_details.count (status.winner->hash ()) == 0))
{
node.active.election_winner_details.emplace (status.winner->hash (), shared_from_this ());
Expand Down Expand Up @@ -80,52 +78,52 @@ void nano::election::confirm_once (nano::unique_lock<nano::mutex> & lock_a)
}
}

bool nano::election::valid_change (nano::election::state_t expected_a, nano::election::state_t desired_a) const
bool nano::election::valid_change (nano::election_state expected_a, nano::election_state desired_a) const
{
bool result = false;
switch (expected_a)
{
case nano::election::state_t::passive:
case nano::election_state::passive:
switch (desired_a)
{
case nano::election::state_t::active:
case nano::election::state_t::confirmed:
case nano::election::state_t::expired_unconfirmed:
case nano::election_state::active:
case nano::election_state::confirmed:
case nano::election_state::expired_unconfirmed:
result = true;
break;
default:
break;
}
break;
case nano::election::state_t::active:
case nano::election_state::active:
switch (desired_a)
{
case nano::election::state_t::confirmed:
case nano::election::state_t::expired_unconfirmed:
case nano::election_state::confirmed:
case nano::election_state::expired_unconfirmed:
result = true;
break;
default:
break;
}
break;
case nano::election::state_t::confirmed:
case nano::election_state::confirmed:
switch (desired_a)
{
case nano::election::state_t::expired_confirmed:
case nano::election_state::expired_confirmed:
result = true;
break;
default:
break;
}
break;
case nano::election::state_t::expired_unconfirmed:
case nano::election::state_t::expired_confirmed:
case nano::election_state::expired_unconfirmed:
case nano::election_state::expired_confirmed:
break;
}
return result;
}

bool nano::election::state_change (nano::election::state_t expected_a, nano::election::state_t desired_a)
bool nano::election::state_change (nano::election_state expected_a, nano::election_state desired_a)
{
bool result = true;
if (valid_change (expected_a, desired_a))
Expand Down Expand Up @@ -169,13 +167,13 @@ void nano::election::send_confirm_req (nano::confirmation_solicitor & solicitor_
void nano::election::transition_active ()
{
nano::unique_lock<nano::mutex> lock{ mutex };
state_change (nano::election::state_t::passive, nano::election::state_t::active);
state_change (nano::election_state::passive, nano::election_state::active);
}

bool nano::election::confirmed_locked () const
{
debug_assert (!mutex.try_lock ());
return state_m == nano::election::state_t::confirmed || state_m == nano::election::state_t::expired_confirmed;
return state_m == nano::election_state::confirmed || state_m == nano::election_state::expired_confirmed;
}

bool nano::election::confirmed () const
Expand All @@ -187,7 +185,7 @@ bool nano::election::confirmed () const
bool nano::election::failed () const
{
nano::unique_lock<nano::mutex> lock{ mutex };
return state_m == nano::election::state_t::expired_unconfirmed;
return state_m == nano::election_state::expired_unconfirmed;
}

bool nano::election::broadcast_block_predicate () const
Expand Down Expand Up @@ -253,24 +251,24 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a
bool result = false;
switch (state_m)
{
case nano::election::state_t::passive:
case nano::election_state::passive:
if (base_latency () * passive_duration_factor < std::chrono::steady_clock::now ().time_since_epoch () - state_start)
{
state_change (nano::election::state_t::passive, nano::election::state_t::active);
state_change (nano::election_state::passive, nano::election_state::active);
}
break;
case nano::election::state_t::active:
case nano::election_state::active:
broadcast_vote_locked (lock);
broadcast_block (solicitor_a);
send_confirm_req (solicitor_a);
break;
case nano::election::state_t::confirmed:
case nano::election_state::confirmed:
result = true; // Return true to indicate this election should be cleaned up
broadcast_block (solicitor_a); // Ensure election winner is broadcasted
state_change (nano::election::state_t::confirmed, nano::election::state_t::expired_confirmed);
state_change (nano::election_state::confirmed, nano::election_state::expired_confirmed);
break;
case nano::election::state_t::expired_unconfirmed:
case nano::election::state_t::expired_confirmed:
case nano::election_state::expired_unconfirmed:
case nano::election_state::expired_confirmed:
debug_assert (false);
break;
}
Expand All @@ -279,7 +277,7 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a
{
// It is possible the election confirmed while acquiring the mutex
// state_change returning true would indicate it
if (!state_change (state_m, nano::election::state_t::expired_unconfirmed))
if (!state_change (state_m, nano::election_state::expired_unconfirmed))
{
node.logger.trace (nano::log::type::election, nano::log::detail::election_expired,
nano::log::arg{ "id", id },
Expand Down Expand Up @@ -738,24 +736,23 @@ std::vector<nano::vote_with_weight_info> nano::election::votes_with_weight () co
return result;
}

nano::stat::detail nano::to_stat_detail (nano::election_behavior behavior)
nano::election_behavior nano::election::behavior () const
{
auto value = magic_enum::enum_cast<nano::stat::detail> (magic_enum::enum_name (behavior));
debug_assert (value);
return value.value_or (nano::stat::detail{});
return behavior_m;
}

nano::election_behavior nano::election::behavior () const
nano::election_state nano::election::state () const
{
return behavior_m;
nano::lock_guard<nano::mutex> guard{ mutex };
return state_m;
}

// TODO: Remove the need for .to_string () calls
void nano::election::operator() (nano::object_stream & obs) const
{
obs.write ("id", id);
obs.write ("qualified_root", qualified_root.to_string ());
obs.write ("behaviour", behavior_m);
obs.write ("behavior", behavior_m);
obs.write ("height", height);
obs.write ("status", current_status ());
}
Expand Down Expand Up @@ -790,3 +787,24 @@ void nano::election_extended_status::operator() (nano::object_stream & obs) cons
obs.write ("amount", amount);
});
}

/*
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like a spurious comment.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added it to separate election class implementation from boilerplate enum conversions. I couldn't think of a good name for this section.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added it to separate election class implementation from boilerplate enum conversions. I couldn't think of a good name for this section.

"Functions for converting election enums to strings and stat details"

*
*/

std::string_view nano::to_string (nano::election_behavior behavior)
{
return magic_enum::enum_name (behavior);
}

nano::stat::detail nano::to_stat_detail (nano::election_behavior behavior)
{
auto value = magic_enum::enum_cast<nano::stat::detail> (magic_enum::enum_name (behavior));
debug_assert (value);
return value.value_or (nano::stat::detail{});
}

std::string_view nano::to_string (nano::election_state state)
{
return magic_enum::enum_name (state);
}
Loading
Loading