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.

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
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
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
2 changes: 1 addition & 1 deletion src/external/s2/s2edgeindex.cc
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(realm::util::LogCategory::query, "Num cells traversed: %1", num_cells);
Copy link
Contributor

Choose a reason for hiding this comment

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

It would be nice if the s2_logger() was set up with the query log category so it doesn't have to be provided every time. (e.g. like a logger subclass that is constructed with a log category)

}

// Appends to "candidate_crossings" all edge references which may cross the
Expand Down
2 changes: 1 addition & 1 deletion src/external/s2/s2edgeutil.cc
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ bool S2EdgeUtil::VertexCrossing(S2Point const& a, S2Point const& b,
// edge cases where this function will be called with 4 distinct
// (but with two extremely close) vertices
//
s2_logger()->warn("VertexCrossing called with 4 distinct vertices");
s2_logger()->warn(realm::util::LogCategory::query, "VertexCrossing called with 4 distinct vertices");
return false;
}

Expand Down
8 changes: 4 additions & 4 deletions src/external/s2/s2loop.cc
Original file line number Diff line number Diff line change
Expand Up @@ -93,14 +93,14 @@ void S2Loop::Init(vector<S2Point> const& vertices) {
bool S2Loop::IsValid(string* err) const {
// Loops must have at least 3 vertices.
if (num_vertices() < 3) {
s2_logger()->error("Degenerate loop");
s2_logger()->error(realm::util::LogCategory::query, "Degenerate loop");
if (err) *err = "Degenerate loop";
return false;
}
// All vertices must be unit length.
for (int i = 0; i < num_vertices(); ++i) {
if (!S2::IsUnitLength(vertex(i))) {
s2_logger()->error("Vertex %1 is not unit length", i);
s2_logger()->error(realm::util::LogCategory::query, "Vertex %1 is not unit length", i);
if (err) *err = realm::util::format("Vertex %1 is not unit length", i);
return false;
}
Expand All @@ -109,7 +109,7 @@ bool S2Loop::IsValid(string* err) const {
hash_map<S2Point, int> vmap;
for (int i = 0; i < num_vertices(); ++i) {
if (!vmap.insert(make_pair(vertex(i), i)).second) {
s2_logger()->error("Duplicate vertices: %1 and %2", vmap[vertex(i)], i);
s2_logger()->error(realm::util::LogCategory::query, "Duplicate vertices: %1 and %2", vmap[vertex(i)], i);
if (err) *err = realm::util::format("Duplicate vertices: %1 and %2", vmap[vertex(i)], i);
return false;
}
Expand Down Expand Up @@ -139,7 +139,7 @@ bool S2Loop::IsValid(string* err) const {
*err = msg;
}
else {
s2_logger()->error(msg.c_str());
s2_logger()->error(realm::util::LogCategory::query, msg.c_str());
}
break;
}
Expand Down
20 changes: 10 additions & 10 deletions src/external/s2/s2polygon.cc
Original file line number Diff line number Diff line change
Expand Up @@ -130,7 +130,7 @@ bool S2Polygon::IsValid(const vector<S2Loop*>& loops, string* err) {
*err = realm::util::format("Duplicate edge: ring %1, edge %2 and ring %3, edge %4", i, j, other.first, other.second);
}
else {
s2_logger()->error("Duplicate edge: ring %1, edge %2 and ring %3, edge %4", i, j, other.first, other.second);
s2_logger()->error(realm::util::LogCategory::query, "Duplicate edge: ring %1, edge %2 and ring %3, edge %4", i, j, other.first, other.second);
}
return false;
}
Expand All @@ -141,15 +141,15 @@ bool S2Polygon::IsValid(const vector<S2Loop*>& loops, string* err) {
// two loops cross.
for (size_t i = 0; i < loops.size(); ++i) {
if (!loops[i]->IsNormalized()) {
s2_logger()->error("Ring %1 encloses more than half the sphere", i);
s2_logger()->error(realm::util::LogCategory::query, "Ring %1 encloses more than half the sphere", i);
if (err) *err = realm::util::format("Ring %1 encloses more than half the sphere", i);
return false;
}
for (size_t j = i + 1; j < loops.size(); ++j) {
// This test not only checks for edge crossings, it also detects
// cases where the two boundaries cross at a shared vertex.
if (loops[i]->ContainsOrCrosses(loops[j]) < 0) {
s2_logger()->error("Ring %1 crosses ring %2", i, j);
s2_logger()->error(realm::util::LogCategory::query, "Ring %1 crosses ring %2", i, j);
if (err) *err = realm::util::format("Ring %1 crosses ring %2", i, j);
return false;
}
Expand Down Expand Up @@ -742,7 +742,7 @@ void S2Polygon::InitToIntersectionSloppy(S2Polygon const* a, S2Polygon const* b,
ClipBoundary(a, false, b, false, false, true, &builder);
ClipBoundary(b, false, a, false, false, false, &builder);
if (!builder.AssemblePolygon(this, NULL)) {
s2_logger()->fatal("Bad directed edges in InitToIntersection");
s2_logger()->fatal(realm::util::LogCategory::query, "Bad directed edges in InitToIntersection");
}
}

Expand All @@ -764,7 +764,7 @@ void S2Polygon::InitToUnionSloppy(S2Polygon const* a, S2Polygon const* b,
ClipBoundary(a, false, b, false, true, true, &builder);
ClipBoundary(b, false, a, false, true, false, &builder);
if (!builder.AssemblePolygon(this, NULL)) {
s2_logger()->fatal("Bad directed edges");
s2_logger()->fatal(realm::util::LogCategory::query, "Bad directed edges");
}
}

Expand All @@ -786,7 +786,7 @@ void S2Polygon::InitToDifferenceSloppy(S2Polygon const* a, S2Polygon const* b,
ClipBoundary(a, false, b, true, true, true, &builder);
ClipBoundary(b, true, a, false, false, false, &builder);
if (!builder.AssemblePolygon(this, NULL)) {
s2_logger()->fatal("Bad directed edges in InitToDifference");
s2_logger()->fatal(realm::util::LogCategory::query, "Bad directed edges in InitToDifference");
}
}

Expand All @@ -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(realm::util::LogCategory::query, "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(realm::util::LogCategory::query, "%1", S2LatLng(line.vertex(indices[i])));
}
return simplified_line;
}
Expand Down Expand Up @@ -871,7 +871,7 @@ void S2Polygon::InitToSimplified(S2Polygon const* a, S1Angle tolerance) {
BreakEdgesAndAddToBuilder(&index, &builder);

if (!builder.AssemblePolygon(this, NULL)) {
s2_logger()->fatal("Bad edges in InitToSimplified.");
s2_logger()->fatal(realm::util::LogCategory::query, "Bad edges in InitToSimplified.");
}
}

Expand Down Expand Up @@ -1029,7 +1029,7 @@ void S2Polygon::InitToCellUnionBorder(S2CellUnion const& cells) {
builder.AddLoop(&cell_loop);
}
if (!builder.AssemblePolygon(this, NULL)) {
s2_logger()->fatal("AssemblePolygon failed in InitToCellUnionBorder");
s2_logger()->fatal(realm::util::LogCategory::query, "AssemblePolygon failed in InitToCellUnionBorder");
}
}

Expand Down
4 changes: 2 additions & 2 deletions src/external/s2/s2polyline.cc
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,7 @@ bool S2Polyline::IsValid(vector<S2Point> const& v, string* err) {
int n = v.size();
for (int i = 0; i < n; ++i) {
if (!S2::IsUnitLength(v[i])) {
s2_logger()->info("Vertex %1 is not unit length", i);
s2_logger()->info(realm::util::LogCategory::query, "Vertex %1 is not unit length", i);
if (err) {
*err = realm::util::format("Vertex %1 is not unit length", i);
}
Expand All @@ -86,7 +86,7 @@ bool S2Polyline::IsValid(vector<S2Point> const& v, string* err) {
for (int i = 1; i < n; ++i) {
if (v[i-1] == v[i] || v[i-1] == -v[i]) {
std::string msg = realm::util::format("Vertices %1 and %2 are identical or antipodal", (i - 1), i);
s2_logger()->info(msg.c_str());
s2_logger()->info(realm::util::LogCategory::query, msg.c_str());
if (err) {
*err = msg;
}
Expand Down
6 changes: 3 additions & 3 deletions src/external/s2/s2regioncoverer.cc
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(realm::util::LogCategory::query, "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(realm::util::LogCategory::query, "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(realm::util::LogCategory::query, "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
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
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
8 changes: 5 additions & 3 deletions src/realm/sync/client.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -949,7 +949,8 @@ void SessionImpl::on_new_flx_subscription_set(int64_t new_version)
// check is that we have completed the IDENT message handshake and have not yet received an ERROR
// message to call ensure_enlisted_to_send().
if (m_state == State::Active && m_ident_message_sent && !m_error_message_received) {
logger.trace("Requesting QUERY change message for new subscription set version %1", new_version);
logger.trace(util::LogCategory::sync, "Requesting QUERY change message for new subscription set version %1",
Copy link
Contributor

Choose a reason for hiding this comment

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

why not session? Isn't it session's impl essentially?

Copy link
Contributor

Choose a reason for hiding this comment

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

I think it would be appropriate to use just session (or sync) for all the session and connection related debug messages - usually we care about the entire flow of events when debugging session/connection/client issues. It would be unfortunate if we got a log from a customer and it only had part of the logs.

new_version);
ensure_enlisted_to_send();
}
}
Expand Down Expand Up @@ -1910,7 +1911,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 +1969,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
19 changes: 18 additions & 1 deletion src/realm/sync/network/default_socket.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -465,12 +465,29 @@ void DefaultWebSocketImpl::initiate_websocket_handshake()
///
/// DefaultSocketProvider - default socket provider implementation
///
class DefaultSocketLogger : public util::Logger {
public:
DefaultSocketLogger(const std::shared_ptr<Logger>& base_logger) noexcept
: Logger(util::LogCategory::network, *base_logger)
, m_base_logger_ptr(base_logger)
{
}

protected:
void do_log(const util::LogCategory& category, Level level, const std::string& message) final
{
Logger::do_log(*m_base_logger_ptr, category, level, message);
}

private:
std::shared_ptr<Logger> m_base_logger_ptr;
};
Copy link
Contributor

Choose a reason for hiding this comment

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

Move this to logger.hpp and change the name to CategoryLogger (or something like that) so it can be used in multiple places.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done


DefaultSocketProvider::DefaultSocketProvider(const std::shared_ptr<util::Logger>& logger,
const std::string user_agent,
const std::shared_ptr<BindingCallbackThreadObserver>& observer_ptr,
AutoStart auto_start)
: m_logger_ptr{logger}
: m_logger_ptr{std::make_shared<DefaultSocketLogger>(logger)}
, m_observer_ptr{observer_ptr}
, m_service{}
, m_random{}
Expand Down
14 changes: 7 additions & 7 deletions src/realm/sync/network/http.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -137,7 +137,7 @@ bool HTTPParserBase::parse_header_line(size_t len)
auto colon = std::find(p, end, ':');

if (colon == end) {
logger.error("Bad header line in HTTP message:\n%1", line);
logger.error(util::LogCategory::network, "Bad header line in HTTP message:\n%1", line);
return false;
}

Expand All @@ -153,15 +153,15 @@ bool HTTPParserBase::parse_header_line(size_t len)
value = trim_whitespace(value);

if (key.size() == 0) {
logger.error("Bad header line in HTTP message:\n%1", line);
logger.error(util::LogCategory::network, "Bad header line in HTTP message:\n%1", line);
return false;
}

if (key == "Content-Length" || key == "content-length") {
if (value.size() == 0) {
// We consider the empty Content-Length to mean 0.
// A warning is logged.
logger.warn("Empty Content-Length header in HTTP message:\n%1", line);
logger.warn(util::LogCategory::network, "Empty Content-Length header in HTTP message:\n%1", line);
m_found_content_length = 0;
}
else {
Expand All @@ -172,7 +172,7 @@ bool HTTPParserBase::parse_header_line(size_t len)
m_found_content_length = content_length;
}
else {
logger.error("Bad Content-Length header in HTTP message:\n%1", line);
logger.error(util::LogCategory::network, "Bad Content-Length header in HTTP message:\n%1", line);
return false;
}
}
Expand Down Expand Up @@ -240,12 +240,12 @@ bool HTTPParserBase::parse_first_line_of_response(StringData line, HTTPStatus& o
auto end = line.data() + line.size();
auto sp = std::find(p, end, ' ');
if (sp == end) {
logger.error("Invalid HTTP response:\n%1", line);
logger.error(util::LogCategory::network, "Invalid HTTP response:\n%1", line);
return false;
}
StringData http_version(p, sp - p);
if (http_version != "HTTP/1.1") {
logger.error("Invalid version in HTTP response:\n%1", line);
logger.error(util::LogCategory::network, "Invalid version in HTTP response:\n%1", line);
return false;
}
auto status_code_begin = sp + 1;
Expand All @@ -267,7 +267,7 @@ bool HTTPParserBase::parse_first_line_of_response(StringData line, HTTPStatus& o
out_status = static_cast<HTTPStatus>(code);
}
else {
logger.error("Invalid status code in HTTP response:\n%1", line);
logger.error(util::LogCategory::network, "Invalid status code in HTTP response:\n%1", line);
return false;
}
return true;
Expand Down
Loading