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

Use logging categories #7052

Merged
merged 5 commits into from
Oct 20, 2023
+263 −178
Merged

Use logging categories #7052

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
1d0f5fe
Use logging categories
jedelbo Oct 11, 2023
22f0222
Adjust S2 tracing levels and categories
jedelbo Oct 16, 2023
fdf4ba7
Review updates
jedelbo Oct 18, 2023
c5d5794
Update low level replication logging
jedelbo Oct 19, 2023
619bb46
Update after review
jedelbo Oct 20, 2023
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
5 changes: 3 additions & 2 deletions src/external/s2/base/logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,9 +38,10 @@
#define DCHECK_GE(val1, val2) REALM_ASSERT_DEBUG_EX(val1 >= val2, val1, val2)
#define DCHECK_GT(val1, val2) REALM_ASSERT_DEBUG_EX(val1 > val2, val1, val2)

static inline std::shared_ptr<realm::util::Logger>& s2_logger()
static inline realm::util::Logger* s2_logger()
{
return realm::util::Logger::get_default_logger();
static realm::util::CategoryLogger my_logger(realm::util::LogCategory::query, realm::util::Logger::get_default_logger());
return &my_logger;
}

#endif // BASE_LOGGING_H
2 changes: 1 addition & 1 deletion src/external/s2/s2edgeindex.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -283,7 +283,7 @@ void S2EdgeIndex::GetEdgesInChildrenCells(
}
}
}
s2_logger()->detail("Num cells traversed: %1", num_cells);
s2_logger()->trace("Num cells traversed: %1", num_cells);
}

// Appends to "candidate_crossings" all edge references which may cross the
Expand Down
4 changes: 2 additions & 2 deletions src/external/s2/s2polygon.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -804,10 +804,10 @@ vector<S2Point>* SimplifyLoopAsPolyline(S2Loop const* loop, S1Angle tolerance) {
if (indices.size() <= 2) return NULL;
// Add them all except the last: it is the same as the first.
vector<S2Point>* simplified_line = new vector<S2Point>(indices.size() - 1);
s2_logger()->detail("Now simplified to: ");
s2_logger()->trace("Now simplified to: ");
for (size_t i = 0; i + 1 < indices.size(); ++i) {
(*simplified_line)[i] = line.vertex(indices[i]);
s2_logger()->detail("%1", S2LatLng(line.vertex(indices[i])));
s2_logger()->trace("%1", S2LatLng(line.vertex(indices[i])));
}
return simplified_line;
}
Expand Down
6 changes: 3 additions & 3 deletions src/external/s2/s2regioncoverer.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -190,7 +190,7 @@ void S2RegionCoverer::AddCandidate(Candidate* candidate) {
+ candidate->num_children) << max_children_shift())
+ num_terminals);
pq_->push(make_pair(priority, candidate));
s2_logger()->detail("Push: %1 (%2) ", candidate->cell.id(), priority);
s2_logger()->trace("Push: %1 (%2) ", candidate->cell.id(), priority);
}
}

