Skip to content

Commit

Permalink
apply unique log ids (arangodb#8561)
Browse files Browse the repository at this point in the history
  • Loading branch information
@ObiWahn @jsteemann
ObiWahn authored and jsteemann committed Mar 25, 2019
1 parent 75c3cad commit c3f7961
Show file tree
Hide file tree
Showing 382 changed files with 4,093 additions and 3,909 deletions.
9 changes: 9 additions & 0 deletions CHANGELOG
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,15 @@
devel
-----

* added "--log.ids" option to arangod

The default value for this option is `false`. Setting the option to `true`
will embed unique ids into all log messages generated in arangod code. This
allows for easy access to the location in the source code from which the
message originates. This should help customers to configure custom
monitoring/alerting based on specific log id occurrences and will also be
helpful for support and development in identifying problems.

* fixed issue #8294: wrong equals behaviour on arrays with ArangoSearch

* fixed internal issue #528: ArangoSearch range query sometimes doesn't work
Expand Down
19 changes: 17 additions & 2 deletions README_maintainers.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,11 +11,26 @@ Setting up git for automatically merging certain automatically generated files i

git config --global merge.ours.driver true


Building
========

Unique Log Ids
--------------

We have unique log ids in order to allow for easy locating of code producing
errors.

LOG_TOPIC(2dead, ....)

To ensure that the ids are unique we run the script `./utils/generateLogIds.py`
during CI runs. The script will fail with a non-zero status if id collisions
are found. You can use `openssl rand -hex 3 | sed 's/.//'` anything that suits
you to generate a **5 hex digit log** id.

CMake
=====

Essentially, you can compile ArangoDB from source by issueing the
Essentially, you can compile ArangoDB from source by issuing the
following commands from a clone of the source repository:

mkdir build
Expand Down
2 changes: 1 addition & 1 deletion arangod/Actions/actions.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -72,7 +72,7 @@ std::shared_ptr<TRI_action_t> TRI_DefineActionVocBase(std::string const& name,
}

// some debug output
LOG_TOPIC(DEBUG, arangodb::Logger::FIXME)
LOG_TOPIC("93939", DEBUG, arangodb::Logger::FIXME)
<< "created JavaScript " << (action->_isPrefix ? "prefix " : "")
<< "action '" << url << "'";
return action;
Expand Down
32 changes: 16 additions & 16 deletions arangod/Agency/ActiveFailoverJob.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ ActiveFailoverJob::ActiveFailoverJob(Node const& snapshot, AgentInterface* agent
} else {
std::stringstream err;
err << "Failed to find job " << _jobId << " in agency.";
LOG_TOPIC(ERR, Logger::SUPERVISION) << err.str();
LOG_TOPIC("c756b", ERR, Logger::SUPERVISION) << err.str();
finish(tmp_server.first, "", false, err.str());
_status = FAILED;
}
Expand All @@ -62,7 +62,7 @@ ActiveFailoverJob::~ActiveFailoverJob() {}
void ActiveFailoverJob::run(bool& aborts) { runHelper(_server, "", aborts); }

bool ActiveFailoverJob::create(std::shared_ptr<VPackBuilder> envelope) {
LOG_TOPIC(DEBUG, Logger::SUPERVISION) << "Todo: Handle failover for leader " + _server;
LOG_TOPIC("3f7ab", DEBUG, Logger::SUPERVISION) << "Todo: Handle failover for leader " + _server;

bool selfCreate = (envelope == nullptr); // Do we create ourselves?

Expand Down Expand Up @@ -126,7 +126,7 @@ bool ActiveFailoverJob::create(std::shared_ptr<VPackBuilder> envelope) {

_status = NOTFOUND;

LOG_TOPIC(INFO, Logger::SUPERVISION) << "Failed to insert job " + _jobId;
LOG_TOPIC("3e5b0", INFO, Logger::SUPERVISION) << "Failed to insert job " + _jobId;
return false;
}

Expand All @@ -138,15 +138,15 @@ bool ActiveFailoverJob::start(bool&) {
if (checkServerHealth(_snapshot, _server) != Supervision::HEALTH_STATUS_FAILED) {
std::string reason = "Server " + _server + " is no longer failed. " +
"Not starting ActiveFailoverJob job";
LOG_TOPIC(INFO, Logger::SUPERVISION) << reason;
LOG_TOPIC("b1d34", INFO, Logger::SUPERVISION) << reason;
return finish(_server, "", true, reason); // move to /Target/Finished
}

auto leader = _snapshot.hasAsSlice(asyncReplLeader);
if (!leader.second || leader.first.compareString(_server) != 0) {
std::string reason =
"Server " + _server + " is not the current replication leader";
LOG_TOPIC(INFO, Logger::SUPERVISION) << reason;
LOG_TOPIC("d468e", INFO, Logger::SUPERVISION) << reason;
return finish(_server, "", true, reason); // move to /Target/Finished
}

Expand All @@ -166,7 +166,7 @@ bool ActiveFailoverJob::start(bool&) {
try {
_snapshot(toDoPrefix + _jobId).toBuilder(todo);
} catch (std::exception const&) {
LOG_TOPIC(INFO, Logger::SUPERVISION) << "Failed to get key " + toDoPrefix + _jobId +
LOG_TOPIC("26fec", INFO, Logger::SUPERVISION) << "Failed to get key " + toDoPrefix + _jobId +
" from agency snapshot";
return false;
}
Expand All @@ -177,11 +177,11 @@ bool ActiveFailoverJob::start(bool&) {

std::string newLeader = findBestFollower();
if (newLeader.empty() || _server == newLeader) {
LOG_TOPIC(INFO, Logger::SUPERVISION)
LOG_TOPIC("a6da3", INFO, Logger::SUPERVISION)
<< "No follower for fail-over available, will retry";
return false; // job will retry later
}
LOG_TOPIC(INFO, Logger::SUPERVISION) << "Selected '" << newLeader << "' as leader";
LOG_TOPIC("2ef54", INFO, Logger::SUPERVISION) << "Selected '" << newLeader << "' as leader";

// Enter pending, remove todo
Builder pending;
Expand Down Expand Up @@ -215,13 +215,13 @@ bool ActiveFailoverJob::start(bool&) {

if (res.accepted && res.indices.size() == 1 && res.indices[0]) {
_status = FINISHED;
LOG_TOPIC(INFO, Logger::SUPERVISION)
LOG_TOPIC("8c325", INFO, Logger::SUPERVISION)
<< "Finished: ActiveFailoverJob server " << _server << " failover to "
<< newLeader;
return true;
}

LOG_TOPIC(INFO, Logger::SUPERVISION)
LOG_TOPIC("bcf05", INFO, Logger::SUPERVISION)
<< "Precondition failed for ActiveFailoverJob " + _jobId;
return false;
}
Expand Down Expand Up @@ -281,14 +281,14 @@ std::string ActiveFailoverJob::findBestFollower() {
}
trans_ret_t res = _agent->transient(std::move(trx));
if (!res.accepted) {
LOG_TOPIC(ERR, Logger::SUPERVISION)
LOG_TOPIC("dbce2", ERR, Logger::SUPERVISION)
<< "could not read from transient while"
<< " determining follower ticks";
return "";
}
VPackSlice resp = res.result->slice();
if (!resp.isArray() || resp.length() == 0) {
LOG_TOPIC(ERR, Logger::SUPERVISION)
LOG_TOPIC("dd849", ERR, Logger::SUPERVISION)
<< "no follower ticks in transient store";
return "";
}
Expand All @@ -311,12 +311,12 @@ std::string ActiveFailoverJob::findBestFollower() {
}
}
} catch (basics::Exception const& e) {
LOG_TOPIC(ERR, Logger::SUPERVISION)
LOG_TOPIC("66318", ERR, Logger::SUPERVISION)
<< "could not determine follower: " << e.message();
} catch (std::exception const& e) {
LOG_TOPIC(ERR, Logger::SUPERVISION) << "could not determine follower: " << e.what();
LOG_TOPIC("92baa", ERR, Logger::SUPERVISION) << "could not determine follower: " << e.what();
} catch (...) {
LOG_TOPIC(ERR, Logger::SUPERVISION)
LOG_TOPIC("567b2", ERR, Logger::SUPERVISION)
<< "internal error while determining best follower";
}

Expand All @@ -327,6 +327,6 @@ std::string ActiveFailoverJob::findBestFollower() {
TRI_ASSERT(ticks.size() == 1 || ticks[0].second >= ticks[1].second);
return ticks[0].first;
}
LOG_TOPIC(ERR, Logger::SUPERVISION) << "no follower ticks available";
LOG_TOPIC("f94ec", ERR, Logger::SUPERVISION) << "no follower ticks available";
return ""; // fallback to any available server
}
18 changes: 9 additions & 9 deletions arangod/Agency/AddFollower.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@ AddFollower::AddFollower(Node const& snapshot, AgentInterface* agent,
} else {
std::stringstream err;
err << "Failed to find job " << _jobId << " in agency.";
LOG_TOPIC(ERR, Logger::SUPERVISION) << err.str();
LOG_TOPIC("4d260", ERR, Logger::SUPERVISION) << err.str();
finish("", tmp_shard.first, false, err.str());
_status = FAILED;
}
Expand All @@ -67,7 +67,7 @@ AddFollower::~AddFollower() {}
void AddFollower::run(bool& aborts) { runHelper("", _shard, aborts); }

bool AddFollower::create(std::shared_ptr<VPackBuilder> envelope) {
LOG_TOPIC(INFO, Logger::SUPERVISION)
LOG_TOPIC("8f72c", INFO, Logger::SUPERVISION)
<< "Todo: AddFollower(s) "
<< " to shard " << _shard << " in collection " << _collection;

Expand Down Expand Up @@ -115,7 +115,7 @@ bool AddFollower::create(std::shared_ptr<VPackBuilder> envelope) {

_status = NOTFOUND;

LOG_TOPIC(INFO, Logger::SUPERVISION) << "Failed to insert job " + _jobId;
LOG_TOPIC("02cef", INFO, Logger::SUPERVISION) << "Failed to insert job " + _jobId;
return false;
}

Expand Down Expand Up @@ -180,7 +180,7 @@ bool AddFollower::start(bool&) {

// Check that the shard is not locked:
if (_snapshot.has(blockedShardsPrefix + _shard)) {
LOG_TOPIC(DEBUG, Logger::SUPERVISION)
LOG_TOPIC("1de2b", DEBUG, Logger::SUPERVISION)
<< "shard " << _shard
<< " is currently locked, not starting AddFollower job " << _jobId;
return false;
Expand All @@ -205,7 +205,7 @@ bool AddFollower::start(bool&) {

// Check that we have enough:
if (available.size() < desiredReplFactor - actualReplFactor) {
LOG_TOPIC(DEBUG, Logger::SUPERVISION)
LOG_TOPIC("50086", DEBUG, Logger::SUPERVISION)
<< "shard " << _shard
<< " does not have enough candidates to add followers, waiting, jobId=" << _jobId;
return false;
Expand Down Expand Up @@ -241,7 +241,7 @@ bool AddFollower::start(bool&) {
if (!tmp_todo.second) {
// Just in case, this is never going to happen, since we will only
// call the start() method if the job is already in ToDo.
LOG_TOPIC(INFO, Logger::SUPERVISION) << "Failed to get key " + toDoPrefix + _jobId +
LOG_TOPIC("24c50", INFO, Logger::SUPERVISION) << "Failed to get key " + toDoPrefix + _jobId +
" from agency snapshot";
return false;
}
Expand All @@ -251,7 +251,7 @@ bool AddFollower::start(bool&) {
} catch (std::exception const& e) {
// Just in case, this is never going to happen, since when _jb is
// set, then the current job is stored under ToDo.
LOG_TOPIC(WARN, Logger::SUPERVISION)
LOG_TOPIC("15c37", WARN, Logger::SUPERVISION)
<< e.what() << ": " << __FILE__ << ":" << __LINE__;
return false;
}
Expand Down Expand Up @@ -302,12 +302,12 @@ bool AddFollower::start(bool&) {

if (res.accepted && res.indices.size() == 1 && res.indices[0]) {
_status = FINISHED;
LOG_TOPIC(INFO, Logger::SUPERVISION) << "Finished: Addfollower(s) to shard "
LOG_TOPIC("961a4", INFO, Logger::SUPERVISION) << "Finished: Addfollower(s) to shard "
<< _shard << " in collection " << _collection;
return true;
}

LOG_TOPIC(INFO, Logger::SUPERVISION)
LOG_TOPIC("63ba4", INFO, Logger::SUPERVISION)
<< "Start precondition failed for AddFollower " + _jobId;
return false;
}
Expand Down
Loading

0 comments on commit c3f7961

Please sign in to comment.