NVMe: Add component tag to the logs Originally when switch to lg2, we missed some component tag. Also some log print didn't have the component tag initially. They created trouble for debugging when multiple NVMe device work together. Tested: N/A Change-Id: I88e31bd4be8820062663a5f4b249855863b54408 Signed-off-by: Hao Jiang <jianghao@google.com>
diff --git a/src/NVMeCacheImpl.hpp b/src/NVMeCacheImpl.hpp index 4717cd8..d79b6cf 100644 --- a/src/NVMeCacheImpl.hpp +++ b/src/NVMeCacheImpl.hpp
@@ -120,8 +120,8 @@ ControllerLogPageMetric<LID, ClockType, DA>>(weakSelf.lock()); if (!self) { - lg2::info("metric released before callback", "PATH", path, "ID", - id); + lg2::info("[{PATH},{ID}]metric released before callback", + "PATH", path, "ID", id); // The Scheduler will clear the invalid cache Task cb({}, 4096, true); return; @@ -132,17 +132,17 @@ if (self->errorCount < ControllerLogPageMetric<LID, ClockType, DA>::errorCountMax) { - lg2::warning("fail to fresh log page at retry({RETRY})", - "PATH", path, "ID", id, "RETRY", - self->errorCount++); + lg2::warning( + "[{PATH},{ID}]fail to fresh log page at retry({RETRY})", + "PATH", path, "ID", id, "RETRY", self->errorCount++); // Schedule the retry after 1s // TODO: costomize the retry delay for each log pages. cb(std::make_error_code(std::errc::io_error), 4096, false); return; } - lg2::error("retry exhausted to fresh log page", "PATH", path, - "ID", id); + lg2::error("[{PATH},{ID}]retry exhausted to fresh log page", + "PATH", path, "ID", id); self->cacheValid = false; // Notify the RefreshCB with error code; the task will @@ -266,8 +266,8 @@ weakSelf.lock()); if (!self) { - lg2::info("metric released before callback", "PATH", path, "ID", - id); + lg2::info("[{PATH},{ID}]metric released before callback", + "PATH", path, "ID", id); // The Scheduler will clear the invalid cache Task cb({}, 4096, true); return; @@ -278,7 +278,7 @@ IdentifyMetric<CNS, ClockType>::errorCountMax) { lg2::warning( - "fail to fresh identify at retry({RETRY}): {ERROR}", + "[{PATH},{ID}]fail to fresh identify at retry({RETRY}): {ERROR}", "PATH", path, "ID", id, "RETRY", self->errorCount++, "ERROR", ex->description()); @@ -286,8 +286,9 @@ cb(std::make_error_code(std::errc::io_error), 4096, false); return; } - lg2::error("retry exhausted to fresh identify: {ERROR}", "PATH", - path, "ID", id, "ERROR", ex->description()); + lg2::error( + "[{PATH},{ID}]retry exhausted to fresh identify: {ERROR}", + "PATH", path, "ID", id, "ERROR", ex->description()); self->cacheValid = false; // Notify the RefreshCB with error code; the task will
diff --git a/src/NVMeController.cpp b/src/NVMeController.cpp index 7917aa6..3dcce85 100644 --- a/src/NVMeController.cpp +++ b/src/NVMeController.cpp
@@ -147,7 +147,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } return self->adminNonDataCmdMethod(std::move(yield), opcode, cdw1, cdw2, @@ -172,7 +173,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -194,7 +196,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -226,7 +229,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error:: Unavailable(); } @@ -255,7 +259,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -275,7 +280,8 @@ if (self->status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", + self->path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -304,7 +310,7 @@ return; } - lg2::info("NVMe version for controller {PATH}: {VERSION}", "PATH", path, + lg2::info("[{PATH}] NVMe version for controller: {VERSION}", "PATH", path, "VERSION", lg2::hex, nvmeVersion); discoverSupportedLogPages(); @@ -451,7 +457,7 @@ } lg2::info( - "Querying Supported Log Pages (00h) for NVMe 2.0+ controller: {PATH}", + "[{PATH}] Querying Supported Log Pages (00h) for NVMe 2.0+ controller", "PATH", path); discoverLogsToken = std::make_shared<bool>(); @@ -467,13 +473,15 @@ nvmeIntf->adminGetLogPage( nvmeCtrl, NVME_LOG_LID_SUPPORTED_LOG_PAGES, NVME_NSID_NONE, 0, 0, - [weakSelf, retryCount, weakToken](const std::error_code& ec, - std::span<uint8_t> data) mutable { + [weakSelf, retryCount, weakToken, path = this->path]( + const std::error_code& ec, std::span<uint8_t> data) mutable { auto self = weakSelf.lock(); if (!self || weakToken.expired()) { - lg2::info("Skipping fetchSupportedLogPages as token expired " - "or controller destroyed"); + lg2::info( + "[{PATH}]Skipping fetchSupportedLogPages as token expired " + "or controller destroyed", + "PATH", path); return; } @@ -489,15 +497,17 @@ self->discoverLogsRetryTimer->expires_after( std::chrono::milliseconds(discoverLogsBackoffMs)); self->discoverLogsRetryTimer->async_wait( - [weakSelf, retryCount, - weakToken](const boost::system::error_code& timerEc) { + [weakSelf, retryCount, weakToken, + path](const boost::system::error_code& timerEc) { auto self = weakSelf.lock(); if (!self || weakToken.expired() || timerEc == boost::asio::error::operation_aborted) { - lg2::info("Skipping fetchSupportedLogPages as token " - "expired or timer canceled or controller " - "destroyed"); + lg2::info( + "[{PATH}]Skipping fetchSupportedLogPages as token " + "expired or timer canceled or controller " + "destroyed", + "PATH", path); return; // Destructed or cancelled naturally! } self->fetchSupportedLogPages(retryCount + 1, weakToken); @@ -506,8 +516,8 @@ } lg2::error( - "{PATH}: Failed to get Supported Log Pages (00h): {ERROR}", - "PATH", self->path, "ERROR", ec.message()); + "[{PATH}] Failed to get Supported Log Pages (00h): {ERROR}", + "PATH", path, "ERROR", ec.message()); self->supportedLogPages.clear(); self->populateMetricStore(); return; @@ -516,8 +526,8 @@ if (data.size() < 1024) { lg2::error( - "{PATH}: Undersized Supported Log Pages payload ({SIZE} bytes)", - "PATH", self->path, "SIZE", data.size()); + "[{PATH}] Undersized Supported Log Pages payload ({SIZE} bytes)", + "PATH", path, "SIZE", data.size()); self->supportedLogPages.clear(); self->populateMetricStore(); return; @@ -539,11 +549,11 @@ std::make_shared<FeatureStore>(io, objServer, conn, path, nvmeIntf, nvmeCtrl, 0, FeatureScope::Controller); - this->featureStore->init([](const std::error_code& ec) { + this->featureStore->init([path = this->path](const std::error_code& ec) { if (ec) { - lg2::error("Failed to initialize feature store: {ERROR}", "ERROR", - ec.message()); + lg2::error("[{PATH}]Failed to initialize feature store: {ERROR}", + "PATH", path, "ERROR", ec.message()); } }); } @@ -600,7 +610,7 @@ auto s = subsys.lock(); if (!s) { - lg2::error("makeAssociation() after shutdown"); + lg2::error("[{PATH}]makeAssociation() after shutdown", "PATH", path); return associations; } @@ -627,15 +637,15 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - lg2::error("GetLogPage fails to open pipe: {ERROR}", "ERROR", - strerror(errno)); + lg2::error("[{PATH}]GetLogPage fails to open pipe: {ERROR}", "PATH", + path, "ERROR", strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open(); } @@ -644,12 +654,12 @@ { nvmeIntf->adminGetLogPage( nvmeCtrl, static_cast<nvme_cmd_get_log_lid>(lid), nsid, lsp, lsi, - [pipe, &io = this->io](const std::error_code& ec, - std::span<uint8_t> data) { + [pipe, &io = this->io, path = this->path](const std::error_code& ec, + std::span<uint8_t> data) { if (ec) { - lg2::error("fail to GetLogPage: {ERROR}", "ERROR", - ec.message()); + lg2::error("[{PATH}]fail to GetLogPage: {ERROR}", "PATH", path, + "ERROR", ec.message()); close(pipe[1]); close(pipe[0]); return; @@ -664,14 +674,15 @@ auto asyncBuffer = std::make_shared<std::vector<uint8_t>>( data.begin(), data.end()); - boost::asio::async_write( - *asyncPipe, boost::asio::buffer(*asyncBuffer), - [asyncPipe, asyncBuffer](const boost::system::error_code& error, + boost::asio::async_write(*asyncPipe, + boost::asio::buffer(*asyncBuffer), + [asyncPipe, asyncBuffer, path]( + const boost::system::error_code& error, std::size_t /* transferredSize */) { if (error) { - lg2::error("GetLogPage fails to write fd: {ERROR}", "ERROR", - error.message()); + lg2::error("[{PATH}]GetLogPage fails to write fd: {ERROR}", + "PATH", path, "ERROR", error.message()); } }); @@ -697,12 +708,12 @@ if (handler) { std::function<void(const std::error_code&, std::span<uint8_t>)> cb = - [pipe, &io = this->io](std::error_code ec, - std::span<uint8_t> data) { + [pipe, &io = this->io, path = this->path]( + std::error_code ec, std::span<uint8_t> data) { if (ec) { - lg2::error("fail to GetLogPage: {ERROR}", "ERROR", - ec.message()); + lg2::error("[{PATH}]fail to GetLogPage: {ERROR}", "PATH", + path, "ERROR", ec.message()); close(pipe[1]); close(pipe[0]); return; @@ -719,13 +730,14 @@ data.begin(), data.end()); boost::asio::async_write( *asyncPipe, boost::asio::buffer(*asyncBuffer), - [asyncPipe, - asyncBuffer](const boost::system::error_code& error, - std::size_t /* transferredSize */) { + [asyncPipe, asyncBuffer, + path](const boost::system::error_code& error, + std::size_t /* transferredSize */) { if (error) { - lg2::error("GetLogPage fails to write fd: {ERROR}", - "ERROR", error.message()); + lg2::error( + "[{PATH}]GetLogPage fails to write fd: {ERROR}", + "PATH", path, "ERROR", error.message()); } }); @@ -767,24 +779,26 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - lg2::error("Identify fails to open pipe: {ERROR}", "ERROR", - strerror(errno)); + lg2::error("[{PATH}]Identify fails to open pipe: {ERROR}", "PATH", path, + "ERROR", strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open(); } nvmeIntf->adminIdentify( nvmeCtrl, static_cast<nvme_identify_cns>(cns), nsid, cntid, - [pipe, &io = this->io](const nvme_ex_ptr& ex, std::span<uint8_t> data) { + [pipe, &io = this->io, path = this->path](const nvme_ex_ptr& ex, + std::span<uint8_t> data) { if (ex) { - lg2::error("fail to Identify: {ERROR}", "ERROR", ex->what()); + lg2::error("[{PATH}]fail to Identify: {ERROR}", "PATH", path, + "ERROR", ex->what()); close(pipe[1]); close(pipe[0]); return; @@ -799,14 +813,14 @@ auto asyncBuffer = std::make_shared<std::vector<uint8_t>>(data.begin(), data.end()); - boost::asio::async_write( - *asyncPipe, boost::asio::buffer(*asyncBuffer), - [asyncPipe, asyncBuffer](const boost::system::error_code& error, - std::size_t /* transferredSize */) { + boost::asio::async_write(*asyncPipe, boost::asio::buffer(*asyncBuffer), + [asyncPipe, asyncBuffer, + path](const boost::system::error_code& error, + std::size_t /* transferredSize */) { if (error) { - lg2::error("Identify fails to write fd: {ERROR}", "ERROR", - error.message()); + lg2::error("[{PATH}]Identify fails to write fd: {ERROR}", + "PATH", path, "ERROR", error.message()); } }); @@ -851,7 +865,7 @@ if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -859,15 +873,20 @@ nvmeIntf->adminFwCommit( nvmeCtrl, static_cast<nvme_fw_commit_ca>(commitAction & 0b111), firmwareSlot, bpid, - [self{shared_from_this()}](const std::error_code& ec, - nvme_status_field status) { + [self{shared_from_this()}, path = this->path]( + const std::error_code& ec, nvme_status_field status) { if (ec) { + lg2::error("[{PATH}]firmware commit failed: {ERROR}", "PATH", path, + "ERROR", ec.message()); self->NVMeAdmin::firmwareCommitStatus(FwCommitStatus::Failed); return; } if (status != NVME_SC_SUCCESS) { + lg2::error( + "[{PATH}]firmware commit status is not success: {STATUS}", + "PATH", path, "STATUS", status); self->NVMeAdmin::firmwareCommitStatus(FwCommitStatus::RequireReset); return; } @@ -987,7 +1006,7 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -1017,7 +1036,7 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -1068,8 +1087,8 @@ }, yield); - lg2::debug("nvme_status:{STATUS}, dw0:{DW0}", "STATUS", nvmeStatus, "DW0", - completionDw0); + lg2::debug("[{PATH}]nvme_status:{STATUS}, dw0:{DW0}", "PATH", path, + "STATUS", nvmeStatus, "DW0", completionDw0); if (nvmeStatus < 0) { throw sdbusplus::exception::SdBusError(err.value(), @@ -1121,8 +1140,8 @@ }, yield); - lg2::debug("NVMe command result: status={STATUS}, dw0={DW0}", "STATUS", - nvmeStatus, "DW0", completionDw0); + lg2::debug("[{PATH}]NVMe command result: status={STATUS}, dw0={DW0}", + "PATH", path, "STATUS", nvmeStatus, "DW0", completionDw0); if (nvmeStatus < 0) { throw sdbusplus::exception::SdBusError(err.value(), @@ -1156,7 +1175,7 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -1203,7 +1222,9 @@ } catch (const std::exception& e) { - lg2::error("{ERROR}", "ERROR", e.what()); + lg2::error( + "[{PATH}]Fail to attach NS({NSID}) to controller: {ERROR}", + "PATH", path, "NSID", nsid, "ERROR", e.what()); throw sdbusplus::xyz::openbmc_project::Common::Error:: InternalFailure(); } @@ -1218,7 +1239,7 @@ { if (status != Status::Enabled) { - lg2::error("Controller has been disabled"); + lg2::error("[{PATH}]Controller has been disabled", "PATH", path); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -1265,7 +1286,9 @@ } catch (const std::exception& e) { - lg2::error("{ERROR}", "ERROR", e.what()); + lg2::error( + "[{PATH}]Fail to detach NS({NSID}) from controller: {ERROR}", + "PATH", path, "NSID", nsid, "ERROR", e.what()); throw sdbusplus::xyz::openbmc_project::Common::Error:: InternalFailure(); }
diff --git a/src/NVMeDrive.cpp b/src/NVMeDrive.cpp index d022961..e64c523 100644 --- a/src/NVMeDrive.cpp +++ b/src/NVMeDrive.cpp
@@ -118,8 +118,9 @@ (void)scdw10; if (ex) { - lg2::error("Error returned reading sanitize log: {ERROR}", - "ERROR", ex->what()); + lg2::error( + "[{PATH}]Error returned reading sanitize log: {ERROR}", + "PATH", self->path, "ERROR", ex->what()); } else {
diff --git a/src/NVMeFeatureStore.cpp b/src/NVMeFeatureStore.cpp index 8002348..672bdd3 100644 --- a/src/NVMeFeatureStore.cpp +++ b/src/NVMeFeatureStore.cpp
@@ -230,21 +230,23 @@ void FeatureStore::fetchIdentifyData(const boost::asio::yield_context& yield) { + std::string path = this->objectPath; auto [ex, data] = asyncAdminIdentify( io, nvmeIntf, ctrl, NVME_IDENTIFY_CNS_CTRL, NVME_NSID_NONE, 0, yield); if (ex) { lg2::error( - "Identify Controller failed during FeatureStore init: {ERROR}", - "ERROR", ex->what()); + "[{PATH}]Identify Controller failed during FeatureStore init: {ERROR}", + "PATH", path, "ERROR", ex->what()); discoverFeatures(yield); return; } if (data.size() < sizeof(nvme_id_ctrl)) { - lg2::error("Identify Controller returned insufficient data"); + lg2::error("[{PATH}]Identify Controller returned insufficient data", + "PATH", path); discoverFeatures(yield); return; } @@ -255,7 +257,9 @@ if (!vwcSupported) { - lg2::info("Volatile Write Cache (FID 0x06) not supported by hardware"); + lg2::info( + "[{PATH}]Volatile Write Cache (FID 0x06) not supported by hardware", + "PATH", path); } discoverFeatures(yield); @@ -263,6 +267,7 @@ void FeatureStore::discoverFeatures(const boost::asio::yield_context& yield) { + std::string path = this->objectPath; bool oncsBit4 = (oncs & (1 << 4)) != 0; featureCollection.clear(); @@ -294,15 +299,16 @@ else { lg2::error( - "Log Page 12h size mismatch: expected {EXPECTED}, got {GOT}", - "EXPECTED", sizeof(struct nvme_fid_supported_effects_log), - "GOT", logData.size()); + "[{PATH}]Log Page 12h size mismatch: expected {EXPECTED}, got {GOT}", + "PATH", path, "EXPECTED", + sizeof(struct nvme_fid_supported_effects_log), "GOT", + logData.size()); } } else { - lg2::error("Failed to fetch Log Page 12h: {ERROR}", "ERROR", - ec.message()); + lg2::error("[{PATH}]Failed to fetch Log Page 12h: {ERROR}", "PATH", + path, "ERROR", ec.message()); } for (const auto& [name, meta] : featuresToCheck) @@ -319,15 +325,15 @@ if ((entry & 0x1) == 0) // FSUPP bit { lg2::info( - "Feature {NAME} (FID {FID}) not supported per Log Page 12h", - "NAME", name, "FID", meta.fid); + "[{PATH}]Feature {NAME} (FID {FID}) not supported per Log Page 12h", + "PATH", path, "NAME", name, "FID", meta.fid); continue; } } else { - lg2::error("Log Page 12h data too short for FID {FID}", "FID", - meta.fid); + lg2::error("[{PATH}]Log Page 12h data too short for FID {FID}", + "PATH", path, "FID", meta.fid); continue; } } @@ -356,8 +362,9 @@ if (ex) { lg2::info( - "Feature {NAME} (FID {FID}) capabilities query failed (unsupported): {ERROR}", - "NAME", name, "FID", meta.fid, "ERROR", ex->what()); + "[{PATH}]Feature {NAME} (FID {FID}) capabilities query failed (unsupported): {ERROR}", + "PATH", path, "NAME", name, "FID", meta.fid, "ERROR", + ex->what()); continue; } @@ -392,6 +399,7 @@ FeatureStore::getFeature(const boost::asio::yield_context& yield, const std::string& featureName) { + std::string path = this->objectPath; if (!isFeatureSupported(featureName)) { throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument(); @@ -442,8 +450,8 @@ if (ex) { - lg2::error("NVMe Get Features (FID {FID}) failed: {ERROR}", "FID", fid, - "ERROR", ex->what()); + lg2::error("[{PATH}]NVMe Get Features (FID {FID}) failed: {ERROR}", + "PATH", path, "FID", fid, "ERROR", ex->what()); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -462,7 +470,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize Arbitration"); + lg2::error("[{PATH}]Failed to serialize Arbitration", "PATH", + path); } break; } @@ -475,7 +484,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize PowerManagement"); + lg2::error("[{PATH}]Failed to serialize PowerManagement", + "PATH", path); } break; } @@ -492,7 +502,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize TemperatureThreshold"); + lg2::error("[{PATH}]Failed to serialize TemperatureThreshold", + "PATH", path); } break; } @@ -507,7 +518,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize ErrorRecovery"); + lg2::error("[{PATH}]Failed to serialize ErrorRecovery", "PATH", + path); } break; } @@ -521,7 +533,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize VolatileWriteCache"); + lg2::error("[{PATH}]Failed to serialize VolatileWriteCache", + "PATH", path); } break; } @@ -534,7 +547,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize NumberOfQueues"); + lg2::error("[{PATH}]Failed to serialize NumberOfQueues", "PATH", + path); } break; } @@ -547,7 +561,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize Interrupt Coalescing"); + lg2::error("[{PATH}]Failed to serialize Interrupt Coalescing", + "PATH", path); } break; } @@ -563,7 +578,9 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize InterruptVectorConfiguration"); + lg2::error( + "[{PATH}]Failed to serialize InterruptVectorConfiguration", + "PATH", path); } break; } @@ -578,7 +595,8 @@ if (!msg.SerializeToArray(protoData.data(), static_cast<int>(protoData.size()))) { - lg2::error("Failed to serialize WriteAtomicityNormal"); + lg2::error("[{PATH}]Failed to serialize WriteAtomicityNormal", + "PATH", path); } break; } @@ -591,7 +609,8 @@ static_cast<int>(protoData.size()))) { lg2::error( - "Failed to serialize AsynchronousEventConfiguration"); + "[{PATH}]Failed to serialize AsynchronousEventConfiguration", + "PATH", path); } break; } @@ -606,6 +625,7 @@ const std::string& featureName, const std::vector<uint8_t>& data) { + std::string path = this->objectPath; if (!isFeatureSupported(featureName)) { throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument(); @@ -647,15 +667,17 @@ if (save && !saveable) { - lg2::error("SetFeature: FID {FID} is not saveable per SEL=011b", - "FID", lg2::hex, fid); + lg2::error( + "[{PATH}]SetFeature: FID {FID} is not saveable per SEL=011b", + "PATH", path, "FID", lg2::hex, fid); throw sdbusplus::xyz::openbmc_project::Common::Error::NotAllowed(); } if (!save && !changeable) { - lg2::error("SetFeature: FID {FID} is not changeable per SEL=011b", - "FID", lg2::hex, fid); + lg2::error( + "[{PATH}]SetFeature: FID {FID} is not changeable per SEL=011b", + "PATH", path, "FID", lg2::hex, fid); throw sdbusplus::xyz::openbmc_project::Common::Error::NotAllowed(); } } @@ -808,8 +830,8 @@ if (ex) { - lg2::error("NVMe Set Features (FID {FID}) failed: {ERROR}", "FID", fid, - "ERROR", ex->what()); + lg2::error("[{PATH}]NVMe Set Features (FID {FID}) failed: {ERROR}", + "PATH", path, "FID", fid, "ERROR", ex->what()); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } }
diff --git a/src/NVMeMetricStore.cpp b/src/NVMeMetricStore.cpp index 13fd315..5384bf5 100644 --- a/src/NVMeMetricStore.cpp +++ b/src/NVMeMetricStore.cpp
@@ -11,8 +11,9 @@ std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - lg2::error("Metric Fetcher failed due to pipe creation: {ERROR}", - "ERROR", strerror(errno)); + lg2::error( + "[{PATH}]Metric Fetcher failed due to pipe creation: {ERROR}", + "PATH", this->path, "ERROR", strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open{}; } @@ -24,14 +25,14 @@ header.end()); asyncBuffer->insert(asyncBuffer->end(), data.begin(), data.end()); - boost::asio::async_write( - *asyncPipe, boost::asio::buffer(*asyncBuffer), - [asyncPipe, asyncBuffer](const boost::system::error_code& error, + boost::asio::async_write(*asyncPipe, boost::asio::buffer(*asyncBuffer), + [asyncPipe, asyncBuffer, path{this->path}]( + const boost::system::error_code& error, std::size_t /* transferredSize */) { if (error) { - lg2::error("Metric Fetcher fails to write fd: {ERROR}", "ERROR", - error.message()); + lg2::error("[{PATH}]Metric Fetcher fails to write fd: {ERROR}", + "PATH", path, "ERROR", error.message()); } }); @@ -58,15 +59,15 @@ auto it = metricStore.find(name); if (it == metricStore.end() || !it->second) { - lg2::error("Cannot find the target Metric", "PATH", this->path, "NAME", - name); + lg2::error("[{PATH}]Cannot find the target Metric: {NAME}", "PATH", + this->path, "NAME", name); throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument{}; } if (!it->second->isCacheValid()) { - lg2::error("The Metric cache is invalid", "PATH", this->path, "NAME", - name); + lg2::error("[{PATH}]The Metric cache is invalid: {NAME}", "PATH", + this->path, "NAME", name); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable{}; } auto data = it->second->getCache(); @@ -114,23 +115,24 @@ { if (name.empty()) { - lg2::error("Metric name is empty"); + lg2::error("[{PATH}]Metric name is empty", "PATH", this->path); throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument{}; } auto it = metricStore.find(name); if (it == metricStore.end() || !it->second) { - lg2::error("Cannot find the target Metric", "PATH", this->path, "NAME", - name); + lg2::error("[{PATH}]Cannot find the target Metric: {NAME}", "PATH", + this->path, "NAME", name); throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument{}; } std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - lg2::error("Metric Fetcher failed due to pipe creation: {ERROR}", - "ERROR", strerror(errno)); + lg2::error( + "[{PATH}]Metric Fetcher failed due to pipe creation: {ERROR}", + "PATH", this->path, "ERROR", strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open{}; } @@ -140,10 +142,12 @@ auto requestTime = std::chrono::steady_clock::now(); ensureFresh(it->second, requestTime, - [asyncPipe, metric = it->second](std::error_code ec) { + [asyncPipe, metric = it->second, + path = this->path](std::error_code ec) { if (ec) { - lg2::error("Metric Refresh fails: {ERROR}", "ERROR", ec.message()); + lg2::error("[{PATH}]Metric Refresh fails: {ERROR}", "PATH", path, + "ERROR", ec.message()); return; } @@ -164,14 +168,14 @@ asyncBuffer->insert(asyncBuffer->end(), std::get<2>(data).begin(), std::get<2>(data).end()); - boost::asio::async_write( - *asyncPipe, boost::asio::buffer(*asyncBuffer), - [asyncPipe, asyncBuffer](const boost::system::error_code& error, - std::size_t /* transferredSize */) { + boost::asio::async_write(*asyncPipe, boost::asio::buffer(*asyncBuffer), + [asyncPipe, asyncBuffer, + path](const boost::system::error_code& error, + std::size_t /* transferredSize */) { if (error) { - lg2::error("Metric Fetcher fails to write fd: {ERROR}", "ERROR", - error.message()); + lg2::error("[{PATH}]Metric Fetcher fails to write fd: {ERROR}", + "PATH", path, "ERROR", error.message()); } }); });
diff --git a/src/NVMeMetricStore.hpp b/src/NVMeMetricStore.hpp index cf4b4a0..e497f91 100644 --- a/src/NVMeMetricStore.hpp +++ b/src/NVMeMetricStore.hpp
@@ -90,8 +90,9 @@ std::string{metric->getIdentifier()}, metric); if (!res) { - lg2::warning("drop a duplicated metric", "PATH", objectPath, - "METRIC", emplaceItr->first); + lg2::warning("[{PATH}]drop a duplicated metric: {METRIC}", + "PATH", objectPath, "METRIC", + emplaceItr->first); } } return temp; @@ -164,8 +165,9 @@ std::string{metric->getIdentifier()}, std::move(metric)); if (!res) { - lg2::warning("drop a duplicated vendor metric", "PATH", path, - "METRIC", itr->first); + lg2::warning( + "[{PATH}]drop a duplicated vendor metric: {METRIC}", "PATH", + path, "METRIC", itr->first); } } @@ -181,9 +183,10 @@ // use validFlag to protect this call if (weakFlag.expired()) { - lg2::info("MetricStore interface expired, update signal " - "skipped.", - "PATH", path); + lg2::info( + "[{PATH}]MetricStore interface expired, update signal " + "skipped.", + "PATH", path); return; } auto metric = weakMetric.lock();
diff --git a/src/NVMeMi.cpp b/src/NVMeMi.cpp index 137b337..e23eb70 100644 --- a/src/NVMeMi.cpp +++ b/src/NVMeMi.cpp
@@ -116,8 +116,9 @@ case Status::Initiated: if (optimizeTimer) { - lg2::info("Cancel the optimization Timer for the endpoint", - "ENDPOINT", endpoint->describe()); + lg2::info( + "[{ENDPOINT}]Cancel the optimization Timer for the endpoint", + "ENDPOINT", endpoint->describe()); optimizeTimer->cancel(); } [[fallthrough]]; @@ -128,7 +129,8 @@ "nvmeEP was unpopulated in Status::Initiated state"); } mctpStatus = Status::Terminating; - lg2::info("start MCTP closure", "ENDPOINT", endpoint->describe()); + lg2::info("[{ENDPOINT}]start MCTP closure", "ENDPOINT", + endpoint->describe()); // Immediately reset endpoint so that we can capture the parameter // from a subsequent invocation of start() while in // Status::Terminating @@ -142,7 +144,7 @@ self->mtu = 64; self->nvmeEP = nullptr; self->mctpStatus = Status::Reset; - lg2::info("end MCTP closure", "DEVICE", + lg2::info("[{DEVICE}]end MCTP closure", "DEVICE", self->device->describe()); if (self->restart) { @@ -216,8 +218,8 @@ optimizeTimer->async_wait([this](boost::system::error_code ec) { if (ec) { - lg2::error("Endpoint optimize timer error: {ERROR}", "ERROR", - ec.what()); + lg2::error("[{DEVICE}]Endpoint optimize timer error: {ERROR}", + "DEVICE", device->describe(), "ERROR", ec.what()); return; } miSetMCTPConfiguration( @@ -225,8 +227,9 @@ self->optimizeTimer = nullptr; if (ec) { - lg2::error("Failed setting up MTU for the MCTP endpoint.", - "DEVICE", self->device->describe()); + lg2::error( + "[{DEVICE}]Failed setting up MTU for the MCTP endpoint.", + "DEVICE", self->device->describe()); self->recover(); return; } @@ -274,7 +277,8 @@ if (!epConnect(endpoint->network(), endpoint->eid())) { epReset(); - lg2::error("can't open MCTP endpoint", "ENDPOINT", ep->describe()); + lg2::error("[{ENDPOINT}]can't open MCTP endpoint", "ENDPOINT", + ep->describe()); return; } } @@ -394,7 +398,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); + lg2::error("[{DEVICE}]{ERROR}", "DEVICE", device->describe(), "ERROR", + e.what()); return std::make_error_code(std::errc::no_such_device); } return {}; @@ -406,7 +411,8 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); + lg2::error("[{DEVICE}]nvme endpoint is invalid", "DEVICE", + device->describe()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -421,19 +427,19 @@ &smbusFreq); if (rc != 0) { - lg2::error("failed to get the SMBus frequency", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]failed to get the SMBus frequency", + "ENDPOINT", ep->describe()); } else if (smbusFreq == NVME_MI_CONFIG_SMBUS_FREQ_100kHz) { - lg2::info("Setting the SMBus frequency to 400kHz", "ENDPOINT", - ep->describe()); + lg2::info("[{ENDPOINT}]Setting the SMBus frequency to 400kHz", + "ENDPOINT", ep->describe()); rc = nvme_mi_mi_config_set_smbus_freq( self->nvmeEP, portId, NVME_MI_CONFIG_SMBUS_FREQ_400kHz); if (rc != 0) { - lg2::error("failed to set the SMBus frequency", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]failed to set the SMBus frequency", + "ENDPOINT", ep->describe()); } } if (rc != 0) @@ -448,7 +454,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); + lg2::error("[{DEVICE}]{ERROR}", "DEVICE", device->describe(), "ERROR", + e.what()); return; } } @@ -459,7 +466,8 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); + lg2::error("[{DEVICE}]nvme endpoint is invalid", "DEVICE", + device->describe()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -476,8 +484,9 @@ if (rc != 0) { - lg2::error("failed to set remote MCTP MTU for port: {PORT}", - "DEVICE", self->device->describe(), "PORT", port); + lg2::error( + "[{DEVICE}]failed to set remote MCTP MTU for port: {PORT}", + "DEVICE", self->device->describe(), "PORT", port); boost::asio::post(self->io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message)); }); @@ -498,7 +507,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); + lg2::error("[{DEVICE}]{ERROR}", "DEVICE", device->describe(), "ERROR", + e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -511,7 +521,8 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); + lg2::error("[{DEVICE}]nvme endpoint is invalid", "DEVICE", + device->describe()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -527,8 +538,8 @@ nvme_mi_ep_set_timeout(self->nvmeEP, timeout); if (rc != 0) { - lg2::error("Failed reading subsystem info failing", "DEVICE", - self->device->describe()); + lg2::error("[{DEVICE}]Failed reading subsystem info failing", + "DEVICE", self->device->describe()); boost::asio::post(self->io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message)); }); @@ -543,9 +554,9 @@ if (rc != 0) { /* PCIe port might not be ready right after AC/DC cycle. */ - lg2::error("failed reading port info for port_id: {PORT}", - "DEVICE", self->device->describe(), "PORT", - portId); + lg2::error( + "[{DEVICE}]failed reading port info for port_id: {PORT}", + "DEVICE", self->device->describe(), "PORT", portId); } else if (portInfo.portt == 0x2) // SMBus ports = 0x2 { @@ -568,7 +579,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); + lg2::error("[{DEVICE}]{ERROR}", "DEVICE", device->describe(), "ERROR", + e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -585,16 +597,17 @@ retries](const std::error_code& ec) mutable { if (!endpoint) { - lg2::error("failed to set MCTP path MTU: Status::Terminating", - "DEVICE", device->describe()); + lg2::error( + "[{DEVICE}]failed to set MCTP path MTU: Status::Terminating", + "DEVICE", device->describe()); cb(ec); return; } if (!ec) { - lg2::info("Finished MCTP initialization. MTU: {MTU}", "ENDPOINT", - endpoint->describe(), "MTU", mtu); + lg2::info("[{ENDPOINT}]Finished MCTP initialization. MTU: {MTU}", + "ENDPOINT", endpoint->describe(), "MTU", mtu); cb(ec); return; } @@ -602,13 +615,13 @@ retries--; if (retries == 0) { - lg2::error("failed to set MCTP path MTU: {ERROR}", "ENDPOINT", - endpoint->describe(), "ERROR", ec.message()); + lg2::error("[{ENDPOINT}]failed to set MCTP path MTU: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", ec.message()); cb(ec); return; } - lg2::warning("retry to set MCTP path MTU", "ENDPOINT", + lg2::warning("[{ENDPOINT}]retry to set MCTP path MTU", "ENDPOINT", endpoint->describe()); configureLocalRouteMtu(std::move(cb), retries); }; @@ -621,7 +634,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { @@ -638,9 +651,9 @@ true, &ssHealth); if (rc < 0) { - lg2::error("fail to subsystem_health_status_poll: {ERROR}", - "ENDPOINT", ep->describe(), "ERROR", - strerror(errno)); + lg2::error( + "[{ENDPOINT}]fail to subsystem_health_status_poll: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", strerror(errno)); boost::asio::post(self->io, [cb{cb}, lastErrno{errno}]() mutable { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), @@ -652,8 +665,9 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to subsystem_health_status_poll: {ERROR}", - "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); + lg2::error( + "[{ENDPOINT}]fail to subsystem_health_status_poll: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); boost::asio::post(self->io, [cb{cb}]() mutable { cb(std::make_error_code(std::errc::bad_message), nullptr); }); @@ -667,7 +681,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); + lg2::error("[{DEVICE}]{ERROR}", "DEVICE", device->describe(), "ERROR", + e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -681,7 +696,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { @@ -696,8 +711,9 @@ int rc = nvme_mi_scan_ep(self->nvmeEP, true); if (rc < 0) { - lg2::error("fail to scan controllers: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", strerror(errno)); + lg2::error("[{ENDPOINT}]fail to scan controllers: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); boost::asio::post(self->io, [cb{cb}, lastErrno{errno}]() mutable { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), @@ -709,8 +725,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to scan controllers: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", errMsg.data()); + lg2::error("[{ENDPOINT}]fail to scan controllers: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); boost::asio::post(self->io, [cb{cb}]() mutable { cb(std::make_error_code(std::errc::bad_message), {}); }); @@ -730,8 +746,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -751,7 +767,8 @@ } catch (const std::runtime_error& e) { - lg2::error("Runtime error: {ERROR}", "ERROR", e.what()); + lg2::error("[{ENDPOINT}]Runtime error: {ERROR}", "ENDPOINT", + endpoint->describe(), "ERROR", e.what()); return false; } } @@ -762,7 +779,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { cb(makeLibNVMeError("nvme endpoint is degraded"), {}); @@ -819,21 +836,23 @@ if (rc < 0) { - lg2::error("fail to do nvme identify: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", strerror(errno)); + lg2::error("[{ENDPOINT}]fail to do nvme identify: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); } else if (rc > 0) { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to do nvme identify: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", errMsg.data()); + lg2::error("[{ENDPOINT}]fail to do nvme identify: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); } auto ex = makeLibNVMeError(errno, rc, "adminIdentify"); if (ex) { - lg2::error("fail to do nvme identify: {ERROR}", "ERROR", + lg2::error("[{ENDPOINT}]fail to do nvme identify: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", ex->description()); } @@ -846,10 +865,11 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); auto msg = std::string("Runtime error: ") + e.what(); - lg2::error("{MSG}", "MSG", msg); + lg2::error("[{ENDPOINT}]{MSG}", "ENDPOINT", endpoint->describe(), "MSG", + msg); boost::asio::post( io, [cb{std::move(cb)}, msg]() { cb(makeLibNVMeError(msg), {}); }); return; @@ -862,7 +882,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(makeLibNVMeError("nvme endpoint is degraded"), 0, {}); @@ -896,15 +916,16 @@ if (rc < 0) { - lg2::error("fail to do nvme get features: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", strerror(errno)); + lg2::error("[{ENDPOINT}]fail to do nvme get features: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); } else if (rc > 0) { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to do nvme get features: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", errMsg.data()); + lg2::error("[{ENDPOINT}]fail to do nvme get features: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); } auto ex = makeLibNVMeError(errno, rc, "adminGetFeatures"); @@ -918,8 +939,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); auto msg = std::string("Runtime error: ") + e.what(); boost::asio::post(io, [cb{std::move(cb)}, msg]() { cb(makeLibNVMeError(msg), 0, {}); @@ -934,7 +955,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(makeLibNVMeError("nvme endpoint is degraded"), 0); @@ -968,15 +989,16 @@ if (rc < 0) { - lg2::error("fail to do nvme set features: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", strerror(errno)); + lg2::error("[{ENDPOINT}]fail to do nvme set features: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); } else if (rc > 0) { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to do nvme set features: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", errMsg.data()); + lg2::error("[{ENDPOINT}]fail to do nvme set features: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); } auto ex = makeLibNVMeError(errno, rc, "adminSetFeatures"); @@ -987,8 +1009,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); auto msg = std::string("Runtime error: ") + e.what(); boost::asio::post( io, [cb{std::move(cb)}, msg]() { cb(makeLibNVMeError(msg), 0); }); @@ -1018,7 +1040,8 @@ rc = nvme_mi_admin_get_log_create_telemetry_host(ctrl, &log); if (rc != 0) { - lg2::error("failed to create telemetry host log"); + lg2::error("[{ENDPOINT}]failed to create telemetry host log", + "ENDPOINT", describeCtrl(ctrl)); return rc; } } @@ -1027,7 +1050,8 @@ if (rc != 0) { - lg2::error("failed to retain telemetry log for {TYPE}", "TYPE", + lg2::error("[{ENDPOINT}]failed to retain telemetry log for {TYPE}", + "ENDPOINT", describeCtrl(ctrl), "TYPE", [host] { return host ? "host" : "ctrl"; }()); return rc; } @@ -1075,7 +1099,7 @@ if (offset >= data.size()) { lg2::error( - "get telemetry log: offset exceed the log size. offset: {OFFSET}, size: {SIZE}", + "[{DEVICE}]get telemetry log: offset exceed the log size. offset: {OFFSET}, size: {SIZE}", "DEVICE", device->describe(), "OFFSET", offset, "SIZE", data.size()); cb(std::make_error_code(std::errc::invalid_argument), {}); @@ -1102,8 +1126,9 @@ if (rc < 0) { - lg2::error("fail to get chunk for telemetry log: {ERROR}", "DEVICE", - self->device->describe(), "ERROR", strerror(errno)); + lg2::error("[{DEVICE}]fail to get chunk for telemetry log: {ERROR}", + "DEVICE", self->device->describe(), "ERROR", + strerror(errno)); boost::asio::post(self->io, [cb{std::move(cb)}, lastErrno{errno}]() { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), {}); @@ -1114,8 +1139,9 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to get chunk for telemetry log: {ERROR}", "DEVICE", - self->device->describe(), "ERROR", errMsg.data()); + lg2::error("[{DEVICE}]fail to get chunk for telemetry log: {ERROR}", + "DEVICE", self->device->describe(), "ERROR", + errMsg.data()); boost::asio::post(self->io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message), {}); }); @@ -1318,7 +1344,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, {}); @@ -1351,8 +1377,8 @@ rc = nvme_mi_admin_get_log_error(ctrl, num, false, log); if (rc != 0) { - lg2::error("fail to get error log", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]fail to get error log", + "ENDPOINT", ep->describe()); break; } } @@ -1366,8 +1392,8 @@ rc = nvme_mi_admin_get_log_smart(ctrl, nsid, false, log); if (rc != 0) { - lg2::error("fail to get smart log", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]fail to get smart log", + "ENDPOINT", ep->describe()); break; } } @@ -1391,8 +1417,8 @@ rc = nvme_mi_admin_get_log_fw_slot(ctrl, false, log); if (rc != 0) { - lg2::error("fail to get firmware slot", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]fail to get firmware slot", + "ENDPOINT", ep->describe()); break; } } @@ -1410,8 +1436,9 @@ log); if (rc != 0) { - lg2::error("fail to get cmd supported and effects log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get cmd supported and effects log", + "ENDPOINT", ep->describe()); break; } } @@ -1427,8 +1454,9 @@ log); if (rc != 0) { - lg2::error("fail to get supported log pages log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get supported log pages log", + "ENDPOINT", ep->describe()); break; } } @@ -1447,8 +1475,9 @@ rc = nvme_mi_admin_get_log(ctrl, &args); if (rc != 0) { - lg2::error("fail to get FID supported and effects log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get FID supported and effects log", + "ENDPOINT", ep->describe()); break; } } @@ -1462,8 +1491,9 @@ rc = nvme_mi_admin_get_log_device_self_test(ctrl, log); if (rc != 0) { - lg2::error("fail to get device self test log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get device self test log", + "ENDPOINT", ep->describe()); break; } } @@ -1478,8 +1508,9 @@ log); if (rc != 0) { - lg2::error("fail to get changed namespace list", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get changed namespace list", + "ENDPOINT", ep->describe()); break; } } @@ -1527,7 +1558,7 @@ if (rc != 0) { lg2::error( - "fail to get command and feature lockdown log", + "[{ENDPOINT}]fail to get command and feature lockdown log", "ENDPOINT", ep->describe()); break; } @@ -1545,8 +1576,9 @@ log); if (rc != 0) { - lg2::error("fail to get reservation notification log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get reservation notification log", + "ENDPOINT", ep->describe()); break; } } @@ -1561,16 +1593,17 @@ int rc = nvme_mi_admin_get_log_sanitize(ctrl, false, log); if (rc != 0) { - lg2::error("fail to get sanitize status log", - "ENDPOINT", ep->describe()); + lg2::error( + "[{ENDPOINT}]fail to get sanitize status log", + "ENDPOINT", ep->describe()); break; } } break; default: { - lg2::error("unknown lid for GetLogPage", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]unknown lid for GetLogPage", + "ENDPOINT", ep->describe()); rc = -1; errno = EINVAL; } @@ -1578,8 +1611,9 @@ if (rc < 0) { - lg2::error("fail to get log page: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", strerror(errno)); + lg2::error("[{ENDPOINT}]fail to get log page: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); logHandler = [cb{cb}, lastErrno{errno}]() mutable { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), {}); @@ -1589,8 +1623,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to get log page: {ERROR}", "ENDPOINT", - ep->describe(), "ERROR", errMsg.data()); + lg2::error("[{ENDPOINT}]fail to get log page: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); logHandler = [cb{cb}]() mutable { cb(std::make_error_code(std::errc::bad_message), {}); }; @@ -1608,8 +1642,8 @@ } catch (const std::runtime_error& e) { - lg2::error("NVMeMi adminGetLogPage throws: {ERROR}", "ENDPOINT", - endpoint->describe(), "ERROR", e.what()); + lg2::error("[{ENDPOINT}]NVMeMi adminGetLogPage throws: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -1649,8 +1683,8 @@ if (postErr) { - lg2::error("adminLockdownInband post failed: {ERROR}", "DEVICE", - device->describe(), "ERROR", postErr.message()); + lg2::error("[{DEVICE}]adminLockdownInband post failed: {ERROR}", + "DEVICE", device->describe(), "ERROR", postErr.message()); boost::asio::post( io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1, 0, "", 0); }); @@ -1665,7 +1699,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, {}, {}); @@ -1713,8 +1747,8 @@ if (rc < 0) { - lg2::error("failed to nvme_mi_admin_xfer", "ENDPOINT", - ep->describe()); + lg2::error("[{ENDPOINT}]failed to nvme_mi_admin_xfer", + "ENDPOINT", ep->describe()); boost::asio::post(self->io, [cb{std::move(cb)}, lastErrno{errno}]() { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), @@ -1740,8 +1774,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}, {}); }); @@ -1755,7 +1789,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, nvme_status_field::NVME_SC_MASK); @@ -1775,9 +1809,9 @@ int rc = nvme_mi_admin_fw_commit(ctrl, &args); if (rc < 0) { - lg2::error("fail to nvme_mi_admin_fw_commit: {ERROR}", - "ENDPOINT", ep->describe(), "ERROR", - strerror(errno)); + lg2::error( + "[{ENDPOINT}]fail to nvme_mi_admin_fw_commit: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", strerror(errno)); boost::asio::post(self->io, [cb{std::move(cb)}, lastErrno{errno}]() { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), @@ -1800,8 +1834,10 @@ default: std::string_view errMsg = statusToString( static_cast<nvme_mi_resp_status>(rc)); - lg2::error("fail to nvme_mi_admin_fw_commit: {ERROR}", - "ERROR", errMsg.data()); + lg2::error( + "[{ENDPOINT}]fail to nvme_mi_admin_fw_commit: {ERROR}", + "ENDPOINT", self->endpoint->describe(), "ERROR", + errMsg.data()); boost::asio::post(self->io, [rc, cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message), static_cast<nvme_status_field>(rc)); @@ -1813,8 +1849,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", - e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1830,7 +1866,7 @@ { if (auto degraded = isEndpointDegraded()) { - lg2::error("MCTP connection is not established", "DEVICE", + lg2::error("[{DEVICE}]MCTP connection is not established", "DEVICE", device->describe()); boost::asio::post(io, [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, nvme_status_field::NVME_SC_MASK); @@ -1845,8 +1881,10 @@ std::ifstream fwFile(firmwarefile, std::ios::in | std::ios::binary); if (fwFile.fail()) { - lg2::error("fail to open fw image file: {FILE}, {ERROR}", - "FILE", firmwarefile, "ERROR", strerror(errno)); + lg2::error( + "[{ENDPOINT}]fail to open fw image file: {FILE}, {ERROR}", + "ENDPOINT", self->endpoint->describe(), "FILE", + firmwarefile, "ERROR", strerror(errno)); boost::asio::post(self->io, [cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), nvme_status_field::NVME_SC_MASK); @@ -1873,14 +1911,17 @@ if (attemptCount > 0) { lg2::warning( - "Retrying the firmware chunk. With Offset: {OFFSET}, Total firmware Size: {SIZE}", - "OFFSET", offset, "SIZE", size); + "[{ENDPOINT}]Retrying the firmware chunk. With Offset: {OFFSET}, Total firmware Size: {SIZE}", + "ENDPOINT", self->endpoint->describe(), "OFFSET", + offset, "SIZE", size); attemptCount = attemptCount - 1; } else { - lg2::error("fail to nvme_mi_admin_fw_download: {ERROR}", - "ERROR", strerror(errno)); + lg2::error( + "[{ENDPOINT}]fail to nvme_mi_admin_fw_download: {ERROR}", + "ENDPOINT", self->endpoint->describe(), "ERROR", + strerror(errno)); boost::asio::post(self->io, [cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), nvme_status_field::NVME_SC_MASK); @@ -1896,8 +1937,9 @@ if (offset >= size) { lg2::info( - "Successfully transferred the firmware. Transfer Size: {XFER}, Total Size: {SIZE}", - "XFER", offset, "SIZE", size); + "[{ENDPOINT}]Successfully transferred the firmware. Transfer Size: {XFER}, Total Size: {SIZE}", + "ENDPOINT", self->endpoint->describe(), "XFER", offset, + "SIZE", size); boost::asio::post(self->io, [rc, cb{std::move(cb)}]() { cb({}, static_cast<nvme_status_field>(rc)); }); @@ -1913,7 +1955,8 @@ } catch (const std::runtime_error& e) { - lg2::error("{ERROR}", "ERROR", e.what()); + lg2::error("[{ENDPOINT}]{ERROR}", "ENDPOINT", endpoint->describe(), + "ERROR", e.what()); boost::asio::post(io, [cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1932,8 +1975,8 @@ std::ios::in | std::ios::binary | std::ios::ate); if (imageFile.fail()) { - lg2::error("Can't open the firmware file: {ERROR}", "ERROR", - strerror(errno)); + lg2::error("[{ENDPOINT}]Can't open the firmware file: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", strerror(errno)); boost::asio::post(io, [cb{cb}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1975,7 +2018,7 @@ }); if (postErr) { - lg2::error("adminSecuritySend post failed: {ERROR}", "DEVICE", + lg2::error("[{DEVICE}]adminSecuritySend post failed: {ERROR}", "DEVICE", device->describe(), "ERROR", postErr.message()); boost::asio::post(io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); @@ -2017,7 +2060,7 @@ if (args.data_len > maxNVMeMILength) { lg2::error( - "nvme_mi_admin_security_send returned excess data, {LEN}", + "[{DEVICE}]nvme_mi_admin_security_send returned excess data, {LEN}", "DEVICE", self->device->describe(), "LEN", args.data_len); boost::asio::post(self->io, [cb]() { cb(std::make_error_code(std::errc::protocol_error), -1, {}); @@ -2035,8 +2078,8 @@ }); if (postErr) { - lg2::error("adminSecurityReceive post failed: {ERROR}", "DEVICE", - device->describe(), "ERROR", postErr.message()); + lg2::error("[{DEVICE}]adminSecurityReceive post failed: {ERROR}", + "DEVICE", device->describe(), "ERROR", postErr.message()); boost::asio::post( io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1, {}); }); } @@ -2064,7 +2107,7 @@ }); if (postErr) { - lg2::error("adminNonDataCmd post failed: {ERROR}", "DEVICE", + lg2::error("[{DEVICE}]adminNonDataCmd post failed: {ERROR}", "DEVICE", device->describe(), "ERROR", postErr.message()); boost::asio::post( io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1, 0); }); @@ -2110,7 +2153,8 @@ std::function<void(nvme_ex_ptr ex)>&& submittedCb, std::function<void(nvme_ex_ptr ex, NVMeNSIdentify newid)>&& finishedCb) { - lg2::debug("createns {TID}", "TID", (int)gettid()); + lg2::debug("[{ENDPOINT}]createns {TID}", "ENDPOINT", endpoint->describe(), + "TID", (int)gettid()); std::error_code postErr = tryPost( [self{shared_from_this()}, ctrl, size, lbaFormat, metadataAtEnd, submittedCb{submittedCb}, finishedCb{std::move(finishedCb)}]() { @@ -2160,14 +2204,16 @@ data.ncap = ::htole64(blocks); data.flbas = flbas; - lg2::debug("verified {TID}", "TID", (int)gettid()); + lg2::debug("[{ENDPOINT}]verified {TID}", "ENDPOINT", + self->endpoint->describe(), "TID", (int)gettid()); // submission has been verified. Handle the cb in main thread // concurrently. boost::asio::post(self->io, [submittedCb{submittedCb}]() mutable { submittedCb(nvme_ex_ptr()); }); - lg2::debug("after submitted_cb {TID}", "TID", (int)gettid()); + lg2::debug("[{ENDPOINT}]after submitted_cb {TID}", "ENDPOINT", + self->endpoint->describe(), "TID", (int)gettid()); unsigned timeout = nvme_mi_ep_get_timeout(self->nvmeEP); nvme_mi_ep_set_timeout(self->nvmeEP, namespaceDefaultTimeoutMS); @@ -2191,11 +2237,13 @@ }); }); - lg2::debug("submitted cb {TID}", "TID", (int)gettid()); + lg2::debug("[{ENDPOINT}]submitted cb {TID}", "ENDPOINT", + endpoint->describe(), "TID", (int)gettid()); if (postErr) { - lg2::error("createNamespace post failed: {ERROR}", "ERROR", + lg2::error("[{ENDPOINT}]createNamespace post failed: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", postErr.message()); auto e = makeLibNVMeError(postErr, -1, "createVolume"); boost::asio::post( @@ -2223,7 +2271,8 @@ }); if (postErr) { - lg2::error("deleteNamespace post failed: {ERROR}", "ERROR", + lg2::error("[{ENDPOINT}]deleteNamespace post failed: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", postErr.message()); boost::asio::post(io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); @@ -2324,8 +2373,9 @@ }); if (postErr) { - lg2::error("adminAttachDetachNamespace post failed: {ERROR}", "ERROR", - postErr.message()); + lg2::error( + "[{ENDPOINT}]adminAttachDetachNamespace post failed: {ERROR}", + "ENDPOINT", endpoint->describe(), "ERROR", postErr.message()); boost::asio::post(io, [cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); } @@ -2349,8 +2399,9 @@ nvme_mi_ep_set_timeout(self->nvmeEP, sanitizeDefaultTimeoutMS); int status = nvme_mi_admin_sanitize_nvm(ctrl, &args); nvme_mi_ep_set_timeout(self->nvmeEP, timeout); - lg2::debug("san status {STATUS}, errno {ERRNO}", "STATUS", status, - "ERRNO", errno); + lg2::debug("[{ENDPOINT}]san status {STATUS}, errno {ERRNO}", "ENDPOINT", + self->endpoint->describe(), "STATUS", status, "ERRNO", + errno); auto ex = makeLibNVMeError(errno, status, "adminSanitize"); boost::asio::post(self->io, [cb{cb}, ex]() mutable { cb(ex); });
diff --git a/src/NVMeSensorMain.cpp b/src/NVMeSensorMain.cpp index 3d71f09..156b39c 100644 --- a/src/NVMeSensorMain.cpp +++ b/src/NVMeSensorMain.cpp
@@ -109,7 +109,7 @@ auto findBus = properties.find("Bus"); if (findBus == properties.end()) { - lg2::error("could not determine bus number for '{PATH}'", "PATH", path); + lg2::error("[{PATH}] could not determine bus number", "PATH", path); return std::nullopt; } @@ -122,7 +122,7 @@ auto findAddr = properties.find("Address"); if (findAddr == properties.end()) { - lg2::error("could not determine address for '{PATH}'", "PATH", path); + lg2::error("[{PATH}] could not determine address", "PATH", path); return std::nullopt; } @@ -135,8 +135,8 @@ auto findName = properties.find("Name"); if (findName == properties.end()) { - lg2::error("could not determine configuration name for '{PATH}'", - "PATH", path); + lg2::error("[{PATH}] could not determine configuration name", "PATH", + path); return std::nullopt; } @@ -150,8 +150,7 @@ auto findProtocol = properties.find("Protocol"); if (findProtocol == properties.end()) { - lg2::error("could not determine nvme protocol for '{PATH}'", "PATH", - path); + lg2::error("[{PATH}] could not determine nvme protocol", "PATH", path); return std::nullopt; } return std::get<std::string>(findProtocol->second); @@ -193,9 +192,8 @@ } else { - lg2::warning( - "'{PATH}': 'SupportedFeatures' is not an array of strings.", "PATH", - path); + lg2::warning("[{PATH}] 'SupportedFeatures' is not an array of strings", + "PATH", path); } return false; } @@ -365,8 +363,8 @@ busInfoList = extractNVMeBusInfo(configData); if (busInfoList.empty()) { - lg2::error("Missing BusInfo for mi_mctp device {PATH}", "PATH", - nvmeObjectPath.str); + lg2::error("[{PATH}] Missing BusInfo for mi_mctp device", + "PATH", nvmeObjectPath.str); continue; } @@ -442,7 +440,7 @@ catch (std::exception& ex) { lg2::error( - "Failed to add nvme basic interface for '{PATH}': {ERROR}", + "[{PATH}] Failed to add nvme basic interface: {ERROR}", "PATH", nvmeObjectPath.str, "ERROR", ex.what()); } } @@ -527,9 +525,8 @@ } catch (std::exception& ex) { - lg2::error( - "Failed to add nvme mi interface for '{PATH}': {ERROR}", - "PATH", nvmeObjectPath.str, "ERROR", ex.what()); + lg2::error("[{PATH}] Failed to add nvme mi interface: {ERROR}", + "PATH", nvmeObjectPath.str, "ERROR", ex.what()); } } }
diff --git a/src/NVMeSubsys.cpp b/src/NVMeSubsys.cpp index 41715d7..fe31755 100644 --- a/src/NVMeSubsys.cpp +++ b/src/NVMeSubsys.cpp
@@ -193,12 +193,12 @@ io, objServer, conn, path, ctrl->getNvmeIntf(), ctrl->getMiCtrl(), 0, FeatureScope::Subsystem); - this->featureStore->init([](const std::error_code& ec) { + this->featureStore->init([path = this->path](const std::error_code& ec) { if (ec) { lg2::error( - "Failed to initialize feature store for subsystem: {ERROR}", - "ERROR", ec.message()); + "[{PATH}]Failed to initialize feature store for subsystem: {ERROR}", + "PATH", path, "ERROR", ec.message()); } }); } @@ -242,8 +242,9 @@ auto findSecondary = controllers.find(secCntlrList->sc_entry[i].scid); if (findSecondary == controllers.end()) { - lg2::error("fail to match secondary controller from " - "identify secondary cntrl list"); + lg2::error("[{PATH}] fail to match secondary controller from " + "identify secondary cntrl list", + "PATH", path); break; } @@ -268,12 +269,12 @@ self->fillDrive(yield); self->updateVolumes(yield); self->querySupportedFormats(yield); - lg2::info("finished NS enum"); + lg2::info("[{PATH}]finished NS enum", "PATH", self->path); } catch (const std::exception& e) { - lg2::error("failed starting the subsystem: {ERROR}", "SUBSYSTEM", - self->name, "ERROR", e.what()); + lg2::error("[{PATH}]failed starting the subsystem: {ERROR}", "PATH", + self->path, "ERROR", e.what()); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -390,7 +391,8 @@ if (!posted) { lg2::error( - "Failed to flush operations, subsystem has stalled!"); + "[{PATH}]Failed to flush operations, subsystem has stalled!", + "PATH", path); } } @@ -448,34 +450,20 @@ { // TODO: mark the subsystem invalid and reschedule refresh lg2::error( - "fail to scan controllers for the nvme subsystem: {ERROR}", - "ERROR", ec.message()); + "[{PATH}]fail to scan controllers for the nvme subsystem: {ERROR}", + "PATH", self->path, "ERROR", ec.message()); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); return; } - // TODO: manually open nvme_mi_ctrl_t from cntrl id, instead hacking - // into structure of nvme_mi_ctrl for (auto* c : ctrlList) { - /* calucate the cntrl id from nvme_mi_ctrl: - struct nvme_mi_ctrl - { - struct nvme_mi_ep* ep; - __u16 id; - struct list_node ep_entry; - }; - */ - // NOLINTNEXTLINE(cppcoreguidelines-pro-type-reinterpret-cast) - uint16_t* index = reinterpret_cast<uint16_t*>( - // NOLINTNEXTLINE(cppcoreguidelines-pro-type-reinterpret-cast) - (reinterpret_cast<uint8_t*>(c) + - std::max(sizeof(uint16_t), sizeof(void*)))); + uint16_t index = getCtrlId(c); std::filesystem::path path = std::filesystem::path(self->path) / "controllers" / - std::to_string(*index); + std::to_string(index); try { @@ -484,16 +472,14 @@ self->config, nvme, c, self->weak_from_this(), self->featureLockdownEnabled); - self->controllers.insert({*index, {nvmeController, {}}}); + self->controllers.insert({index, {nvmeController, {}}}); } catch (const std::exception& e) { lg2::error( - "failed to create controller: {CONTROLLER}, reason: {REASON}", - "CONTROLLER", *index, "REASON", e.what()); + "[{PATH}]failed to create controller: {CONTROLLER}, reason: {REASON}", + "PATH", path, "CONTROLLER", index, "REASON", e.what()); } - - index++; } // self->createStorageAssociation(); @@ -530,7 +516,9 @@ std::span<uint8_t> data) { if (ex || data.size() < sizeof(nvme_secondary_ctrl_list)) { - lg2::error("fail to identify secondary controller list"); + lg2::error( + "[{PATH}]fail to identify secondary controller list", + "PATH", self->path); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -542,7 +530,9 @@ if (listHdr->num == 0) { - lg2::error("empty identify secondary controller list"); + lg2::error( + "[{PATH}]empty identify secondary controller list", + "PATH", self->path); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -582,8 +572,8 @@ if (!primaryController) { lg2::error( - "dbus call for inactive NVMe subsystem {SUBSYSTEM}. Returning Unavailable", - "SUBSYSTEM", name); + "[{PATH}]dbus call for inactive NVMe subsystem {SUBSYSTEM}. Returning Unavailable", + "PATH", path, "SUBSYSTEM", name); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } return primaryController; @@ -625,8 +615,8 @@ std::vector<thresholds::Threshold> sensorThresholds; if (!parseThresholdsFromConfig(config, sensorThresholds)) { - lg2::error("error populating thresholds for {SENSOR}", "SENSOR", - *sensorName); + lg2::error("[{PATH}]error populating thresholds for {SENSOR}", "PATH", + path, "SENSOR", *sensorName); throw std::runtime_error("error populating thresholds for " + *sensorName); } @@ -643,7 +633,8 @@ auto sensorBase = config.find(configInterfaceName(nvme::sensorType)); if (sensorBase == config.end()) { - lg2::warning("cannot find sensor config {CONFIG} for {NAME}", "CONFIG", + lg2::warning("[{PATH}]cannot find sensor config {CONFIG} for {NAME}", + "PATH", path, "CONFIG", configInterfaceName(nvme::sensorType), "NAME", name); } else @@ -702,8 +693,8 @@ if (error == std::errc::no_such_device) { lg2::error( - "error reading ctemp from subsystem, reason: {ERROR}", - "ERROR", error.message()); + "[{PATH}]error reading ctemp from subsystem, reason: {ERROR}", + "PATH", self->path, "ERROR", error.message()); self->markFunctional(false); self->markAvailable(false); return; @@ -712,15 +703,16 @@ if (error) { lg2::error( - "error reading ctemp from subsystem, reason: {ERROR}", - "ERROR", error.message()); + "[{PATH}]error reading ctemp from subsystem, reason: {ERROR}", + "PATH", self->path, "ERROR", error.message()); self->ctemp->incrementError(); return; } if (status == nullptr) { - lg2::error("empty data returned by data fetcher"); + lg2::error("[{PATH}]empty data returned by data fetcher", + "PATH", self->path); self->markFunctional(false); return; } @@ -732,8 +724,8 @@ NVME_MI_BASIC_SFLGS_DRIVE_FUNCTIONAL) == 0)) { lg2::error( - "{NAME}: health poll returns drive not ready or drive not functional", - "NAME", self->name); + "[{PATH}]health poll returns drive not ready or drive not functional", + "PATH", self->path); self->markFunctional(false); return; } @@ -764,7 +756,9 @@ // do not poll the health status if the subsystem is intiatilzing if (self->status == Status::Intiatilzing) { - lg2::info("subsystem is initializing, cancel the health poll"); + lg2::info( + "[{PATH}]subsystem is initializing, cancel the health poll", + "PATH", self->path); cb(std::make_error_code(std::errc::operation_canceled), nullptr); return; @@ -784,33 +778,34 @@ if (error == std::errc::operation_canceled) { - lg2::info("processing health data has been cancelled"); + lg2::info("[{PATH}]processing health data has been cancelled", + "PATH", self->path); return; } if (self->status == Status::Intiatilzing) { lg2::info( - "subsystem is initializing, do not process the status"); + "[{PATH}]subsystem is initializing, do not process the status", + "PATH", self->path); return; } if (error == std::errc::no_such_device) { lg2::error( - "error reading ctemp from subsystem, reason: {ERROR}", - "ERROR", error.message()); + "[{PATH}]error reading ctemp from subsystem, reason: {ERROR}", + "PATH", self->path, "ERROR", error.message()); // stop the subsystem self->markFunctional(false); self->markAvailable(false); - return; } if (error) { lg2::error( - "error reading ctemp from subsystem, reason: {ERROR}", - "ERROR", error.message()); + "[{PATH}]error reading ctemp from subsystem, reason: {ERROR}", + "PATH", self->path, "ERROR", error.message()); self->ctemp->incrementError(); if (self->ctemp->inError()) { @@ -829,8 +824,8 @@ if (!df) { // stop the subsystem - lg2::error("{NAME}: health poll returns df status 0", "NAME", - self->name); + lg2::error("[{PATH}]health poll returns df status 0", "PATH", + self->path); self->markFunctional(false); return; } @@ -859,7 +854,7 @@ if (status == Status::Intiatilzing) { - lg2::debug("status init"); + lg2::debug("[{PATH}]status init", "PATH", path); auto timer = std::make_shared<boost::asio::steady_timer>( io, std::chrono::milliseconds(100)); timer->async_wait( @@ -873,7 +868,7 @@ } else { - lg2::debug("status else"); + lg2::debug("[{PATH}]status else", "PATH", path); markFunctional(false); // There's been an explicit request to stop the subsystem. If it has @@ -916,15 +911,16 @@ auto [ex] = boost::asio::async_initiate<boost::asio::yield_context, submit_callback_t>( [weak{weak_from_this()}, progId, intf, ctrl, size, lbaFormat, - metadataAtEnd](auto&& handler) { + metadataAtEnd, path = this->path](auto&& handler) { auto h = asio_helper::CopyableCallback( std::forward<decltype(handler)>(handler)); // #1 - intf->createNamespace(ctrl, size, lbaFormat, metadataAtEnd, + intf->createNamespace( + ctrl, size, lbaFormat, metadataAtEnd, - // submitted_cb - [h](const nvme_ex_ptr& ex) mutable { + // submitted_cb + [h](const nvme_ex_ptr& ex) mutable { // #2 // Async completion of the createNamespace call. @@ -933,16 +929,17 @@ h(std::make_tuple(ex)); }, - // finished_cb - [weak, progId](const nvme_ex_ptr& ex, - NVMeNSIdentify newns) mutable { + // finished_cb + [weak, progId, path](const nvme_ex_ptr& ex, + NVMeNSIdentify newns) mutable { // #5. This will only be called once #4 completes. // It will not be called if the submit failed. auto self = weak.lock(); if (!self) { lg2::warning( - "createNamespace completed while nvmesensor was exiting"); + "[{PATH}]createNamespace completed while nvmesensor was exiting", + "PATH", path); return; } // The NS create has completed (either successfully or not) @@ -1019,8 +1016,8 @@ } catch (const std::exception& e) { - lg2::error("Unhandled error in createVolumeFinished: {ERROR}", "ERROR", - e.what()); + lg2::error("[{PATH}]Unhandled error in createVolumeFinished: {ERROR}", + "PATH", path, "ERROR", e.what()); } } @@ -1109,7 +1106,7 @@ uint16_t num = ::le16toh(list.num); if (num == NVME_ID_CTRL_LIST_MAX) { - lg2::warning("full ctrl list returned"); + lg2::warning("[{PATH}]full ctrl list returned", "PATH", path); } for (auto i = 0; i < num; i++) @@ -1169,8 +1166,8 @@ std::back_inserter(deletions)); lg2::info( - "[{SUBSYSTEM}] subsystem enum {NS_SIZE} NS, {ADDITIONS} will be added, {DELETIONS} will be deleted", - "SUBSYSTEM", name, "NS_SIZE", ns.size(), "ADDITIONS", additions.size(), + "[{PATH}]subsystem enum {NS_SIZE} NS, {ADDITIONS} will be added, {DELETIONS} will be deleted", + "PATH", path, "NS_SIZE", ns.size(), "ADDITIONS", additions.size(), "DELETIONS", deletions.size()); for (auto n : deletions) @@ -1240,8 +1237,9 @@ { if (volPath.parent_path() != path + "/volumes") { - lg2::error("getVolume path '{PATH}' doesn't match parent {PARENT_PATH}", - "PATH", volPath.str, "PARENT_PATH", path); + lg2::error( + "[{PATH}]getVolume path '{VOLPATH}' doesn't match parent {PARENT_PATH}", + "PATH", path, "VOLPATH", volPath.str, "PARENT_PATH", path); return nullptr; } @@ -1250,14 +1248,16 @@ auto e = std::from_chars(id.data(), id.data() + id.size(), nsid); if (e.ptr != id.data() + id.size() || e.ec != std::errc()) { - lg2::error("getVolume path '{PATH}' bad nsid", "PATH", volPath.str); + lg2::error("[{PATH}]getVolume path '{VOLPATH}' bad nsid", "PATH", path, + "VOLPATH", volPath.str); return nullptr; } auto v = volumes.find(nsid); if (v == volumes.end()) { - lg2::error("getVolume nsid {NSID} not found", "NSID", nsid); + lg2::error("[{PATH}]getVolume nsid {NSID} not found", "PATH", path, + "NSID", nsid); return nullptr; } @@ -1270,7 +1270,8 @@ if (!controllers.contains(ctrlId)) { - lg2::error("attachedVolumes bad controller {CTRLID}", "CTRLID", ctrlId); + lg2::error("[{PATH}]attachedVolumes bad controller {CTRLID}", "PATH", + path, "CTRLID", ctrlId); return vols; } @@ -1302,7 +1303,7 @@ throw std::runtime_error(std::format("attachCtrlVolume bad ns {}", ns)); } attached[c].insert(ns); - lg2::info("{NAME} attached insert {C} {NS}", "NAME", name, "C", c, "NS", + lg2::info("[{PATH}] attached insert {C} {NS}", "PATH", path, "C", c, "NS", ns); controllers[c].first->updateAssociation(); } @@ -1324,7 +1325,8 @@ throw std::runtime_error(std::format("detachCtrlVolume bad ns {}", ns)); } attached[c].erase(ns); - lg2::info("{NAME} attached erase {C} {NS}", "NAME", name, "C", c, "NS", ns); + lg2::info("[{PATH}] attached erase {C} {NS}", "PATH", path, "C", c, "NS", + ns); controllers[c].first->updateAssociation(); } @@ -1361,7 +1363,7 @@ { std::string errMsg = std::string("Internal error, NSID exists " + std::to_string(ns.namespaceId)); - lg2::error("{ERROR}", "ERROR", errMsg); + lg2::error("[{PATH}] {ERROR}", "PATH", path, "ERROR", errMsg); throw makeLibNVMeError(errMsg); } @@ -1439,14 +1441,14 @@ throw std::runtime_error(std::format("{}: Bad nlbaf {}", name, nlbaf)); } - lg2::debug("{NAME}: Got nlbaf {NLBAF}", "NAME", name, "NLBAF", nlbaf); + lg2::debug("[{PATH}] Got nlbaf {NLBAF}", "PATH", path, "NLBAF", nlbaf); std::vector<LBAFormat> formats; for (size_t i = 0; i < nlbaf; i++) { size_t blockSize = 1UL << id.lbaf[i].ds; size_t metadataSize = id.lbaf[i].ms; RelPerf rp = relativePerformanceFromRP(id.lbaf[i].rp); - lg2::debug("{NAME}: lbaf {LBAF} blocksize {BLOCKSIZE}", "NAME", name, + lg2::debug("[{PATH}] lbaf {LBAF} blocksize {BLOCKSIZE}", "PATH", path, "LBAF", i, "BLOCKSIZE", blockSize); formats.push_back({.index = i, .blockSize = blockSize, @@ -1517,8 +1519,8 @@ { if (status != Status::Start) { - lg2::error("Subsystem not in Start state, have {STATUS}", "STATUS", - static_cast<int>(status)); + lg2::error("[{PATH}]Subsystem not in Start state, have {STATUS}", + "PATH", path, "STATUS", static_cast<int>(status)); return; }
diff --git a/src/NVMeUtil.hpp b/src/NVMeUtil.hpp index 694c065..125c731 100644 --- a/src/NVMeUtil.hpp +++ b/src/NVMeUtil.hpp
@@ -1,53 +1,20 @@ #pragma once +#include <libnvme-mi.h> + #include <boost/algorithm/string/join.hpp> #include <boost/asio.hpp> #include <phosphor-logging/lg2.hpp> +#include <algorithm> #include <chrono> +#include <cstdlib> #include <filesystem> +#include <format> +#include <memory> #include <mutex> #include <optional> #include <system_error> -/** - * @brief Logs a message via lg2 at most once every N seconds specific to the - * call site. - * - * This macro utilizes static local variables to maintain state specific - * to the exact line of code where the macro is expanded. - * - * It uses double-checked locking to ensure thread safety if multiple threads - * hit the exact same log statement simultaneously. - * - * @param level The lg2 severity level (e.g., info, error, warning, debug). - * @param N The interval in seconds. - * @param msg The message format string. - * @param ... Optional arguments for the format string. - */ -#define LG2_LOG_EVERY_N_SEC(level, N, msg, ...) \ - do \ - { \ - /* The magic happens here: These static variables are unique per */ \ - /* every distinct place this macro is used in the source code. */ \ - static std::chrono::steady_clock::time_point _lg2_site_last_time; \ - static std::mutex _lg2_site_mutex; \ - \ - /* Use steady_clock so system time changes don't break the timer */ \ - auto _lg2_now = std::chrono::steady_clock::now(); \ - \ - /* Optimization: Quick check without locking first */ \ - if (_lg2_now - _lg2_site_last_time >= std::chrono::seconds(N)) \ - { \ - std::lock_guard<std::mutex> _lg2_lock(_lg2_site_mutex); \ - /* Thread Safety: Double-check inside lock */ \ - if (_lg2_now - _lg2_site_last_time >= std::chrono::seconds(N)) \ - { \ - lg2::level(msg, ##__VA_ARGS__); \ - _lg2_site_last_time = _lg2_now; \ - } \ - } \ - } while (0) - namespace nvme { static constexpr const char* sensorType = "NVME1000"; @@ -277,3 +244,47 @@ } return result; } + +// Helper functions to extract endpoint / controller descriptor from +// nvme_mi_ctrl_t. +// TODO: Replace with upstream API nvme_mi_controller_desc(nvme_mi_ctrl_t ctrl) +// once available in libnvme. +inline uint16_t getCtrlId(nvme_mi_ctrl_t ctrl) +{ + // NOLINTBEGIN(cppcoreguidelines-pro-type-reinterpret-cast) + return *reinterpret_cast<const uint16_t*>( + reinterpret_cast<const uint8_t*>(ctrl) + + std::max(sizeof(uint16_t), sizeof(void*))); + // NOLINTEND(cppcoreguidelines-pro-type-reinterpret-cast) +} + +inline std::string describeCtrl(nvme_mi_ctrl_t ctrl) +{ + if (ctrl == nullptr) + { + return "null"; + } + /* + * Internal layout from libnvme private.h: + * struct nvme_mi_ctrl { + * struct nvme_mi_ep *ep; + * __u16 id; + * struct list_node ep_entry; + * }; + */ + // NOLINTBEGIN(cppcoreguidelines-pro-type-reinterpret-cast) + auto* ep = *reinterpret_cast<nvme_mi_ep_t*>(ctrl); + // NOLINTEND(cppcoreguidelines-pro-type-reinterpret-cast) + uint16_t id = getCtrlId(ctrl); + + if (ep != nullptr) + { + std::unique_ptr<char, decltype(&std::free)> epDesc( + nvme_mi_endpoint_desc(ep), &std::free); + if (epDesc != nullptr) + { + return std::format("{}:ctrl-{}", epDesc.get(), id); + } + } + return std::format("ctrl-{}", id); +}
diff --git a/src/NVMeVolume.cpp b/src/NVMeVolume.cpp index 4920fa2..59add3f 100644 --- a/src/NVMeVolume.cpp +++ b/src/NVMeVolume.cpp
@@ -151,8 +151,8 @@ catch (const std::exception& e) { lg2::error( - "Failed to get primary controller for feature store: {ERROR}", - "ERROR", e.what()); + "[{PATH}]Failed to get primary controller for feature store: {ERROR}", + "PATH", path, "ERROR", e.what()); return; } @@ -165,11 +165,12 @@ conn->get_io_context(), objServer, conn, path, ctrl->getNvmeIntf(), ctrl->getMiCtrl(), namespaceId(), FeatureScope::Namespace); - this->featureStore->init([](const std::error_code& ec) { + this->featureStore->init([path = this->path](const std::error_code& ec) { if (ec) { - lg2::error("Failed to initialize feature store for volume: {ERROR}", - "ERROR", ec.message()); + lg2::error( + "[{PATH}]Failed to initialize feature store for volume: {ERROR}", + "PATH", path, "ERROR", ec.message()); } }); }
diff --git a/src/Utils.hpp b/src/Utils.hpp index ed53334..8b99160 100644 --- a/src/Utils.hpp +++ b/src/Utils.hpp
@@ -8,15 +8,18 @@ #include <boost/algorithm/string/replace.hpp> #include <boost/asio/steady_timer.hpp> #include <boost/container/flat_map.hpp> +#include <phosphor-logging/lg2.hpp> #include <sdbusplus/asio/connection.hpp> #include <sdbusplus/asio/object_server.hpp> #include <sdbusplus/message/types.hpp> +#include <chrono> #include <filesystem> #include <functional> #include <iostream> #include <list> #include <memory> +#include <mutex> #include <optional> #include <regex> #include <span> @@ -26,6 +29,45 @@ #include <variant> #include <vector> +/** + * @brief Logs a message via lg2 at most once every N seconds specific to the + * call site. + * + * This macro utilizes static local variables to maintain state specific + * to the exact line of code where the macro is expanded. + * + * It uses double-checked locking to ensure thread safety if multiple threads + * hit the exact same log statement simultaneously. + * + * @param level The lg2 severity level (e.g., info, error, warning, debug). + * @param N The interval in seconds. + * @param msg The message format string. + * @param ... Optional arguments for the format string. + */ +#define LG2_LOG_EVERY_N_SEC(level, N, msg, ...) \ + do \ + { \ + /* The magic happens here: These static variables are unique per */ \ + /* every distinct place this macro is used in the source code. */ \ + static std::chrono::steady_clock::time_point _lg2_site_last_time; \ + static std::mutex _lg2_site_mutex; \ + \ + /* Use steady_clock so system time changes don't break the timer */ \ + auto _lg2_now = std::chrono::steady_clock::now(); \ + \ + /* Optimization: Quick check without locking first */ \ + if (_lg2_now - _lg2_site_last_time >= std::chrono::seconds(N)) \ + { \ + std::lock_guard<std::mutex> _lg2_lock(_lg2_site_mutex); \ + /* Thread Safety: Double-check inside lock */ \ + if (_lg2_now - _lg2_site_last_time >= std::chrono::seconds(N)) \ + { \ + lg2::level(msg, ##__VA_ARGS__); \ + _lg2_site_last_time = _lg2_now; \ + } \ + } \ + } while (0) + const constexpr char* jsonStore = "/var/configuration/flattened.json"; const constexpr char* inventoryPath = "/xyz/openbmc_project/inventory"; const constexpr char* entityManagerName = "xyz.openbmc_project.EntityManager";
diff --git a/src/sensor.hpp b/src/sensor.hpp index 13bf1d3..23ff9a9 100644 --- a/src/sensor.hpp +++ b/src/sensor.hpp
@@ -2,7 +2,6 @@ #include "dbus-sensor_config.h" -#include "NVMeUtil.hpp" #include "SensorPaths.hpp" #include "Thresholds.hpp" #include "Utils.hpp"