Expand Down Expand Up @@ -255,7 +255,7 @@ void S2RegionCoverer::GetCoveringInternal(S2Region const& region) {
(!interior_covering_ || result_->size() < (size_t)max_cells_)) {
Candidate* candidate = pq_->top().second;
pq_->pop();
s2_logger()->detail("Pop: %1", candidate->cell.id());
s2_logger()->trace("Pop: %1", candidate->cell.id());
if (candidate->cell.level() < min_level_ ||
candidate->num_children == 1 ||
(int)result_->size() + (int)(interior_covering_ ? 0 : (int)pq_->size()) +
Expand All @@ -272,7 +272,7 @@ void S2RegionCoverer::GetCoveringInternal(S2Region const& region) {
AddCandidate(candidate);
}
}
s2_logger()->detail("Created %1 cells, %2 candidates created, %3 left", result_->size(),
s2_logger()->trace("Created %1 cells, %2 candidates created, %3 left", result_->size(),
candidates_created_counter_, pq_->size());
while (!pq_->empty()) {
DeleteCandidate(pq_->top().second, true);
Expand Down
12 changes: 7 additions & 5 deletions src/realm/backup_restore.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -108,7 +108,7 @@ void BackupHandler::restore_from_backup()
if (backup_exists(m_prefix, v)) {
prep_logging();
auto backup_nm = backup_name(m_prefix, v);
m_logger->info("%1 : Restoring from backup: %2", m_time_buf, backup_nm);
m_logger->info(util::LogCategory::storage, "%1 : Restoring from backup: %2", m_time_buf, backup_nm);
util::File::move(backup_nm, m_path);
return;
}
Expand All @@ -127,7 +127,8 @@ void BackupHandler::cleanup_backups()
double diff = difftime(now, last_modified);
if (diff > v.second) {
prep_logging();
m_logger->info("%1 : Removing old backup: %2 (age %3)", m_time_buf, fn, diff);
m_logger->info(util::LogCategory::storage, "%1 : Removing old backup: %2 (age %3)", m_time_buf,
fn, diff);
util::File::remove(fn);
}
}
Expand Down Expand Up @@ -167,7 +168,8 @@ void BackupHandler::backup_realm_if_needed(int current_file_format_version, int
// ignore it, if attempt to get free space fails for any reason
if (util::File::get_free_space(m_path) < util::File::get_size_static(m_path) * 2) {
prep_logging();
m_logger->error("%1 : Insufficient free space for backup: %2", m_time_buf, backup_nm);
m_logger->error(util::LogCategory::storage, "%1 : Insufficient free space for backup: %2", m_time_buf,
backup_nm);
return;
}
}
Expand All @@ -176,7 +178,7 @@ void BackupHandler::backup_realm_if_needed(int current_file_format_version, int
}
{
prep_logging();
m_logger->info("%1 : Creating backup: %2", m_time_buf, backup_nm);
m_logger->info(util::LogCategory::storage, "%1 : Creating backup: %2", m_time_buf, backup_nm);
}
std::string part_name = backup_nm + ".part";
// The backup file should be a 1-1 copy, so that we can get the original
Expand All @@ -188,7 +190,7 @@ void BackupHandler::backup_realm_if_needed(int current_file_format_version, int
util::File::copy(m_path, part_name);
util::File::move(part_name, backup_nm);
prep_logging();
m_logger->info("%1 : Completed backup: %2", m_time_buf, backup_nm);
m_logger->info(util::LogCategory::storage, "%1 : Completed backup: %2", m_time_buf, backup_nm);
}
catch (...) {
try {
Expand Down
8 changes: 5 additions & 3 deletions src/realm/object-store/sync/app.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -322,22 +322,24 @@ bool App::init_logger()

bool App::would_log(util::Logger::Level level)
{
return init_logger() && m_logger_ptr->would_log(level);
return init_logger() && m_logger_ptr->would_log(util::LogCategory::app, level);
}

template <class... Params>
void App::log_debug(const char* message, Params&&... params)
{
if (init_logger()) {
m_logger_ptr->log(util::Logger::Level::debug, message, std::forward<Params>(params)...);
m_logger_ptr->log(util::LogCategory::app, util::Logger::Level::debug, message,
std::forward<Params>(params)...);
}
}

template <class... Params>
void App::log_error(const char* message, Params&&... params)
{
if (init_logger()) {
m_logger_ptr->log(util::Logger::Level::error, message, std::forward<Params>(params)...);
m_logger_ptr->log(util::LogCategory::app, util::Logger::Level::error, message,
std::forward<Params>(params)...);
}
}

Expand Down
60 changes: 35 additions & 25 deletions src/realm/replication.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -225,23 +225,26 @@ void Replication::set(const Table* t, ColKey col_key, ObjKey key, Mixed value, _
if (col_key.get_type() == col_type_Link && value.is_type(type_Link)) {
auto target_table = t->get_opposite_table(col_key);
if (target_table->is_embedded()) {
logger->log(util::Logger::Level::trace, " Creating embedded object '%1' in '%2'",
target_table->get_class_name(), t->get_column_name(col_key));
logger->log(LogCategory::object, util::Logger::Level::trace,
" Creating embedded object '%1' in '%2'", target_table->get_class_name(),
t->get_column_name(col_key));
}
else if (target_table->get_primary_key_column()) {
auto link = value.get<ObjKey>();
auto pk = target_table->get_primary_key(link);
logger->log(util::Logger::Level::trace, " Linking object '%1' with primary key %2 from '%3'",
logger->log(LogCategory::object, util::Logger::Level::trace,
" Linking object '%1' with primary key %2 from '%3'",
target_table->get_class_name(), pk, t->get_column_name(col_key));
}
else {
logger->log(util::Logger::Level::trace, " Linking object '%1'[%2] from '%3'",
target_table->get_class_name(), key, t->get_column_name(col_key));
logger->log(LogCategory::object, util::Logger::Level::trace,
" Linking object '%1'[%2] from '%3'", target_table->get_class_name(), key,
t->get_column_name(col_key));
}
}
else {
logger->log(util::Logger::Level::trace, " Set '%1' to %2", t->get_column_name(col_key),
value.to_string(util::Logger::max_width_of_value));
logger->log(LogCategory::object, util::Logger::Level::trace, " Set '%1' to %2",
t->get_column_name(col_key), value.to_string(util::Logger::max_width_of_value));
}
}
}
Expand All @@ -253,15 +256,16 @@ void Replication::nullify_link(const Table* t, ColKey col_key, ObjKey key)
select_obj(key);
m_encoder.modify_object(col_key, key); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Nullify '%1'", t->get_column_name(col_key));
logger->log(LogCategory::object, util::Logger::Level::trace, " Nullify '%1'", t->get_column_name(col_key));
}
}

void Replication::add_int(const Table* t, ColKey col_key, ObjKey key, int_fast64_t value)
{
do_set(t, col_key, key); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Adding %1 to '%2'", value, t->get_column_name(col_key));
logger->log(LogCategory::object, util::Logger::Level::trace, " Adding %1 to '%2'", value,
t->get_column_name(col_key));
}
}

Expand Down Expand Up @@ -290,23 +294,24 @@ void Replication::log_collection_operation(const char* operation, const Collecti
if (Table::is_link_type(col_key.get_type()) && value.is_type(type_Link)) {
auto target_table = m_selected_table->get_opposite_table(col_key);
if (target_table->is_embedded()) {
logger->log(util::Logger::Level::trace, " %1 embedded object '%2' in %3%4 ", operation,
target_table->get_class_name(), path, position);
logger->log(LogCategory::object, util::Logger::Level::trace, " %1 embedded object '%2' in %3%4 ",
operation, target_table->get_class_name(), path, position);
}
else if (target_table->get_primary_key_column()) {
auto link = value.get<ObjKey>();
auto pk = target_table->get_primary_key(link);
logger->log(util::Logger::Level::trace, " %1 object '%2' with primary key %3 in %4%5", operation,
target_table->get_class_name(), pk, path, position);
logger->log(LogCategory::object, util::Logger::Level::trace,
" %1 object '%2' with primary key %3 in %4%5", operation, target_table->get_class_name(),
pk, path, position);
}
else {
auto link = value.get<ObjKey>();
logger->log(util::Logger::Level::trace, " %1 object '%2'[%3] in %4%5", operation,
logger->log(LogCategory::object, util::Logger::Level::trace, " %1 object '%2'[%3] in %4%5", operation,
target_table->get_class_name(), link, path, position);
}
}
else {
logger->log(util::Logger::Level::trace, " %1 %2 in %3%4", operation,
logger->log(LogCategory::object, util::Logger::Level::trace, " %1 %2 in %3%4", operation,
value.to_string(util::Logger::max_width_of_value), path, position);
}
}
Expand Down Expand Up @@ -337,8 +342,8 @@ void Replication::list_erase(const CollectionBase& list, size_t link_ndx)
select_collection(list); // Throws
m_encoder.collection_erase(list.translate_index(link_ndx)); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Erase '%1' at position %2", get_prop_name(list.get_short_path()),
link_ndx);
logger->log(LogCategory::object, util::Logger::Level::trace, " Erase '%1' at position %2",
get_prop_name(list.get_short_path()), link_ndx);
}
}

