nvmedevice: fix tight event cycle grace period race conditions This commit resolves two race conditions that could bypass the tight event cycle grace period mitigation: 1. Ghost Callback Race: A `Degraded` or `Removed` event could be processed immediately after the grace period timer expires but before the ASIO queue executes the timer callback. Relying solely on `recovering` was insufficient (especially for `Removed` events), leading to an unwanted NVMe interface start on a device that was just stopped. 2. Consecutive Available Bypass: Back-to-back `Available` events during the grace period bypassed the `recovering` boolean logic and immediately started the interface, completely negating the grace period. Both race conditions are now closed by introducing a `gracePeriodActive` state variable. We now safely verify this state within the async timer callback before starting the device, and explicitly ignore consecutive `Available` events when the ASIO timer is actively running. Testing: - Added `consecutiveAvailableBypass` unit test to verify that consecutive `Available` events do not bypass the grace period timer. Tested: all unitest passed Change-Id: Iced289dd4da6692dc3353e4814228eacaa6f2c97 Signed-off-by: Hao Jiang <jianghao@google.com>
diff --git a/src/NVMeDevice.cpp b/src/NVMeDevice.cpp index 98877b5..dcce6de 100644 --- a/src/NVMeDevice.cpp +++ b/src/NVMeDevice.cpp
@@ -1,6 +1,7 @@ #include "NVMeDevice.hpp" #include <boost/system/detail/error_code.hpp> +#include <phosphor-logging/lg2.hpp> #include <cassert> @@ -88,8 +89,9 @@ void NVMeDevice::degraded(const std::shared_ptr<MctpEndpoint>& ep) { assert(intf.getProtocol() == NVMeIntf::Protocol::NVMeMI); - std::cout << "[" << ep->describe() << "]: Degraded\n"; + lg2::info("[{ENDPOINT}]: Degraded", "ENDPOINT", ep->describe()); recovering = true; + gracePeriodActive = false; timer->cancel(); std::get<std::shared_ptr<NVMeMiIntf>>(intf.getInferface())->stop(); } @@ -99,8 +101,8 @@ assert(intf.getProtocol() == NVMeIntf::Protocol::NVMeMI); assert(timer); assert(gracePeriod); - std::cout << subsys->getName() << " [" << ep->describe() - << "]: Available\n"; + lg2::info("[{SUBSYS}][{ENDPOINT}]: Available", "SUBSYS", subsys->getName(), + "ENDPOINT", ep->describe()); // The behaviour of MctpEndpoint::subscribe() is to register the provided // callbacks, and then fetch the current state of the endpoint. As a @@ -138,18 +140,61 @@ // at risk of the tight event cycle, therefore we enforce the grace-period. // If we've not passed through 'Degraded' but we have an 'Available' event // we know we're in the start-up path, which we don't want to delay. + // + // State machine for events and grace period: + // ```mermaid + // stateDiagram-v2 + // [*] --> Setup : Device Initialized + // + // state "Setup (Initial State)" as Setup + // state "Active (Interface Started)" as Active + // state "Degraded State\n(recovering = true)" as Degraded + // state "Grace Period Active\n(Timer Ticking)" as GracePeriod + // + // %% Setup transitions + // Setup --> Active : Available Event\n(Bypasses Grace Period) + // Setup --> Degraded : Degraded Event + // + // %% Active transitions + // Active --> Degraded : Degraded Event\n(Stops Interface) + // Active --> Setup : Removed Event\n(Stops Interface, Restarts) + // + // %% Degraded transitions + // Degraded --> GracePeriod : Available Event\n(Sets + // recovering=false,\nStarts Timer) Degraded --> Setup : Removed + // Event\n(Stops Interface, Restarts) + // + // %% Grace Period transitions + // GracePeriod --> Active : Timer Expires\n(Starts Interface) + // GracePeriod --> GracePeriod : Available Event\n(Ignored, Timer + // Continues) GracePeriod --> Degraded : Degraded Event\n(Cancels Timer, + // Stops Interface) GracePeriod --> Setup : Removed Event\n(Cancels + // Timer, Restarts) + // ``` if (recovering) { recovering = false; + gracePeriodActive = true; timer->expires_after(*gracePeriod); timer->async_wait( [weak{weak_from_this()}, ep](const boost::system::error_code& ec) { - if (ec) - { - return; - } if (auto self = weak.lock()) { + if (ec) + { + self->gracePeriodActive = false; + lg2::info( + "[{ENDPOINT}] grace period expired due to: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", ec.message()); + return; + } + // Ensure we haven't degraded or been removed while the + // callback was waiting in the ASIO event queue. + if (!self->gracePeriodActive) + { + return; + } + self->gracePeriodActive = false; std::get<std::shared_ptr<NVMeMiIntf>>(self->intf.getInferface()) ->start(ep); } @@ -157,15 +202,22 @@ } else { + // If the grace period is actively running, this is a consecutive + // Available event. We ignore it to avoid bypassing the grace period. + if (gracePeriodActive) + { + return; + } + // If we're not recovering we should only see an 'Available' event // when we're first initialising the device. There should be no timers // to cancel. std::size_t cancelled = timer->cancel(); if (cancelled != 0) { - std::cerr << "[ " << ep->describe() - << "]: Unexpected timer cancellation (" << cancelled - << ") in non-recovery path!\n"; + lg2::error( + "[{ENDPOINT}]: Unexpected timer cancellation ({CANCELLED}) in non-recovery path!", + "ENDPOINT", ep->describe(), "CANCELLED", cancelled); } std::get<std::shared_ptr<NVMeMiIntf>>(intf.getInferface())->start(ep); } @@ -174,8 +226,9 @@ void NVMeDevice::removed(const std::shared_ptr<MctpEndpoint>& ep) { assert(intf.getProtocol() == NVMeIntf::Protocol::NVMeMI); - std::cout << "[" << ep->describe() << "]: Removed\n"; + lg2::info("[{ENDPOINT}]: Removed", "ENDPOINT", ep->describe()); recovering = false; + gracePeriodActive = false; std::get<std::shared_ptr<NVMeMiIntf>>(intf.getInferface())->stop(); restart(); }
diff --git a/src/NVMeDevice.hpp b/src/NVMeDevice.hpp index feb40d7..fe1952f 100644 --- a/src/NVMeDevice.hpp +++ b/src/NVMeDevice.hpp
@@ -59,4 +59,5 @@ std::optional<boost::asio::steady_timer> timer; std::optional<std::chrono::seconds> gracePeriod; bool recovering{}; + bool gracePeriodActive{}; };
diff --git a/tests/test_nvme_mi_recovery.cpp b/tests/test_nvme_mi_recovery.cpp index 00f4714..0065e8e 100644 --- a/tests/test_nvme_mi_recovery.cpp +++ b/tests/test_nvme_mi_recovery.cpp
@@ -41,6 +41,24 @@ MOCK_METHOD(std::string, describe, (), (const, override)); }; +class TestNVMeMi : public NVMeMi +{ + public: + using NVMeMi::NVMeMi; + bool isStarted = false; + + void start(const std::shared_ptr<MctpEndpoint>& ep) override + { + isStarted = true; + NVMeMi::start(ep); + } + void stop() override + { + isStarted = false; + NVMeMi::stop(); + } +}; + TEST(NVMeRecovery, optimisationFailure) { boost::asio::io_context io; @@ -106,6 +124,179 @@ io.run(); } +TEST(NVMeRecovery, tightEventCycle) +{ + boost::asio::io_context io; + + auto mctpEp = std::make_shared<MockMctpEndpoint>(); + EXPECT_CALL(*mctpEp, describe()) + .WillRepeatedly(testing::Return("Mock MCTP Endpoint")); + EXPECT_CALL(*mctpEp, eid()).WillRepeatedly(testing::Return(9)); + EXPECT_CALL(*mctpEp, network()).WillRepeatedly(testing::Return(1)); + EXPECT_CALL(*mctpEp, isI2cAccessible()) + .WillRepeatedly(testing::Return(true)); + + boost::asio::spawn(io, [&](boost::asio::yield_context yield) { + MctpEndpoint::Event degradedHandler; + MctpEndpoint::Event availableHandler; + MctpEndpoint::Event removedHandler; + EXPECT_CALL(*mctpEp, subscribe(testing::_, testing::_, testing::_)) + .WillOnce(testing::DoAll(testing::SaveArg<0>(°radedHandler), + testing::SaveArg<1>(&availableHandler), + testing::SaveArg<2>(&removedHandler), + testing::InvokeWithoutArgs([&]() { + io.post([&]() { availableHandler(mctpEp); }); + }))); + EXPECT_CALL(*mctpEp, recover()).Times(testing::AnyNumber()); + + boost::asio::steady_timer timer(io); + auto mctpDev = std::make_shared<MockMctpDevice>(); + EXPECT_CALL(*mctpDev, describe()) + .WillRepeatedly(testing::Return("Mock MCTP Device")); + EXPECT_CALL(*mctpDev, setup(testing::_)) + .WillOnce(testing::InvokeArgument<0>(std::error_code(), mctpEp)); + + auto systemBus = std::make_shared<sdbusplus::asio::connection>(io); + sdbusplus::asio::object_server objectServer(systemBus, true); + auto worker = NVMeMiWorker::create(io); + auto intf = NVMeIntf::create<TestNVMeMi>(io, systemBus, mctpDev, + worker); + auto testMi = std::dynamic_pointer_cast<TestNVMeMi>( + std::get<std::shared_ptr<NVMeMiIntf>>(intf.getInferface())); + SensorData sensorData{}; + auto subsys = NVMeSubsystem::create(io, objectServer, systemBus, "/foo", + "bar", sensorData, intf, false); + auto nvmeDev = NVMeDevice::create(io, mctpDev, std::move(intf), subsys, + std::chrono::seconds(2)); + nvmeDev->start(); + + // Wait for initial available handler to fire + timer.expires_after(std::chrono::milliseconds(100)); + timer.async_wait(yield); + + // 1. Degrade + degradedHandler(mctpEp); + + // 2. Wait < 1 sec + timer.expires_after(std::chrono::milliseconds(500)); + timer.async_wait(yield); + + // 3. Available + availableHandler(mctpEp); + + // 4. Wait < 1 sec again (before 2s grace period ends) + timer.expires_after(std::chrono::milliseconds(500)); + timer.async_wait(yield); + + // 5. Degrade + degradedHandler(mctpEp); + + // Let things settle to ensure no crashes + timer.expires_after(std::chrono::seconds(2)); + timer.async_wait(yield); + + // Validate the final state for the mctpEp should be degraded + EXPECT_FALSE(testMi->isStarted); + + nvmeDev->stop(); + + timer.expires_after(std::chrono::seconds(1)); + timer.async_wait(yield); + + EXPECT_TRUE(testing::Mock::VerifyAndClearExpectations(mctpEp.get())); + EXPECT_TRUE(testing::Mock::VerifyAndClearExpectations(mctpDev.get())); + io.stop(); + }); + + io.run(); +} + +TEST(NVMeRecovery, consecutiveAvailableBypass) +{ + boost::asio::io_context io; + + auto mctpEp = std::make_shared<MockMctpEndpoint>(); + EXPECT_CALL(*mctpEp, describe()) + .WillRepeatedly(testing::Return("Mock MCTP Endpoint")); + EXPECT_CALL(*mctpEp, eid()).WillRepeatedly(testing::Return(9)); + EXPECT_CALL(*mctpEp, network()).WillRepeatedly(testing::Return(1)); + EXPECT_CALL(*mctpEp, isI2cAccessible()) + .WillRepeatedly(testing::Return(true)); + + boost::asio::spawn(io, [&](boost::asio::yield_context yield) { + MctpEndpoint::Event degradedHandler; + MctpEndpoint::Event availableHandler; + MctpEndpoint::Event removedHandler; + EXPECT_CALL(*mctpEp, subscribe(testing::_, testing::_, testing::_)) + .WillOnce(testing::DoAll(testing::SaveArg<0>(°radedHandler), + testing::SaveArg<1>(&availableHandler), + testing::SaveArg<2>(&removedHandler), + testing::InvokeWithoutArgs([&]() { + io.post([&]() { availableHandler(mctpEp); }); + }))); + EXPECT_CALL(*mctpEp, recover()).Times(testing::AnyNumber()); + + boost::asio::steady_timer timer(io); + auto mctpDev = std::make_shared<MockMctpDevice>(); + EXPECT_CALL(*mctpDev, describe()) + .WillRepeatedly(testing::Return("Mock MCTP Device")); + EXPECT_CALL(*mctpDev, setup(testing::_)) + .WillOnce(testing::InvokeArgument<0>(std::error_code(), mctpEp)); + + auto systemBus = std::make_shared<sdbusplus::asio::connection>(io); + sdbusplus::asio::object_server objectServer(systemBus, true); + auto worker = NVMeMiWorker::create(io); + auto intf = NVMeIntf::create<TestNVMeMi>(io, systemBus, mctpDev, + worker); + auto testMi = std::dynamic_pointer_cast<TestNVMeMi>( + std::get<std::shared_ptr<NVMeMiIntf>>(intf.getInferface())); + SensorData sensorData{}; + auto subsys = NVMeSubsystem::create(io, objectServer, systemBus, "/foo", + "bar", sensorData, intf, false); + auto nvmeDev = NVMeDevice::create(io, mctpDev, std::move(intf), subsys, + std::chrono::seconds(2)); + nvmeDev->start(); + + // Wait for initial available handler to fire + timer.expires_after(std::chrono::milliseconds(100)); + timer.async_wait(yield); + + // 1. Degrade + degradedHandler(mctpEp); + EXPECT_FALSE(testMi->isStarted); + + // 2. Available (starts 2s timer) + availableHandler(mctpEp); + EXPECT_FALSE(testMi->isStarted); + + // 3. Wait 0.5s, well within the 2s grace period + timer.expires_after(std::chrono::milliseconds(500)); + timer.async_wait(yield); + + // 4. Consecutive Available + // The current buggy code bypasses the grace period here and calls + // start() immediately. + availableHandler(mctpEp); + EXPECT_FALSE(testMi->isStarted); + + // 5. Wait for the remainder of the 2s grace period + timer.expires_after(std::chrono::seconds(2)); + timer.async_wait(yield); + + EXPECT_TRUE(testMi->isStarted); + + nvmeDev->stop(); + + timer.expires_after(std::chrono::seconds(1)); + timer.async_wait(yield); + + EXPECT_TRUE(testing::Mock::VerifyAndClearExpectations(mctpEp.get())); + EXPECT_TRUE(testing::Mock::VerifyAndClearExpectations(mctpDev.get())); + io.stop(); + }); + + io.run(); +} // Unused, but required to link successfully std::unordered_map<std::string, void*> pluginLibMap = {};