Simulation will return and error and print if any non-suppressed SevError events were logged.

This means that loops like `seed=1; while ./fdbserver -r simulation -s $seed;
do seed=$(($seed+1)); done` to find an example of an often failing test.  This
also means joshua will report ExitCode errors on anything that has a SevError
in the log.

As a part of this, we also implicitly downgrade any injected errors to SevWarnAlways.
This commit is contained in:
Alex Miller 2017-12-15 18:20:33 -08:00
parent 7ce93426ed
commit 1488c12c18
3 changed files with 24 additions and 1 deletions

View File

@ -1675,6 +1675,13 @@ int main(int argc, char* argv[]) {
for(auto i = processes.begin(); i != processes.end(); ++i) for(auto i = processes.begin(); i != processes.end(); ++i)
printf("%s %s: %0.3f Mclocks\n", (*i)->name, (*i)->address.toString().c_str(), (*i)->cpuTicks / 1e6); printf("%s %s: %0.3f Mclocks\n", (*i)->name, (*i)->address.toString().c_str(), (*i)->cpuTicks / 1e6);
} }
if (role == Simulation) {
unsigned long sevErrorEventsLogged = TraceEvent::CountEventsLoggedAt(SevError);
if (sevErrorEventsLogged > 0) {
printf("%lu SevError events logged\n", sevErrorEventsLogged);
rc = FDB_EXIT_ERROR;
}
}
//g_simulator.run(); //g_simulator.run();

View File

@ -695,8 +695,10 @@ TraceEvent& TraceEvent::error(class Error const& error, bool includeCancelled) {
// Suppress the entire message // Suppress the entire message
enabled = false; enabled = false;
} else { } else {
if (error.isInjectedFault()) if (error.isInjectedFault()) {
detail("ErrorIsInjectedFault", true); detail("ErrorIsInjectedFault", true);
if (severity == SevError) severity = SevWarnAlways;
}
detail("Error", error.name()); detail("Error", error.name());
detail("ErrorDescription", error.what()); detail("ErrorDescription", error.what());
detail("ErrorCode", error.code()); detail("ErrorCode", error.code());
@ -856,6 +858,14 @@ TraceEvent& TraceEvent::GetLastError() {
#endif #endif
} }
// We're cheating in counting, as in practice, we only use {10,20,30,40}.
static_assert(SevMaxUsed / 10 + 1 == 5, "Please bump eventCounts[5] to SevMaxUsed/10+1");
unsigned long TraceEvent::eventCounts[5] = {0,0,0,0,0};
unsigned long TraceEvent::CountEventsLoggedAt(Severity sev) {
return TraceEvent::eventCounts[sev/10];
}
TraceEvent& TraceEvent::backtrace(std::string prefix) { TraceEvent& TraceEvent::backtrace(std::string prefix) {
if (this->severity == SevError) return *this; // We'll backtrace this later in ~TraceEvent if (this->severity == SevError) return *this; // We'll backtrace this later in ~TraceEvent
return detail((prefix + "Backtrace").c_str(), platform::get_backtrace()); return detail((prefix + "Backtrace").c_str(), platform::get_backtrace());
@ -898,6 +908,7 @@ TraceEvent::~TraceEvent() {
if (g_traceLog.isOpen()) { if (g_traceLog.isOpen()) {
writef("/>\r\n"); writef("/>\r\n");
g_traceLog.write( buffer, length ); g_traceLog.write( buffer, length );
TraceEvent::eventCounts[severity/10]++;
// Log Metrics // Log Metrics
if(g_traceLog.logTraceEventMetrics && *type != '\0' && isNetworkThread()) { if(g_traceLog.logTraceEventMetrics && *type != '\0' && isNetworkThread()) {

View File

@ -48,6 +48,7 @@ enum Severity {
SevWarn=20, SevWarn=20,
SevWarnAlways=30, SevWarnAlways=30,
SevError=40, SevError=40,
SevMaxUsed=SevError,
SevMax=1000000 SevMax=1000000
}; };
@ -142,6 +143,9 @@ public:
~TraceEvent(); // Actually logs the event ~TraceEvent(); // Actually logs the event
// Return the number of invocations of TraceEvent() at the specified logging level.
static unsigned long CountEventsLoggedAt(Severity);
DynamicEventMetric *tmpEventMetric; // This just just a place to store fields DynamicEventMetric *tmpEventMetric; // This just just a place to store fields
private: private:
@ -153,6 +157,7 @@ private:
const char *type; const char *type;
UID id; UID id;
static unsigned long eventCounts[5];
static thread_local bool networkThread; static thread_local bool networkThread;
bool init( Severity, const char* type ); bool init( Severity, const char* type );