Expand All @@ -347,8 +352,8 @@ void Replication::list_move(const CollectionBase& list, size_t from_link_ndx, si
select_collection(list); // Throws
m_encoder.collection_move(list.translate_index(from_link_ndx), list.translate_index(to_link_ndx)); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Move %1 to %2 in '%3'", from_link_ndx, to_link_ndx,
get_prop_name(list.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Move %1 to %2 in '%3'", from_link_ndx,
to_link_ndx, get_prop_name(list.get_short_path()));
}
}

Expand All @@ -368,7 +373,8 @@ void Replication::set_erase(const CollectionBase& set, size_t set_ndx, Mixed val
select_collection(set); // Throws
m_encoder.collection_erase(set_ndx); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Erase %1 from '%2'", value, get_prop_name(set.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Erase %1 from '%2'", value,
get_prop_name(set.get_short_path()));
}
}

Expand All @@ -377,7 +383,8 @@ void Replication::set_clear(const CollectionBase& set)
select_collection(set); // Throws
m_encoder.collection_clear(set.size()); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Clear '%1'", get_prop_name(set.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'",
get_prop_name(set.get_short_path()));
}
}

Expand Down Expand Up @@ -407,7 +414,8 @@ void Replication::list_clear(const CollectionBase& list)
select_collection(list); // Throws
m_encoder.collection_clear(list.size()); // Throws
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Clear '%1'", get_prop_name(list.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'",
get_prop_name(list.get_short_path()));
}
}

