SERVER-25981 fix race in log component settings

4 files changed, 139 insertions, 22 deletions

diff --git a/src/mongo/logger/SConscript b/src/mongo/logger/SConscript
index 1d7959d9344..d1d5be5831b 100644
--- a/src/mongo/logger/SConscript
+++ b/src/mongo/logger/SConscript
@@ -22,6 +22,10 @@ env.Program('console_test', 'console_test.cpp',
                 LIBDEPS=['$BUILD_DIR/mongo/base',
                          '$BUILD_DIR/mongo/unittest/unittest_main'])
 
+env.CppUnitTest('log_component_settings_test', 'log_component_settings_test.cpp',
+                LIBDEPS=['$BUILD_DIR/mongo/base',
+                         '$BUILD_DIR/mongo/unittest/concurrency'])
+
 env.CppUnitTest('log_test', 'log_test.cpp',
                 LIBDEPS=['$BUILD_DIR/mongo/base'])
 
diff --git a/src/mongo/logger/log_component_settings.cpp b/src/mongo/logger/log_component_settings.cpp
index 8e642793f26..02649ad5fb0 100644
--- a/src/mongo/logger/log_component_settings.cpp
+++ b/src/mongo/logger/log_component_settings.cpp
@@ -35,42 +35,61 @@ namespace mongo {
 namespace logger {
 
 LogComponentSettings::LogComponentSettings() {
-    _minimumLoggedSeverity[LogComponent::kDefault] = LogSeverity::Log().toInt();
+    _minimumLoggedSeverity[LogComponent::kDefault].store(LogSeverity::Log().toInt());
 
     for (int i = 0; i < int(LogComponent::kNumLogComponents); ++i) {
-        _minimumLoggedSeverity[i] = _minimumLoggedSeverity[LogComponent::kDefault];
-        _hasMinimumLoggedSeverity[i] = false;
+        _minimumLoggedSeverity[i].store(_minimumLoggedSeverity[LogComponent::kDefault].load());
+        _hasMinimumLoggedSeverity[i].store(false);
     }
 
-    _hasMinimumLoggedSeverity[LogComponent::kDefault] = true;
+    _hasMinimumLoggedSeverity[LogComponent::kDefault].store(true);
 }
 
 LogComponentSettings::~LogComponentSettings() {}
 
 bool LogComponentSettings::hasMinimumLogSeverity(LogComponent component) const {
     dassert(int(component) >= 0 && int(component) < LogComponent::kNumLogComponents);
-    return _hasMinimumLoggedSeverity[component];
+    return _hasMinimumLoggedSeverity[component].load();
 }
 
 LogSeverity LogComponentSettings::getMinimumLogSeverity(LogComponent component) const {
     dassert(int(component) >= 0 && int(component) < LogComponent::kNumLogComponents);
-    return LogSeverity::cast(_minimumLoggedSeverity[component]);
+    return LogSeverity::cast(_minimumLoggedSeverity[component].load());
 }
 
 void LogComponentSettings::setMinimumLoggedSeverity(LogComponent component, LogSeverity severity) {
     dassert(int(component) >= 0 && int(component) < LogComponent::kNumLogComponents);
-    _minimumLoggedSeverity[component] = severity.toInt();
-    _hasMinimumLoggedSeverity[component] = true;
+    stdx::lock_guard<stdx::mutex> lk(_mtx);
+    _setMinimumLoggedSeverityInLock(component, severity);
+}
+
+void LogComponentSettings::_setMinimumLoggedSeverityInLock(LogComponent component,
+                                                           LogSeverity severity) {
+    _minimumLoggedSeverity[component].store(severity.toInt());
+    _hasMinimumLoggedSeverity[component].store(true);
 
     // Every unconfigured component will inherit log severity from parent.
     // Traversing the severity array once works because child components always
     // come after the parent in the LogComponent::Value enumeration.
     for (int i = 0; i < int(LogComponent::kNumLogComponents); ++i) {
-        if (!_hasMinimumLoggedSeverity[i]) {
+        if (!_hasMinimumLoggedSeverity[i].load()) {
             LogComponent::Value v = LogComponent::Value(i);
             LogComponent parentComponent = LogComponent(v).parent();
             LogSeverity parentSeverity = getMinimumLogSeverity(parentComponent);
-            _minimumLoggedSeverity[i] = parentSeverity.toInt();
+            _minimumLoggedSeverity[i].store(parentSeverity.toInt());
+        }
+    }
+
+    if (kDebugBuild) {
+        // This loop validates the guarantee that either an element has an individual log severity
+        // set or that it's value is equal to its parent's (i.e. either the value is set or
+        // inherited).
+        for (int i = 0; i < int(LogComponent::kNumLogComponents); ++i) {
+            LogComponent::Value v = LogComponent::Value(i);
+            LogComponent parentComponent = LogComponent(v).parent();
+            invariant(_hasMinimumLoggedSeverity[i].load() ||
+                      _minimumLoggedSeverity[i].load() ==
+                          _minimumLoggedSeverity[parentComponent].load());
         }
     }
 }
@@ -78,26 +97,22 @@ void LogComponentSettings::setMinimumLoggedSeverity(LogComponent component, LogS
 void LogComponentSettings::clearMinimumLoggedSeverity(LogComponent component) {
     dassert(int(component) >= 0 && int(component) < LogComponent::kNumLogComponents);
 
+    stdx::lock_guard<stdx::mutex> lk(_mtx);
+
     // LogComponent::kDefault must always be configured.
     if (component == LogComponent::kDefault) {
-        setMinimumLoggedSeverity(component, LogSeverity::Log());
+        _setMinimumLoggedSeverityInLock(component, LogSeverity::Log());
         return;
     }
 
     // Set unconfigured severity level to match LogComponent::kDefault.
-    setMinimumLoggedSeverity(component, getMinimumLogSeverity(component.parent()));
-    _hasMinimumLoggedSeverity[component] = false;
+    _setMinimumLoggedSeverityInLock(component, getMinimumLogSeverity(component.parent()));
+    _hasMinimumLoggedSeverity[component].store(false);
 }
 
 bool LogComponentSettings::shouldLog(LogComponent component, LogSeverity severity) const {
     dassert(int(component) >= 0 && int(component) < LogComponent::kNumLogComponents);
-
-    // Should match parent component if minimum severity level is not configured for
-    // component.
-    dassert(_hasMinimumLoggedSeverity[component] ||
-            _minimumLoggedSeverity[component] == _minimumLoggedSeverity[component.parent()]);
-
-    return severity >= LogSeverity::cast(_minimumLoggedSeverity[component]);
+    return severity >= LogSeverity::cast(_minimumLoggedSeverity[component].loadRelaxed());
 }
 
 }  // logger
diff --git a/src/mongo/logger/log_component_settings.h b/src/mongo/logger/log_component_settings.h
index 0e9a7bc81ae..22d1ad27161 100644
--- a/src/mongo/logger/log_component_settings.h
+++ b/src/mongo/logger/log_component_settings.h
@@ -30,6 +30,8 @@
 #include "mongo/base/disallow_copying.h"
 #include "mongo/logger/log_component.h"
 #include "mongo/logger/log_severity.h"
+#include "mongo/platform/atomic_word.h"
+#include "mongo/stdx/mutex.h"
 
 namespace mongo {
 namespace logger {
@@ -79,17 +81,23 @@ public:
     bool shouldLog(LogComponent component, LogSeverity severity) const;
 
 private:
+    void _setMinimumLoggedSeverityInLock(LogComponent component, LogSeverity severity);
+
+    // A mutex to synchronize writes to the severity arrays. This mutex is to synchronize changes to
+    // the entire array, and the atomics are to synchronize individual elements.
+    stdx::mutex _mtx;
+
     // True if a log severity is explicitly set for a component.
     // This differentiates between unconfigured components and components that happen to have
     // the same severity as kDefault.
     // This is also used to update the severities of unconfigured components when the severity
     // for kDefault is modified.
-    bool _hasMinimumLoggedSeverity[LogComponent::kNumLogComponents];
+    AtomicBool _hasMinimumLoggedSeverity[LogComponent::kNumLogComponents];
 
     // Log severities for components.
     // Store numerical values of severities to be cache-line friendly.
     // Set to kDefault minimum logged severity if _hasMinimumLoggedSeverity[i] is false.
-    signed char _minimumLoggedSeverity[LogComponent::kNumLogComponents];
+    AtomicInt32 _minimumLoggedSeverity[LogComponent::kNumLogComponents];
 };
 
 }  // namespace logger
diff --git a/src/mongo/logger/log_component_settings_test.cpp b/src/mongo/logger/log_component_settings_test.cpp
new file mode 100644
index 00000000000..6f663c7729c
--- /dev/null
+++ b/src/mongo/logger/log_component_settings_test.cpp
@@ -0,0 +1,90 @@
+/**
+ *    Copyright (C) 2016 MongoDB Inc.
+ *
+ *    This program is free software: you can redistribute it and/or  modify
+ *    it under the terms of the GNU Affero General Public License, version 3,
+ *    as published by the Free Software Foundation.
+ *
+ *    This program is distributed in the hope that it will be useful,
+ *    but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *    GNU Affero General Public License for more details.
+ *
+ *    You should have received a copy of the GNU Affero General Public License
+ *    along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ *    As a special exception, the copyright holders give permission to link the
+ *    code of portions of this program with the OpenSSL library under certain
+ *    conditions as described in each individual source file and distribute
+ *    linked combinations including the program with the OpenSSL library. You
+ *    must comply with the GNU Affero General Public License in all respects for
+ *    all of the code used other than as permitted herein. If you modify file(s)
+ *    with this exception, you may extend this exception to your version of the
+ *    file(s), but you are not obligated to do so. If you do not wish to do so,
+ *    delete this exception statement from your version. If you delete this
+ *    exception statement from all source files in the program, then also delete
+ *    it in the license file.
+ */
+
+#include "mongo/platform/basic.h"
+
+#include "mongo/logger/log_component.h"
+#include "mongo/logger/log_component_settings.h"
+#include "mongo/logger/logger.h"
+#include "mongo/platform/atomic_word.h"
+#include "mongo/stdx/thread.h"
+#include "mongo/unittest/barrier.h"
+
+#include "mongo/unittest/unittest.h"
+
+namespace {
+
+using namespace mongo;
+using namespace mongo::logger;
+
+// This test checks that calling "shouldLog" and "setMinimumLoggedSeverity" concurrently doesn't
+// cause an invariant failure, i.e. that these methods are thread-safe.
+TEST(SERVER25981Test, SetSeverityShouldLogAndClear) {
+    unittest::Barrier startupBarrier(4);
+    AtomicBool running(true);
+
+    stdx::thread shouldLogThread([&]() {
+        startupBarrier.countDownAndWait();
+        while (running.load()) {
+            logger::globalLogDomain()->shouldLog(LogComponent::kDefault,
+                                                 logger::LogSeverity::Debug(3));
+        }
+    });
+
+    stdx::thread setMinimumLoggedSeverityThreadA([&]() {
+        startupBarrier.countDownAndWait();
+        while (running.load()) {
+            logger::globalLogDomain()->setMinimumLoggedSeverity(LogComponent::kDefault,
+                                                                logger::LogSeverity::Debug(1));
+        }
+    });
+
+    stdx::thread setMinimumLoggedSeverityThreadB([&]() {
+        startupBarrier.countDownAndWait();
+        while (running.load()) {
+            logger::globalLogDomain()->setMinimumLoggedSeverity(LogComponent::kDefault,
+                                                                logger::LogSeverity::Log());
+        }
+    });
+
+    stdx::thread clearMinimumLoggedSeverityThread([&]() {
+        startupBarrier.countDownAndWait();
+        while (running.load()) {
+            logger::globalLogDomain()->clearMinimumLoggedSeverity(LogComponent::kDefault);
+        }
+    });
+
+    mongo::sleepmillis(4000);
+    running.store(false);
+    shouldLogThread.join();
+    setMinimumLoggedSeverityThreadA.join();
+    setMinimumLoggedSeverityThreadB.join();
+    clearMinimumLoggedSeverityThread.join();
+}
+
+}  // namespace