MB-33637: Fix memcached testapp ChangeVerbosity LoggingTest

This test is currently flawed for multiple reasons.

1) When run in non-embedded mode (every CV run) the test looks will
always pass because the cb::logger::checkLogLevels() call will look
in the registry belonging to the testapp process and not the
memcached process. This means that it will find no loggers to check
the verbosity of, and will always return true.

2) The test log levels are the wrong way around.

3) The test is racey. We might attempt to shut down the memcached
server before the thread that changes verbosity completes execution.
This thread will segfault when it logs if this is the case.

Fix this test by:

a) Creating an EWB command that returns SUCCESS if the log levels are
the correct value.

b) Fixing the log level mapping.

c) Runing the verbosity change in the memcached worker thread. It's
a quick operation that will only block if we are registering or
unregistered loggers (creating/destroying buckets/DCP connections).
Verbosity changing is also very infrequently used.


Change-Id: I1b9d36217e7108b44663b8f5bcf013ceae6a4050
Reviewed-on: http://review.couchbase.org/107289
Tested-by: Build Bot <[email protected]>
Reviewed-by: Dave Rigby <[email protected]>

Author: BenHuddleston

daemon/memcached.cc

@@ -264,7 +264,7 @@ void associate_initial_bucket(Connection& connection) {
     }
 }
 
-static void populate_log_level(void*) {
+static void populate_log_level() {
     const auto val = settings.getLogLevel();
 
     // Log the verbosity value set by the user and not the log level as they
@@ -278,8 +278,6 @@ void perform_callbacks(ENGINE_EVENT_TYPE type,
                        const void *data,
                        const void *void_cookie)
 {
-    cb_thread_t tid;
-
     switch (type) {
         /*
          * The following events operates on a connection which is passed in
@@ -316,11 +314,12 @@ void perform_callbacks(ENGINE_EVENT_TYPE type,
         }
 
         if (service_online) {
-            if (cb_create_thread(&tid, populate_log_level, nullptr, 1) == -1) {
-                LOG_WARNING(
-                        "Failed to create thread to notify engines about "
-                        "changing log level");
-            }
+            // MB-33637: Make the verbosity change in the calling thread.
+            // This should be a relatively quick operation as we only block if
+            // we are registering or unregistering new loggers. It also prevents
+            // a race condition on shutdown where we could attempt to log
+            // something but the logger has already been destroyed.
+            populate_log_level();
         }
         break;
 

engines/ewouldblock_engine/ewouldblock_engine.cc

@@ -618,6 +618,9 @@ class EWB_Engine : public EngineIface, public DcpIface {
 
                 case EWBEngineMode::SetItemCas:
                     return setItemCas(cookie, key, value, response);
+
+                case EWBEngineMode::CheckLogLevels:
+                    return checkLogLevels(cookie, value, response);
             }
 
             if (new_mode == nullptr) {
@@ -1012,6 +1015,10 @@ class EWB_Engine : public EngineIface, public DcpIface {
                                  uint32_t cas,
                                  const AddResponseFn& response);
 
+    ENGINE_ERROR_CODE checkLogLevels(const void* cookie,
+                                     uint32_t value,
+                                     const AddResponseFn& response);
+
 private:
     // Shared state between the main thread of execution and the background
     // thread processing pending io ops.
@@ -1988,6 +1995,25 @@ ENGINE_ERROR_CODE EWB_Engine::setItemCas(const void* cookie,
     return ENGINE_SUCCESS;
 }
 
+ENGINE_ERROR_CODE EWB_Engine::checkLogLevels(const void* cookie,
+                                             uint32_t value,
+                                             const AddResponseFn& response) {
+    auto level = spdlog::level::level_enum(value);
+    auto rsp = cb::logger::checkLogLevels(level);
+
+    response(nullptr,
+             0,
+             nullptr,
+             0,
+             nullptr,
+             0,
+             PROTOCOL_BINARY_RAW_BYTES,
+             rsp ? cb::mcbp::Status::Success : cb::mcbp::Status::Einval,
+             0,
+             cookie);
+    return ENGINE_SUCCESS;
+}
+
 cb::engine_errc EWB_Engine::set_collection_manifest(
         gsl::not_null<const void*> cookie, cb::const_char_buffer json) {
     return real_engine->set_collection_manifest(cookie, json);

engines/ewouldblock_engine/ewouldblock_engine.h

@@ -81,5 +81,10 @@ enum class EWBEngineMode : uint32_t {
     // Set the CAS for an item.
     // Requires the CAS of the item. Bear in mind that we're limited to
     // 32 bits.
-    SetItemCas = 10
+    SetItemCas = 10,
+
+    // Make a single call to cb::logger::check_levels and return the result.
+    // This allows us to verify that all of the registered logger instances are
+    // set to the correct level.
+    CheckLogLevels = 11,
 };

tests/testapp/testapp_logging.cc

@@ -36,7 +36,7 @@ class LoggingTest : public TestappTest,
 
         // Fail this test if the connection does not return a successful
         // response
-        EXPECT_TRUE(rsp.isSuccess());
+        ASSERT_TRUE(rsp.isSuccess());
     }
 };
 
@@ -46,17 +46,22 @@ TEST_P(LoggingTest, ChangeVerbosity) {
     spdlog::level::level_enum level;
     switch (GetParam()) {
     case 0:
-        level = spdlog::level::trace;
+        level = spdlog::level::info;
         break;
     case 1:
         level = spdlog::level::debug;
         break;
-    default: /* We default to 2 if a greater number is specified */
-        level = spdlog::level::info;
+    default:
+        level = spdlog::level::trace;
         break;
     }
 
-    EXPECT_TRUE(cb::logger::checkLogLevels(level));
+    // The configure function will check the response and fail the test if not
+    // ENGINE_SUCCESS.
+    ewouldblock_engine_configure(ENGINE_ERROR_CODE::ENGINE_SUCCESS,
+                                 EWBEngineMode::CheckLogLevels,
+                                 level,
+                                 "key");
 }
 
 // Test with verbosity values 0, 1, 2