Expand All @@ -416,7 +424,7 @@ void Replication::link_list_nullify(const Lst<ObjKey>& list, size_t link_ndx)
select_collection(list);
m_encoder.collection_erase(link_ndx);
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Nullify '%1' position %2",
logger->log(LogCategory::object, util::Logger::Level::trace, " Nullify '%1' position %2",
m_selected_table->get_column_name(list.get_col_key()), link_ndx);
}
}
Expand Down Expand Up @@ -448,7 +456,8 @@ void Replication::dictionary_erase(const CollectionBase& dict, size_t ndx, Mixed
select_collection(dict);
m_encoder.collection_erase(ndx);
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Erase %1 from '%2'", key, get_prop_name(dict.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Erase %1 from '%2'", key,
get_prop_name(dict.get_short_path()));
}
}

Expand All @@ -457,6 +466,7 @@ void Replication::dictionary_clear(const CollectionBase& dict)
select_collection(dict);
m_encoder.collection_clear(dict.size());
if (auto logger = get_logger()) {
logger->log(util::Logger::Level::trace, " Clear '%1'", get_prop_name(dict.get_short_path()));
logger->log(LogCategory::object, util::Logger::Level::trace, " Clear '%1'",
get_prop_name(dict.get_short_path()));
}
}
5 changes: 3 additions & 2 deletions src/realm/sync/client.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1910,7 +1910,8 @@ ClientImpl::Connection::Connection(ClientImpl& client, connection_ident_type ide
Optional<std::string> ssl_trust_certificate_path,
std::function<SSLVerifyCallback> ssl_verify_callback,
Optional<ProxyConfig> proxy_config, ReconnectInfo reconnect_info)
: logger_ptr{std::make_shared<util::PrefixLogger>(make_logger_prefix(ident), client.logger_ptr)} // Throws
: logger_ptr{std::make_shared<util::PrefixLogger>(util::LogCategory::session, make_logger_prefix(ident),
client.logger_ptr)} // Throws
, logger{*logger_ptr}
, m_client{client}
, m_verify_servers_ssl_certificate{verify_servers_ssl_certificate} // DEPRECATED
Expand Down Expand Up @@ -1967,7 +1968,7 @@ void ClientImpl::Connection::resume_active_sessions()

void ClientImpl::Connection::on_idle()
{
logger.debug("Destroying connection object");
logger.debug(util::LogCategory::session, "Destroying connection object");
Copy link
Contributor

Choose a reason for hiding this comment

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

connection can serve multiple session. Maybe introduce one more category under client for Connection? Otherwise just 'client' would be appropriate i think. @michael-wb what are you thought?

ClientImpl& client = get_client();
client.remove_connection(*this);
// NOTE: This connection object is now destroyed!
Expand Down
Loading