NVMe: use phosphor-logging/lg2 for logging Inspired by https://gerrit.openbmc.org/c/openbmc/dbus-sensors/+/78412. Using lg2 for nvmed logging. Also, utilize log level to concise the log printing. * using lg2::warning for all retries * using lg2::error for errors * using lg2::info for the state transition info * using lg2::debug for all debug related stuff Fix some minor issue which was not detected by std::cerr. Tested: journal log: https://paste.googleplex.com/6575901127081984 Change-Id: Ia14236654c2b12034e3d087ca84a5168c62106ea Signed-off-by: Hao Jiang <jianghao@google.com>
diff --git a/src/NVMeBasic.cpp b/src/NVMeBasic.cpp index de71423..f8fca8b 100644 --- a/src/NVMeBasic.cpp +++ b/src/NVMeBasic.cpp
@@ -7,6 +7,7 @@ #include <boost/asio/read.hpp> #include <boost/asio/streambuf.hpp> #include <boost/asio/write.hpp> +#include <phosphor-logging/lg2.hpp> #include <iostream> #include <map> @@ -72,9 +73,9 @@ // NOLINTNEXTLINE(cppcoreguidelines-pro-type-vararg) if (::ioctl(fileHandle.handle(), I2C_SLAVE, addr) == -1) { - std::cerr << "Failed to configure device address 0x" << std::hex - << (int)addr << " for bus " << std::dec << bus << ": " - << strerror(errno) << "\n"; + lg2::error( + "Failed to configure device address '{ADDR}' for bus '{BUS}': ERRNO", + "ADDR", lg2::hex, addr, "BUS", bus, "ERRNO", lg2::hex, errno); resp.resize(0); return; } @@ -85,16 +86,17 @@ size = i2c_smbus_read_block_data(fileHandle.handle(), cmd, resp.data()); if (size < 0) { - std::cerr << "Failed to read block data from device 0x" << std::hex - << (int)addr << " on bus " << std::dec << bus << ": " - << strerror(errno) << "\n"; + lg2::error( + "Failed to read block data from device '{ADDR}' on bus '{BUS}': ERRNO", + "ADDR", lg2::hex, addr, "BUS", bus, "ERRNO", lg2::hex, errno); resp.resize(0); } else if (size > UINT8_MAX + 1) { - std::cerr << "Unexpected message length from device 0x" << std::hex - << (int)addr << " on bus " << std::dec << bus << ": " - << size << " (" << UINT8_MAX << ")\n"; + lg2::error( + "Unexpected message length from device '{ADDR}' on bus '{BUS}': '{SIZE}' ({MAX})", + "ADDR", lg2::hex, addr, "BUS", bus, "SIZE", size, "MAX", + UINT8_MAX); resp.resize(0); } else @@ -104,8 +106,8 @@ } catch (const std::out_of_range& e) { - std::cerr << "Failed to create file handle for bus " << std::dec << bus - << ": " << e.what() << "\n"; + lg2::error("Failed to create file handle for bus '{BUS}': '{ERR}'", + "BUS", bus, "ERR", e); resp.resize(0); } } @@ -129,8 +131,9 @@ ssize_t rc = ::read(in.handle(), req.data(), req.size()); if (rc != static_cast<ssize_t>(req.size())) { - std::cerr << "Failed to read request from in descriptor " - << strerror(errno) << "\n"; + lg2::error( + "Failed to read request from in descriptor '{ERROR_MESSAGE}'", + "ERROR_MESSAGE", strerror(errno)); if (rc != 0) { return -errno; @@ -148,9 +151,9 @@ rc = ::write(out.handle(), &len, sizeof(len)); if (rc != sizeof(len)) { - std::cerr << "Failed to write block (" << std::dec << len - << ") length to out descriptor: " - << strerror(static_cast<int>(-rc)) << "\n"; + lg2::error( + "Failed to write block ({LEN}) length to out descriptor: '{ERRNO}'", + "LEN", len, "ERRNO", strerror(static_cast<int>(-rc))); if (rc != 0) { return -errno; @@ -166,9 +169,9 @@ ssize_t egress = ::write(out.handle(), &(*cursor), lenRemaining); if (egress == -1) { - std::cerr << "Failed to write block data of length " << std::dec - << lenRemaining << " to out pipe: " << strerror(errno) - << "\n"; + lg2::error( + "Failed to write block data of length '{LEN}' to out pipe: '{ERROR_MESSAGE}'", + "LEN", lenRemaining, "ERROR_MESSAGE", strerror(errno)); if (rc != 0) { return -errno; @@ -194,26 +197,26 @@ /* Set up inter-thread communication */ if (::pipe(requestPipe.data()) == -1) { - std::cerr << "Failed to create request pipe: " << strerror(errno) - << "\n"; + lg2::error("Failed to create request pipe: '{ERROR}'", "ERROR", + strerror(errno)); throw std::error_code(errno, std::system_category()); } if (::pipe(responsePipe.data()) == -1) { - std::cerr << "Failed to create response pipe: " << strerror(errno) - << "\n"; + lg2::error("Failed to create response pipe: '{ERROR}'", "ERROR", + strerror(errno)); if (::close(requestPipe[0]) == -1) { - std::cerr << "Failed to close write fd of request pipe: " - << strerror(errno) << "\n"; + lg2::error("Failed to close write fd of request pipe '{ERROR}'", + "ERROR", strerror(errno)); } if (::close(requestPipe[1]) == -1) { - std::cerr << "Failed to close read fd of request pipe: " - << strerror(errno) << "\n"; + lg2::error("Failed to close read fd of request pipe '{ERROR}'", + "ERROR", strerror(errno)); } throw std::error_code(errno, std::system_category()); @@ -231,11 +234,11 @@ if ((rc = procFunc(streamIn, streamOut)) < 0) { - std::cerr << "Failure while processing query stream: " - << strerror(static_cast<int>(-rc)) << "\n"; + lg2::error("Failure while processing query stream: '{ERROR}'", + "ERROR", strerror(static_cast<int>(-rc))); } - std::cerr << "Terminating basic query thread\n"; + lg2::error("Terminating basic query thread"); }); } @@ -269,7 +272,8 @@ [command](boost::system::error_code ec, std::size_t) { if (ec) { - std::cerr << "Got error writing basic query: " << ec << "\n"; + lg2::error("Got error writing basic query: '{ERROR_MESSAGE}'", + "ERROR_MESSAGE", ec.message()); } }); @@ -282,7 +286,8 @@ [response](const boost::system::error_code& ec, std::size_t n) { if (ec) { - std::cerr << "Got error completing basic query: " << ec << "\n"; + lg2::error("Got error completing basic query: '{ERROR_MESSAGE}'", + "ERROR_MESSAGE", ec.message()); return static_cast<std::size_t>(0); } @@ -296,8 +301,9 @@ if (n > len + 1) { - std::cerr << "Query stream has become unsynchronised: " << "n: " - << n << ", " << "len: " << len << "\n"; + lg2::error( + "Query stream has become unsynchronised: n: {N}, len: {LEN}", + "N", n, "LEN", len); return static_cast<std::size_t>(0); } @@ -318,7 +324,8 @@ const boost::system::error_code& ec, std::size_t length) mutable { if (ec) { - std::cerr << "Got error reading basic query: " << ec << "\n"; + lg2::error("Got error reading basic query: '{ERROR_MESSAGE}'", + "ERROR_MESSAGE", ec.message()); boost::asio::post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::io_error), nullptr); }); @@ -327,7 +334,7 @@ if (length == 0) { - std::cerr << "Invalid message length: " << length << "\n"; + lg2::error("Invalid message length: '{LEN}'", "LEN", length); return; }
diff --git a/src/NVMeCache.hpp b/src/NVMeCache.hpp index d1869ef..bf8e538 100644 --- a/src/NVMeCache.hpp +++ b/src/NVMeCache.hpp
@@ -1,9 +1,10 @@ #pragma once #include <boost/asio/steady_timer.hpp> +#include <phosphor-logging/lg2.hpp> #include <chrono> +#include <format> #include <functional> -#include <iostream> #include <memory> #include <set> #include <vector> @@ -215,8 +216,7 @@ auto metric = itr->second.lock(); if (!metric) { - // LOG_INFO - std::cerr << "the task is invalid, removed from task queue\n"; + lg2::info("the task is invalid, removed from task queue"); itr = taskQueue.erase(itr); } else if (!metric.owner_before(task) && @@ -256,8 +256,7 @@ weakFlag](boost::system::error_code ec) { if (ec || weakFlag.expired()) { - // LOG_INFO - std::cerr << "new expiration time set\n"; + lg2::info("new expiration time set"); return; } @@ -265,8 +264,7 @@ if (!self) { - // LOG_INFO - std::cerr << "the scheduler has stopped\n"; + lg2::info("the scheduler has stopped"); return; } @@ -275,8 +273,7 @@ auto task = weakTask.lock(); if (!task) { - // LOG_INFO - std::cerr << "the task is invalid, removed from task queue\n"; + lg2::info("the task is invalid, removed from task queue"); self->dequeue(); return; } @@ -290,7 +287,7 @@ std::shared_ptr<MetricBase<ClockType_>> task = weakTask.lock(); if (!task) { - std::cerr << "the task is invalid, removed from task queue\n"; + lg2::info("the task is invalid, removed from task queue"); self->executingTask.reset(); self->dequeue(); return;
diff --git a/src/NVMeCacheImpl.hpp b/src/NVMeCacheImpl.hpp index 0f5968f..51252f9 100644 --- a/src/NVMeCacheImpl.hpp +++ b/src/NVMeCacheImpl.hpp
@@ -100,9 +100,8 @@ ControllerLogPageMetric<LID, ClockType>>(weakSelf.lock()); if (!self) { - // TODO: error_level = INFO - std::cerr << std::format( - "[{}, {}]metric released before callback\n", path, id); + lg2::info("metric released before callback", "PATH", path, "ID", + id); // The Scheduler will clear the invalid cache Task cb({}, 4096, true); return; @@ -112,19 +111,17 @@ if (self->errorCount < ControllerLogPageMetric<LID, ClockType>::errorCountMax) { - // TODO: error_level = WARN - std::cerr << std::format( - "[{}, {}]fail to fresh log page at retry({})\n", path, - id, self->errorCount++); + lg2::warning("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; } - - std::cerr << std::format( - "[{}, {}]retry exhausted to fresh log page\n", path, id); + lg2::error("retry exhausted to fresh log page", "PATH", path, + "ID", id); self->cacheValid = false; // Notify the RefreshCB with error code; the task will @@ -247,9 +244,8 @@ weakSelf.lock()); if (!self) { - // TODO: error_level = INFO - std::cerr << std::format( - "[{}, {}]metric released before callback\n", path, id); + lg2::info("metric released before callback", "PATH", path, "ID", + id); // The Scheduler will clear the invalid cache Task cb({}, 4096, true); return; @@ -259,18 +255,17 @@ if (self->errorCount < IdentifyMetric<CNS, ClockType>::errorCountMax) { - // TODO: error_level = WARN - std::cerr << std::format( - "[{}, {}]fail to fresh identify at retry({}): {}\n", - path, id, self->errorCount++, ex->description()); + lg2::warning( + "fail to fresh identify at retry({RETRY}): {ERROR}", + "PATH", path, "ID", id, "RETRY", self->errorCount++, + "ERROR", ex->description()); // Schedule the retry after 1s cb(std::make_error_code(std::errc::io_error), 4096, false); return; } - std::cerr << std::format( - "[{}, {}]retry exhausted to fresh identify: {}\n", path, id, - ex->description()); + lg2::error("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 427b484..881f225 100644 --- a/src/NVMeController.cpp +++ b/src/NVMeController.cpp
@@ -8,6 +8,7 @@ #include "NVMePlugin.hpp" #include "NVMeSubsys.hpp" +#include <phosphor-logging/lg2.hpp> #include <sdbusplus/exception.hpp> #include <sdbusplus/message/native_types.hpp> #include <xyz/openbmc_project/Common/File/error.hpp> @@ -16,7 +17,6 @@ #include <cstdio> #include <filesystem> #include <fstream> -#include <iostream> // using sdbusplus::xyz::openbmc_project::Inventory::Item::server:: // StorageController; @@ -81,7 +81,7 @@ if (self->status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } return self->adminNonDataCmdMethod(std::move(yield), opcode, cdw1, cdw2, @@ -106,7 +106,7 @@ if (self->status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -128,7 +128,7 @@ if (self->status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -154,7 +154,7 @@ if (self->status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -174,7 +174,7 @@ if (self->status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -308,7 +308,7 @@ auto s = subsys.lock(); if (!s) { - std::cerr << "makeAssociation() after shutdown\n"; + lg2::error("makeAssociation() after shutdown"); return associations; } @@ -335,15 +335,15 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - std::cerr << "GetLogPage fails to open pipe: " << std::strerror(errno) - << '\n'; + lg2::error("GetLogPage fails to open pipe: {ERROR}", "ERROR", + strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open(); } @@ -356,7 +356,8 @@ std::span<uint8_t> data) { if (ec) { - std::cerr << "fail to GetLogPage: " << ec.message() << '\n'; + lg2::error("fail to GetLogPage: {ERROR}", "ERROR", + ec.message()); close(pipe[1]); close(pipe[0]); return; @@ -377,9 +378,8 @@ std::size_t /* transferredSize */) { if (error) { - std::cerr - << "GetLogPage fails to write fd: " << error.message() - << '\n'; + lg2::error("GetLogPage fails to write fd: {ERROR}", "ERROR", + error.message()); } }); @@ -409,7 +409,8 @@ std::span<uint8_t> data) { if (ec) { - std::cerr << "fail to GetLogPage: " << ec.message() << '\n'; + lg2::error("fail to GetLogPage: {ERROR}", "ERROR", + ec.message()); close(pipe[1]); close(pipe[0]); return; @@ -431,8 +432,8 @@ std::size_t /* transferredSize */) { if (error) { - std::cerr << "GetLogPage fails to write fd: " - << error.message() << '\n'; + lg2::error("GetLogPage fails to write fd: {ERROR}", + "ERROR", error.message()); } }); @@ -474,15 +475,15 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - std::cerr << "Identify fails to open pipe: " << std::strerror(errno) - << '\n'; + lg2::error("Identify fails to open pipe: {ERROR}", "ERROR", + strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open(); } @@ -491,7 +492,7 @@ [pipe, &io = this->io](const nvme_ex_ptr& ex, std::span<uint8_t> data) { if (ex) { - std::cerr << "fail to Identify: " << ex << '\n'; + lg2::error("fail to Identify: {ERROR}", "ERROR", ex->what()); close(pipe[1]); close(pipe[0]); return; @@ -512,8 +513,8 @@ std::size_t /* transferredSize */) { if (error) { - std::cerr << "Identify fails to write fd: " << error.message() - << '\n'; + lg2::error("Identify fails to write fd: {ERROR}", "ERROR", + error.message()); } }); @@ -558,7 +559,7 @@ if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -684,7 +685,7 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -714,7 +715,7 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -765,8 +766,8 @@ }, yield); - std::cerr << "nvme_status:" << nvmeStatus << ", dw0:" << completionDw0 - << '\n'; + lg2::debug("nvme_status:{STATUS}, dw0:{DW0}", "STATUS", nvmeStatus, "DW0", + completionDw0); if (nvmeStatus < 0) { throw sdbusplus::exception::SdBusError(err.value(), @@ -797,7 +798,7 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -844,7 +845,7 @@ } catch (const std::exception& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); throw sdbusplus::xyz::openbmc_project::Common::Error:: InternalFailure(); } @@ -859,7 +860,7 @@ { if (status != Status::Enabled) { - std::cerr << "Controller has been disabled" << '\n'; + lg2::error("Controller has been disabled"); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } @@ -906,7 +907,7 @@ } catch (const std::exception& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); throw sdbusplus::xyz::openbmc_project::Common::Error:: InternalFailure(); }
diff --git a/src/NVMeDrive.cpp b/src/NVMeDrive.cpp index 48bb6c1..d022961 100644 --- a/src/NVMeDrive.cpp +++ b/src/NVMeDrive.cpp
@@ -3,7 +3,7 @@ #include "NVMeError.hpp" #include "NVMeSubsys.hpp" -#include <iostream> +#include <phosphor-logging/lg2.hpp> namespace common_err = sdbusplus::xyz::openbmc_project::Common::Error; @@ -118,8 +118,8 @@ (void)scdw10; if (ex) { - std::cerr << "Error returned reading sanitize log: " << ex - << '\n'; + lg2::error("Error returned reading sanitize log: {ERROR}", + "ERROR", ex->what()); } else {
diff --git a/src/NVMeError.cpp b/src/NVMeError.cpp index eda98de..85e4ea5 100644 --- a/src/NVMeError.cpp +++ b/src/NVMeError.cpp
@@ -2,6 +2,7 @@ #include <libnvme-mi.h> +#include <phosphor-logging/lg2.hpp> #include <xyz/openbmc_project/Common/Device/error.hpp> #include <xyz/openbmc_project/Common/error.hpp> @@ -177,7 +178,8 @@ if (nvmeStatus < 0) { auto desc = std::string("libnvme error: ") + err.message(); - std::cerr << methodName << ":" << desc << '\n'; + lg2::error("{METHOD}: {DESC}", "METHOD", methodName, "DESC", + desc.c_str()); return std::make_shared<NVMeSdBusPlusError>(desc); } if (nvmeStatus > 0) @@ -196,11 +198,11 @@ translateLibNVMeMI(val, desc, specific); break; default: - std::cerr << "Unknown libnvme error status " << nvmeStatus - << '\n'; + lg2::error("Unknown libnvme error status {STATUS}", "STATUS", + nvmeStatus); desc = "Unknown libnvme error"; } - std::cerr << methodName << ":" << desc << '\n'; + lg2::error("{METHOD}: {DESC}", "METHOD", methodName, "DESC", desc); return std::make_shared<NVMeSdBusPlusError>(desc, specific); } // No Error
diff --git a/src/NVMeMetricStore.cpp b/src/NVMeMetricStore.cpp index d3f577f..ff39271 100644 --- a/src/NVMeMetricStore.cpp +++ b/src/NVMeMetricStore.cpp
@@ -1,5 +1,6 @@ #include "NVMeMetricStore.hpp" +#include <phosphor-logging/lg2.hpp> #include <xyz/openbmc_project/Common/File/error.hpp> #include <xyz/openbmc_project/Common/error.hpp> @@ -10,8 +11,8 @@ std::array<int, 2> pipe{}; if (::pipe(pipe.data()) < 0) { - std::cerr << "Metric Fetcher failed due to pipe creation " - << std::strerror(errno) << "\n"; + lg2::error("Metric Fetcher failed due to pipe creation: {ERROR}", + "ERROR", strerror(errno)); throw sdbusplus::xyz::openbmc_project::Common::File::Error::Open{}; } @@ -29,8 +30,8 @@ std::size_t /* transferredSize */) { if (error) { - std::cerr << "Metric Fetcher fails to write fd: " << error.message() - << "\n"; + lg2::error("Metric Fetcher fails to write fd: {ERROR}", "ERROR", + error.message()); } }); @@ -57,15 +58,15 @@ auto it = metricStore.find(name); if (it == metricStore.end() || !it->second) { - std::cerr << std::format("[{}, {}]cannot find the target Metric", - this->path, name); + lg2::error("Cannot find the target Metric", "PATH", this->path, "NAME", + name); throw sdbusplus::xyz::openbmc_project::Common::Error::InvalidArgument{}; } if (!it->second->isCacheValid()) { - std::cerr << std::format("[{}, {}]the Metric cache is invalid", - this->path, name); + lg2::error("The Metric cache is invalid", "PATH", this->path, "NAME", + name); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable{}; } auto data = it->second->getCache();
diff --git a/src/NVMeMetricStore.hpp b/src/NVMeMetricStore.hpp index 607108b..1d22c39 100644 --- a/src/NVMeMetricStore.hpp +++ b/src/NVMeMetricStore.hpp
@@ -18,7 +18,6 @@ #include <xyz/openbmc_project/NVMe/MetricStore/server.hpp> #include <functional> -#include <iostream> #include <memory> #include <string> #include <tuple> @@ -71,9 +70,8 @@ std::string{metric->getIdentifier()}, std::move(metric)); if (!res) { - std::cerr << std::format( - "[{}, {}] drop a duplicated vendor metic\n", path, - itr->first); + lg2::warning("drop a duplicated vendor metic", "PATH", path, + "METRIC", itr->first); } } @@ -89,10 +87,9 @@ // use validFlag to protect this call if (weakFlag.expired()) { - // TODO: log_level = INFO - std::cerr << std::format( - "[{}]MetricStore interface expired, update signal skipped.\n", - path); + lg2::info("MetricStore interface expired, update signal " + "skipped.", + "PATH", path); return; } auto metric = weakMetric.lock();
diff --git a/src/NVMeMi.cpp b/src/NVMeMi.cpp index 32162ae..46cbd94 100644 --- a/src/NVMeMi.cpp +++ b/src/NVMeMi.cpp
@@ -6,11 +6,11 @@ #include <endian.h> #include <boost/endian.hpp> +#include <phosphor-logging/lg2.hpp> #include <cassert> #include <cerrno> #include <fstream> -#include <iostream> #include <stdexcept> namespace common_err = sdbusplus::xyz::openbmc_project::Common::Error; @@ -63,9 +63,8 @@ case Status::Initiated: if (optimizeTimer) { - std::cerr << "[" << endpoint->describe() << "]" - << "Cancel the optimization Timer for the endpoint" - << '\n'; + lg2::info("Cancel the optimization Timer for the endpoint", + "ENDPOINT", endpoint->describe()); optimizeTimer->cancel(); } [[fallthrough]]; @@ -76,8 +75,7 @@ "nvmeEP was unpopulated in Status::Initiated state"); } mctpStatus = Status::Terminating; - std::cerr << "[" << endpoint->describe() << "]" - << "start MCTP closure" << '\n'; + lg2::info("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 @@ -91,8 +89,8 @@ self->mtu = 64; self->nvmeEP = nullptr; self->mctpStatus = Status::Reset; - std::cerr << "[" << self->device->describe() << "] " - << "end MCTP closure" << '\n'; + lg2::info("end MCTP closure", "DEVICE", + self->device->describe()); if (self->restart) { // If restart is true then we've captured the updated @@ -165,7 +163,8 @@ optimizeTimer->async_wait([this](boost::system::error_code ec) { if (ec) { - std::cerr << "Endpoint optimize timer error " << ec << '\n'; + lg2::error("Endpoint optimize timer error: {ERROR}", "ERROR", + ec.what()); return; } miSetMCTPConfiguration( @@ -173,9 +172,8 @@ self->optimizeTimer = nullptr; if (ec) { - std::cerr << "[" << self->device->describe() << "]" - << "Failed setting up MTU for the MCTP endpoint." - << '\n'; + lg2::error("Failed setting up MTU for the MCTP endpoint.", + "DEVICE", self->device->describe()); self->recover(); return; } @@ -223,8 +221,7 @@ if (!epConnect(endpoint->network(), endpoint->eid())) { epReset(); - std::cerr << "[" << ep->describe() << "]" - << "can't open MCTP endpoint " << '\n'; + lg2::error("can't open MCTP endpoint", "ENDPOINT", ep->describe()); return; } } @@ -344,7 +341,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << device->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); return std::make_error_code(std::errc::no_such_device); } return {}; @@ -356,8 +353,7 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - std::cerr << "[" << device->describe() << "]" - << "nvme endpoint is invalid" << '\n'; + lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -372,19 +368,19 @@ &smbusFreq); if (rc != 0) { - std::cerr << "[" << ep->describe() - << "] failed to get the SMBus frequency " << '\n'; + lg2::error("failed to get the SMBus frequency", "ENDPOINT", + ep->describe()); } else if (smbusFreq == NVME_MI_CONFIG_SMBUS_FREQ_100kHz) { - std::cerr << "[" << ep->describe() - << "] Setting the SMBus frequency to 400kHz\n"; + lg2::info("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) { - std::cerr << "[" << ep->describe() - << "] failed to set the SMBus frequency\n"; + lg2::error("failed to set the SMBus frequency", "ENDPOINT", + ep->describe()); } } if (rc != 0) @@ -399,7 +395,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << device->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); return; } } @@ -410,8 +406,7 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - std::cerr << "[" << device->describe() << "] " - << "nvme endpoint is invalid" << '\n'; + lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -428,9 +423,8 @@ if (rc != 0) { - std::cerr << "[" << self->device->describe() << "]" - << " failed to set remote MCTP MTU for port :" - << unsigned(port) << '\n'; + lg2::error("failed to set remote MCTP MTU for port: {PORT}", + "DEVICE", self->device->describe(), "PORT", port); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message)); }); @@ -451,7 +445,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << device->describe() << "] " << e.what() << '\n'; + lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -464,8 +458,7 @@ { if (mctpStatus == Status::Reset || mctpStatus == Status::Terminating) { - std::cerr << "[" << device->describe() << "] " - << "nvme endpoint is invalid" << '\n'; + lg2::error("nvme endpoint is invalid", "DEVICE", device->describe()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -481,8 +474,8 @@ nvme_mi_ep_set_timeout(self->nvmeEP, timeout); if (rc != 0) { - std::cerr << "[" << self->device->describe() << "] " - << "Failed reading subsystem info failing " << '\n'; + lg2::error("Failed reading subsystem info failing", "DEVICE", + self->device->describe()); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message)); }); @@ -497,9 +490,9 @@ if (rc != 0) { /* PCIe port might not be ready right after AC/DC cycle. */ - std::cerr << "[" << self->device->describe() - << "] failed reading port info for port_id: " - << unsigned(portId) << '\n'; + lg2::error("failed reading port info for port_id: {PORT}", + "DEVICE", self->device->describe(), "PORT", + portId); } else if (portInfo.portt == 0x2) // SMBus ports = 0x2 { @@ -521,7 +514,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << device->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device)); }); @@ -538,17 +531,16 @@ retries](const std::error_code& ec) mutable { if (!endpoint) { - std::cerr << "[" << device->describe() << "] " - << "failed to set MCTP path MTU: Status::Terminating" - << '\n'; + lg2::error("failed to set MCTP path MTU: Status::Terminating", + "DEVICE", device->describe()); cb(ec); return; } if (!ec) { - std::cout << "[" << endpoint->describe() << "] " - << "Finished MCTP initialization. MTU: " << mtu << '\n'; + lg2::info("Finished MCTP initialization. MTU: {MTU}", "ENDPOINT", + endpoint->describe(), "MTU", mtu); cb(ec); return; } @@ -556,15 +548,14 @@ retries--; if (retries == 0) { - std::cerr << "[" << endpoint->describe() << "] " - << "failed to set MCTP path MTU: " << ec.message() - << '\n'; + lg2::error("failed to set MCTP path MTU: {ERROR}", "ENDPOINT", + endpoint->describe(), "ERROR", ec.message()); cb(ec); return; } - std::cerr << "[" << endpoint->describe() << "] " - << "retry to set MCTP path MTU" << '\n'; + lg2::warning("retry to set MCTP path MTU", "ENDPOINT", + endpoint->describe()); configureLocalRouteMtu(std::move(cb), retries); }; endpoint->setMtu(mctpMtu, std::move(retry)); @@ -576,8 +567,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post([cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, nullptr); @@ -593,9 +584,9 @@ true, &ssHealth); if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << " fail to subsystem_health_status_poll: " - << std::strerror(errno) << '\n'; + lg2::error("fail to subsystem_health_status_poll: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); self->io.post([cb{cb}, lastErrno{errno}]() mutable { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), nullptr); @@ -606,9 +597,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - std::cerr << "[" << ep->describe() << "]" - << " fail to subsystem_health_status_poll: " << errMsg - << '\n'; + lg2::error("fail to subsystem_health_status_poll: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", errMsg.data()); self->io.post([cb{cb}]() mutable { cb(std::make_error_code(std::errc::bad_message), nullptr); }); @@ -621,7 +611,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << device->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "DEVICE", device->describe(), "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -635,8 +625,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post( [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, {}); }); @@ -649,9 +639,8 @@ int rc = nvme_mi_scan_ep(self->nvmeEP, true); if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to scan controllers: " - << std::strerror(errno) << '\n'; + lg2::error("fail to scan controllers: {ERROR}", "ENDPOINT", + ep->describe(), "ERROR", strerror(errno)); self->io.post([cb{cb}, lastErrno{errno}]() mutable { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), {}); @@ -662,8 +651,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - std::cerr << "[" << ep->describe() << "]" - << "fail to scan controllers: " << errMsg << '\n'; + lg2::error("fail to scan controllers: {ERROR}", "ENDPOINT", + ep->describe(), "ERROR", errMsg.data()); self->io.post([cb{cb}]() mutable { cb(std::make_error_code(std::errc::bad_message), {}); }); @@ -682,7 +671,8 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << endpoint->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", + e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -702,7 +692,7 @@ } catch (const std::runtime_error& e) { - std::cerr << "Runtime error: " << e.what() << '\n'; + lg2::error("Runtime error: {ERROR}", "ERROR", e.what()); return false; } } @@ -713,8 +703,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post([cb{std::move(cb)}, errc{degraded.value()}]() { cb(makeLibNVMeError("nvme endpoint is degraded"), {}); }); @@ -770,23 +760,22 @@ if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to do nvme identify: " - << std::strerror(errno) << '\n'; + lg2::error("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)); - std::cerr << "[" << ep->describe() << "]" - << "fail to do nvme identify: " << errMsg << '\n'; + lg2::error("fail to do nvme identify: {ERROR}", "ENDPOINT", + ep->describe(), "ERROR", errMsg.data()); } auto ex = makeLibNVMeError(errno, rc, "adminIdentify"); if (ex) { - std::cerr << "fail to do nvme identify: " << ex->description() - << '\n'; + lg2::error("fail to do nvme identify: {ERROR}", "ERROR", + ex->description()); } self->io.post([cb{cb}, ex, data{std::move(data)}]() mutable { @@ -797,9 +786,10 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << endpoint->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", + e.what()); auto msg = std::string("Runtime error: ") + e.what(); - std::cerr << msg << '\n'; + lg2::error("{MSG}", "MSG", msg); io.post([cb{std::move(cb)}, msg]() { cb(makeLibNVMeError(msg), {}); }); return; } @@ -826,7 +816,7 @@ rc = nvme_mi_admin_get_log_create_telemetry_host(ctrl, &log); if (rc != 0) { - std::cerr << "failed to create telemetry host log" << '\n'; + lg2::error("failed to create telemetry host log"); return rc; } } @@ -835,8 +825,8 @@ if (rc != 0) { - std::cerr << "failed to retain telemetry log for " - << (host ? "host" : "ctrl") << '\n'; + lg2::error("failed to retain telemetry log for {TYPE}", "TYPE", + [host] { return host ? "host" : "ctrl"; }()); return rc; } @@ -857,9 +847,10 @@ { if (offset >= data.size()) { - std::cerr << "[" << device->describe() << "]" - << "get telemetry log: offset exceed the log size. " - << "offset: " << offset << ", size: " << data.size() << '\n'; + lg2::error( + "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), {}); return; } @@ -884,9 +875,8 @@ if (rc < 0) { - std::cerr << "[" << self->device->describe() << "]" - << "fail to get chunk for telemetry log: " - << std::strerror(errno) << '\n'; + lg2::error("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)), {}); @@ -897,9 +887,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - std::cerr << "[" << self->device->describe() << "]" - << "fail to get chunk for telemetry log: " << errMsg - << '\n'; + lg2::error("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), {}); }); @@ -933,8 +922,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post( [cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, {}); }); return; @@ -965,8 +954,8 @@ rc = nvme_mi_admin_get_log_error(ctrl, num, false, log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get error log" << '\n'; + lg2::error("fail to get error log", "ENDPOINT", + ep->describe()); break; } } @@ -980,8 +969,8 @@ rc = nvme_mi_admin_get_log_smart(ctrl, nsid, false, log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get smart log" << '\n'; + lg2::error("fail to get smart log", "ENDPOINT", + ep->describe()); break; } } @@ -1005,8 +994,8 @@ rc = nvme_mi_admin_get_log_fw_slot(ctrl, false, log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get firmware slot" << '\n'; + lg2::error("fail to get firmware slot", "ENDPOINT", + ep->describe()); break; } } @@ -1024,9 +1013,8 @@ log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get cmd supported and effects log" - << '\n'; + lg2::error("fail to get cmd supported and effects log", + "ENDPOINT", ep->describe()); break; } } @@ -1040,8 +1028,8 @@ rc = nvme_mi_admin_get_log_device_self_test(ctrl, log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get device self test log" << '\n'; + lg2::error("fail to get device self test log", + "ENDPOINT", ep->describe()); break; } } @@ -1056,9 +1044,8 @@ log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get changed namespace list" - << '\n'; + lg2::error("fail to get changed namespace list", + "ENDPOINT", ep->describe()); break; } } @@ -1092,10 +1079,9 @@ int rc = nvme_mi_admin_get_log_lockdown(ctrl, lsp, log); if (rc != 0) { - std::cerr - << "[" << ep->describe() << "]" - << "fail to get command and feature lockdown log" - << '\n'; + lg2::error( + "fail to get command and feature lockdown log", + "ENDPOINT", ep->describe()); break; } } @@ -1112,10 +1098,8 @@ log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get reservation " - "notification log" - << '\n'; + lg2::error("fail to get reservation notification log", + "ENDPOINT", ep->describe()); break; } } @@ -1130,16 +1114,16 @@ int rc = nvme_mi_admin_get_log_sanitize(ctrl, false, log); if (rc != 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get sanitize status log" << '\n'; + lg2::error("fail to get sanitize status log", + "ENDPOINT", ep->describe()); break; } } break; default: { - std::cerr << "[" << ep->describe() << "]" - << "unknown lid for GetLogPage" << '\n'; + lg2::error("unknown lid for GetLogPage", "ENDPOINT", + ep->describe()); rc = -1; errno = EINVAL; } @@ -1147,9 +1131,8 @@ if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to get log page: " << std::strerror(errno) - << '\n'; + lg2::error("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)), {}); @@ -1159,8 +1142,8 @@ { std::string_view errMsg = statusToString(static_cast<nvme_mi_resp_status>(rc)); - std::cerr << "[" << ep->describe() << "]" - << "fail to get log pag: " << errMsg << '\n'; + lg2::error("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), {}); }; @@ -1178,8 +1161,8 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << endpoint->describe() << "]" - << "NVMeMi adminGetLogPage throws: " << e.what() << '\n'; + lg2::error("NVMeMi adminGetLogPage throws: {ERROR}", "ENDPOINT", + endpoint->describe(), "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -1195,8 +1178,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post([cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, {}, {}); }); @@ -1243,8 +1226,8 @@ if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << "failed to nvme_mi_admin_xfer" << '\n'; + lg2::error("failed to nvme_mi_admin_xfer", "ENDPOINT", + ep->describe()); self->io.post([cb{std::move(cb)}, lastErrno{errno}]() { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), {}, {}); @@ -1268,7 +1251,8 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << endpoint->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", + e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}, {}); }); @@ -1282,8 +1266,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post([cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, nvme_status_field::NVME_SC_MASK); }); @@ -1302,9 +1286,9 @@ int rc = nvme_mi_admin_fw_commit(ctrl, &args); if (rc < 0) { - std::cerr << "[" << ep->describe() << "]" - << "fail to nvme_mi_admin_fw_commit: " - << std::strerror(errno) << '\n'; + lg2::error("fail to nvme_mi_admin_fw_commit: {ERROR}", + "ENDPOINT", ep->describe(), "ERROR", + strerror(errno)); self->io.post([cb{std::move(cb)}, lastErrno{errno}]() { cb(std::make_error_code(static_cast<std::errc>(lastErrno)), nvme_status_field::NVME_SC_MASK); @@ -1326,9 +1310,8 @@ default: std::string_view errMsg = statusToString( static_cast<nvme_mi_resp_status>(rc)); - std::cerr - << "fail to nvme_mi_admin_fw_commit: " << errMsg - << '\n'; + lg2::error("fail to nvme_mi_admin_fw_commit: {ERROR}", + "ERROR", errMsg.data()); self->io.post([rc, cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message), static_cast<nvme_status_field>(rc)); @@ -1340,7 +1323,8 @@ } catch (const std::runtime_error& e) { - std::cerr << "[" << endpoint->describe() << "]" << e.what() << '\n'; + lg2::error("{ERROR}", "ENDPOINT", endpoint->describe(), "ERROR", + e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1356,8 +1340,8 @@ { if (auto degraded = isEndpointDegraded()) { - std::cerr << "[" << device->describe() << "]" - << " MCTP connection is not established" << '\n'; + lg2::error("MCTP connection is not established", "DEVICE", + device->describe()); io.post([cb{std::move(cb)}, errc{degraded.value()}]() { cb(errc, nvme_status_field::NVME_SC_MASK); }); @@ -1371,8 +1355,8 @@ std::ifstream fwFile(firmwarefile, std::ios::in | std::ios::binary); if (fwFile.fail()) { - std::cerr << "fail to open fw image file: " << firmwarefile - << strerror(errno) << '\n'; + lg2::error("fail to open fw image file: {FILE}, {ERROR}", + "FILE", firmwarefile, "ERROR", strerror(errno)); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), nvme_status_field::NVME_SC_MASK); @@ -1398,15 +1382,15 @@ { if (attemptCount > 0) { - std::cout << "Retrying the firmware chunk. With Offset :" - << offset << " Total firmware Size :" << size - << '\n'; + lg2::warning( + "Retrying the firmware chunk. With Offset: {OFFSET}, Total firmware Size: {SIZE}", + "OFFSET", offset, "SIZE", size); attemptCount = attemptCount - 1; } else { - std::cerr << "fail to nvme_mi_admin_fw_download: " - << std::strerror(errno) << '\n'; + lg2::error("fail to nvme_mi_admin_fw_download: {ERROR}", + "ERROR", strerror(errno)); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), nvme_status_field::NVME_SC_MASK); @@ -1421,9 +1405,9 @@ } if (offset >= size) { - std::cout - << "Successfully transferred the firmware. Transfer Size : " - << offset << " Total Size :" << size << '\n'; + lg2::info( + "Successfully transferred the firmware. Transfer Size: {XFER}, Total Size: {SIZE}", + "XFER", offset, "SIZE", size); self->io.post([rc, cb{std::move(cb)}]() { cb({}, static_cast<nvme_status_field>(rc)); }); @@ -1438,7 +1422,7 @@ } catch (const std::runtime_error& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1457,8 +1441,8 @@ std::ios::in | std::ios::binary | std::ios::ate); if (imageFile.fail()) { - std::cerr << "Can't open the firmware file: " << std::strerror(errno) - << '\n'; + lg2::error("Can't open the firmware file: {ERROR}", "ERROR", + strerror(errno)); io.post([cb{cb}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -1499,8 +1483,8 @@ }); if (postErr) { - std::cerr << "[" << device->describe() << "]" - << "adminSecuritySend post failed: " << postErr << '\n'; + lg2::error("adminSecuritySend post failed: {ERROR}", "DEVICE", + device->describe(), "ERROR", postErr.message()); io.post([cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); } } @@ -1539,9 +1523,9 @@ if (args.data_len > maxNVMeMILength) { - std::cerr << "[" << self->device->describe() << "]" - << "nvme_mi_admin_security_send returned excess data, " - << args.data_len << '\n'; + lg2::error( + "nvme_mi_admin_security_send returned excess data, {LEN}", + "DEVICE", self->device->describe(), "LEN", args.data_len); self->io.post([cb]() { cb(std::make_error_code(std::errc::protocol_error), -1, {}); }); @@ -1557,8 +1541,8 @@ }); if (postErr) { - std::cerr << "[" << device->describe() << "]" - << "adminSecurityReceive post failed: " << postErr << '\n'; + lg2::error("adminSecurityReceive post failed: {ERROR}", "DEVICE", + device->describe(), "ERROR", postErr.message()); io.post([cb{std::move(cb)}, postErr]() { cb(postErr, -1, {}); }); } } @@ -1585,8 +1569,8 @@ }); if (postErr) { - std::cerr << "[" << device->describe() << "]" - << "adminNonDataCmd post failed: " << postErr << '\n'; + lg2::error("adminNonDataCmd post failed: {ERROR}", "DEVICE", + device->describe(), "ERROR", postErr.message()); io.post([cb{std::move(cb)}, postErr]() { cb(postErr, -1, 0); }); } } @@ -1595,7 +1579,7 @@ size_t NVMeMi::getBlockSize(nvme_mi_ctrl_t ctrl, size_t lbaFormat) { struct nvme_id_ns id = {}; - std::cout << "getblocksize" << '\n'; + lg2::debug("getblocksize"); int status = nvme_mi_admin_identify_ns(ctrl, NVME_NSID_ALL, &id); auto e = makeLibNVMeError(errno, status, "getBlockSize"); if (e) @@ -1605,7 +1589,8 @@ throw e; } - std::cout << "nlbaf " << (int)id.nlbaf << "lbaf " << (int)lbaFormat << '\n'; + lg2::debug("nlbaf {NLBAF}, lbaf {LBAF}", "NLBAF", (int)id.nlbaf, "LBAF", + (int)lbaFormat); // Sanity check for the value from the drive size_t maxLbaf = std::min(63, (int)id.nlbaf); @@ -1629,7 +1614,7 @@ std::function<void(nvme_ex_ptr ex)>&& submittedCb, std::function<void(nvme_ex_ptr ex, NVMeNSIdentify newid)>&& finishedCb) { - std::cout << "createns " << (int)gettid() << '\n'; + lg2::debug("createns {TID}", "TID", (int)gettid()); std::error_code postErr = tryPost( [self{shared_from_this()}, ctrl, size, lbaFormat, metadataAtEnd, submittedCb{submittedCb}, finishedCb{std::move(finishedCb)}]() { @@ -1679,14 +1664,14 @@ data.ncap = ::htole64(blocks); data.flbas = flbas; - std::cout << "verified " << (int)gettid() << '\n'; + lg2::debug("verified {TID}", "TID", (int)gettid()); // submission has been verified. Handle the cb in main thread // concurrently. self->io.post([submittedCb{submittedCb}]() mutable { submittedCb(nvme_ex_ptr()); }); - std::cout << "after submitted_cb " << (int)gettid() << '\n'; + lg2::debug("after submitted_cb {TID}", "TID", (int)gettid()); unsigned timeout = nvme_mi_ep_get_timeout(self->nvmeEP); nvme_mi_ep_set_timeout(self->nvmeEP, namespaceDefaultTimeoutMS); @@ -1724,12 +1709,12 @@ #endif }); - std::cout << "submitted cb " << (int)gettid() << '\n'; + lg2::debug("submitted cb {TID}", "TID", (int)gettid()); if (postErr) { - std::cerr << "adminAttachDetachNamespace post failed: " << postErr - << '\n'; + lg2::error("createNamespace post failed: {ERROR}", "ERROR", + postErr.message()); auto e = makeLibNVMeError(postErr, -1, "createVolume"); io.post([submittedCb{std::move(submittedCb)}, e]() { submittedCb(e); }); } @@ -1754,7 +1739,8 @@ }); if (postErr) { - std::cerr << "deleteNamespace post failed: " << postErr << '\n'; + lg2::error("deleteNamespace post failed: {ERROR}", "ERROR", + postErr.message()); io.post([cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); } } @@ -1851,8 +1837,8 @@ }); if (postErr) { - std::cerr << "adminAttachDetachNamespace post failed: " << postErr - << '\n'; + lg2::error("adminAttachDetachNamespace post failed: {ERROR}", "ERROR", + postErr.message()); io.post([cb{std::move(cb)}, postErr]() { cb(postErr, -1); }); } } @@ -1875,7 +1861,8 @@ 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); - std::cout << "san status " << status << "errno " << errno << '\n'; + lg2::debug("san status {STATUS}, errno {ERRNO}", "STATUS", status, + "ERRNO", errno); auto ex = makeLibNVMeError(errno, status, "adminSanitize"); self->io.post([cb{cb}, ex]() mutable { cb(ex); });
diff --git a/src/NVMeMiFake.hpp b/src/NVMeMiFake.hpp index bd13504..ce22761 100644 --- a/src/NVMeMiFake.hpp +++ b/src/NVMeMiFake.hpp
@@ -2,8 +2,8 @@ #include <boost/asio.hpp> #include <boost/endian.hpp> +#include <phosphor-logging/lg2.hpp> -#include <iostream> #include <thread> struct ListNode @@ -30,8 +30,8 @@ thread = std::thread([&io = workerIO, &stop = workerStop, &mtx = workerMtx, &cv = workerCv, &isNotified = workerIsNotified, delay]() { - std::cerr << "NVMeMiFake worker thread started: " << io.stopped() - << '\n'; + lg2::info("NVMeMiFake worker thread started: {STOPPED}", "STOPPED", + io.stopped()); // With BOOST_ASIO_DISABLE_THREADS, boost::asio::executor_work_guard // issues null_event across the thread, which caused invalid // invokation. We implement a simple invoke machenism based @@ -44,7 +44,7 @@ std::this_thread::sleep_for(delay); io.run(); io.restart(); - std::cerr << "job done\n"; + lg2::info("job done"); { std::unique_lock<std::mutex> lock(mtx); cv.wait(lock, [&]() { return isNotified; }); @@ -57,22 +57,22 @@ } } } - std::cerr << "NVMeMi worker this line should not be reached\n"; + lg2::error("NVMeMi worker this line should not be reached"); }); ctrls.resize(3); - std::cerr << "NVMeMiFake constructor\n"; + lg2::info("NVMeMiFake constructor"); } ~NVMeMiFake() override { if (valid) { - std::cerr << "NVMeMiFake destroyer\n"; + lg2::info("NVMeMiFake destroyer"); } else { - std::cerr << "NVMeMiFake default destroyer\n"; + lg2::info("NVMeMiFake default destroyer"); } // close worker @@ -109,7 +109,7 @@ { if (workerStop) { - std::cerr << "worker thread for nvme endpoint is stopped\n"; + lg2::error("worker thread for nvme endpoint is stopped"); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); @@ -118,7 +118,7 @@ } post([self{shared_from_this()}, cb = std::move(cb)] { - std::cerr << "libnvme: scan\n"; + lg2::info("libnvme: scan"); self->io.post([self{self->shared_from_this()}, cb{cb}]() mutable { auto& ctrl1 = self->ctrls[0]; auto& ctrl2 = self->ctrls[1]; @@ -145,9 +145,9 @@ [[maybe_unused]] uint32_t nsid, [[maybe_unused]] uint16_t cntid, std::function<void(nvme_ex_ptr, std::span<uint8_t>)>&& cb) override { - std::cerr << "identify\n"; + lg2::info("identify"); post([self{shared_from_this()}, cb = std::move(cb), cns, nsid]() { - std::cerr << "libnvme: identify\n"; + lg2::info("libnvme: identify"); self->io.post([cb{cb}, cns, nsid]() mutable { std::vector<uint8_t> data; switch (cns) @@ -214,8 +214,8 @@ log.lpi = 0x07; if (rc != 0) { - std::cerr - << "failed to create telemetry host log\n"; + lg2::error( + "failed to create telemetry host log"); throw std::system_error( errno, std::generic_category()); } @@ -236,9 +236,8 @@ if (rc != 0) { - std::cerr - << "failed to retain telemetry host " - "log full log\n"; + lg2::error( + "failed to retain telemetry host log full log"); throw std::system_error( errno, std::generic_category()); } @@ -264,7 +263,7 @@ default: { - std::cerr << "unknown lid for GetLogPage\n"; + lg2::error("unknown lid for GetLogPage"); throw std::system_error(std::make_error_code( std::errc::invalid_argument)); } @@ -284,7 +283,7 @@ } catch (const std::runtime_error& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}); }); @@ -308,8 +307,8 @@ int rc = 1; if (rc < 0) { - std::cerr << "fail to subsystem_health_status_poll: " - << std::strerror(errno) << '\n'; + lg2::error("fail to subsystem_health_status_poll: {ERROR}", + "ERROR", strerror(errno)); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), nvme_status_field::NVME_SC_MASK); @@ -330,9 +329,9 @@ default: std::string_view errMsg = statusToString( static_cast<nvme_mi_resp_status>(rc)); - std::cerr - << "fail to subsystem_health_status_poll: " - << errMsg << '\n'; + lg2::error( + "fail to subsystem_health_status_poll: {ERROR}", + "ERROR", errMsg.data()); self->io.post([rc, cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::bad_message), static_cast<nvme_status_field>(rc)); @@ -344,7 +343,7 @@ } catch (const std::runtime_error& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), nvme_status_field::NVME_SC_MASK); @@ -392,7 +391,7 @@ if (rc < 0) { - std::cerr << "failed to nvme_mi_admin_xfer\n"; + lg2::error("failed to nvme_mi_admin_xfer"); self->io.post([cb{std::move(cb)}]() { cb(std::make_error_code(static_cast<std::errc>(errno)), {}, {}); @@ -425,7 +424,7 @@ } catch (const std::runtime_error& e) { - std::cerr << e.what() << '\n'; + lg2::error("{ERROR}", "ERROR", e.what()); io.post([cb{std::move(cb)}]() { cb(std::make_error_code(std::errc::no_such_device), {}, {}); }); @@ -545,7 +544,7 @@ std::unique_lock<std::mutex> lock(workerMtx); if (!workerStop) { - std::cerr << "do post\n"; + lg2::info("do post"); workerIsNotified = true; workerIO.post(std::move(func)); workerCv.notify_all();
diff --git a/src/NVMePlugin.cpp b/src/NVMePlugin.cpp index e450017..702065c 100644 --- a/src/NVMePlugin.cpp +++ b/src/NVMePlugin.cpp
@@ -7,6 +7,8 @@ #include "NVMeSubsys.hpp" #include "Utils.hpp" +#include <phosphor-logging/lg2.hpp> + // map from plugin path (subsystem path) to getMetric function std::unordered_map<std::string, std::function<std::vector<std::shared_ptr<MetricBase<>>>( @@ -22,9 +24,8 @@ if (res == subsystem->controllers.end() || &controller != res->second.first.get()) { - std::cerr << ("Failed to create controller plugin: " - "cannot find the controller") - << '\n'; + lg2::error( + "Failed to create controller plugin: cannot find the controller"); res->second.second.reset(); return {}; }
diff --git a/src/NVMeSensorMain.cpp b/src/NVMeSensorMain.cpp index b3a32b5..7189cdb 100644 --- a/src/NVMeSensorMain.cpp +++ b/src/NVMeSensorMain.cpp
@@ -26,6 +26,7 @@ #include <boost/algorithm/string.hpp> #include <boost/asio/steady_timer.hpp> +#include <phosphor-logging/lg2.hpp> #include <filesystem> #include <fstream> @@ -63,19 +64,20 @@ const std::string confPath = "/var/run/nvmed/banned-i2c-bus.conf"; if (!std::filesystem::exists(script)) { - std::cerr << "Script " << script << " doesn't exist" << '\n'; + lg2::error("Script {SCRIPT} doesn't exist", "SCRIPT", script); return; } - std::cerr << "Begin to execute " << script << '\n'; + lg2::info("Begin to execute {SCRIPT}", "SCRIPT", script); // TODO: (b/376270522) cert-env33-c error: calling 'system' uses a command // processor int rc = std::system(script.c_str()); // NOLINT(cert-env33-c) - std::cerr << "Shell script rc = " << rc << '\n'; + lg2::info("Shell script rc = {RC}", "RC", rc); if (!std::filesystem::exists(confPath)) { - std::cerr << "Warning: " << confPath << " doesn't exist." << '\n'; + lg2::warning("Warning: {CONF_PATH} doesn't exist.", "CONF_PATH", + confPath); // Be optimistic，assume no bus is banned return; } @@ -83,7 +85,7 @@ file.open(confPath); if (!file.is_open()) { - std::cerr << "Error: cannot open " << confPath << '\n'; + lg2::error("Error: cannot open {CONF_PATH}", "CONF_PATH", confPath); // Be optimistic，assume no bus is banned return; } @@ -92,7 +94,7 @@ int i2cBus{0}; while (file >> i2cBus) { - std::cerr << "Banned i2c bus: " << i2cBus << '\n'; + lg2::info("Banned i2c bus: {BUS}", "BUS", i2cBus); bannedBuses.insert(i2cBus); } file.close(); @@ -105,7 +107,7 @@ auto findBus = properties.find("Bus"); if (findBus == properties.end()) { - std::cerr << "could not determine bus number for " << path << "\n"; + lg2::error("could not determine bus number for '{PATH}'", "PATH", path); return std::nullopt; } @@ -118,7 +120,7 @@ auto findAddr = properties.find("Address"); if (findAddr == properties.end()) { - std::cerr << "could not determine address for " << path << "\n"; + lg2::error("could not determine address for '{PATH}'", "PATH", path); return std::nullopt; } @@ -131,8 +133,8 @@ auto findName = properties.find("Name"); if (findName == properties.end()) { - std::cerr << "could not determine configuration name for " << path - << "\n"; + lg2::error("could not determine configuration name for '{PATH}'", + "PATH", path); return std::nullopt; } @@ -146,7 +148,8 @@ auto findProtocol = properties.find("Protocol"); if (findProtocol == properties.end()) { - std::cerr << "could not determine nvme protocl for " << path << "\n"; + lg2::error("could not determine nvme protocol for '{PATH}'", "PATH", + path); return std::nullopt; } return std::get<std::string>(findProtocol->second); @@ -298,15 +301,15 @@ // I2C directly. if (!isMctpReactorDevice && !isI2cAccessible) { - std::cerr << "Found an mctpd device that isn't I2C accessible," - "but it must be: " - << nvmeObjectPath.str << '\n'; + lg2::info("Found an mctpd device that isn't I2C accessible," + "but it must be: {PATH}", + "PATH", nvmeObjectPath.str); continue; } if (busNumber && bannedBuses.contains(*busNumber)) { - std::cerr << "Skip banned i2c bus:" << *busNumber << '\n'; + lg2::info("Skip banned i2c bus: {BUS}", "BUS", *busNumber); continue; } @@ -320,8 +323,8 @@ // protocol because we don't need it for now. if (*nvmeProtocol == "mi_basic" && !isI2cAccessible) { - std::cerr << "Skipping an mi_basic device that's not accessible " - "over i2c bus.\n"; + lg2::info("Skipping an mi_basic device that's not accessible " + "over i2c bus."); continue; } @@ -342,9 +345,9 @@ } catch (std::exception& ex) { - std::cerr << "Failed to add nvme basic interface for " - << std::string(nvmeObjectPath) << ": " << ex.what() - << "\n"; + lg2::error( + "Failed to add nvme basic interface for '{PATH}': {ERROR}", + "PATH", nvmeObjectPath.str, "ERROR", ex.what()); continue; } } @@ -413,9 +416,9 @@ } catch (std::exception& ex) { - std::cerr << "Failed to add nvme mi interface for " - << std::string(nvmeObjectPath) << ": " << ex.what() - << "\n"; + lg2::error( + "Failed to add nvme mi interface for '{PATH}': {ERROR}", + "PATH", nvmeObjectPath.str, "ERROR", ex.what()); continue; } } @@ -466,9 +469,8 @@ } catch (std::exception& ex) { - std::cerr << "Failed to add nvme subsystem for " - << std::string(interfacePath) << ": " << ex.what() - << "\n"; + lg2::error("Failed to add nvme subsystem for '{PATH}': {ERROR}", + "PATH", std::string(interfacePath), "ERROR", ex.what()); continue; } } @@ -503,9 +505,8 @@ } else { - std::cerr << "more than one `handleConfigurations` has been " - "scheduled, cancel the current one" - << '\n'; + lg2::error("more than one `handleConfigurations` has been " + "scheduled, cancel the current one"); } }); auto timer = std::make_shared<boost::asio::steady_timer>( @@ -523,9 +524,8 @@ } else { - std::cerr << "`handleConfigurations` has not been triggered, " - "cancel the time" - << '\n'; + lg2::error("`handleConfigurations` has not been triggered, " + "cancel the timer"); } }); @@ -536,7 +536,7 @@ { if (message.is_method_error()) { - std::cerr << "interfacesRemoved callback method error\n"; + lg2::error("interfacesRemoved callback method error"); return; } @@ -566,7 +566,7 @@ { if (singleWorkerFeature) { - std::cerr << "singleWorkerFeature on " << '\n'; + lg2::info("singleWorkerFeature on"); } // Load plugin shared libraries @@ -582,13 +582,14 @@ } else { - std::cerr << "could not load the plugin: " << dlerror() << '\n'; + lg2::error("could not load the plugin: {ERROR}", "ERROR", + dlerror()); } } } catch (const std::filesystem::filesystem_error& e) { - std::cerr << "failed to open plugin folder: " << e.what() << '\n'; + lg2::error("failed to open plugin folder: {ERROR}", "ERROR", e.what()); } // TODO: set single thread mode according to input parameters @@ -616,7 +617,7 @@ if (ec) { - std::cerr << "Error: " << ec.message() << "\n"; + lg2::error("Error: {ERROR}", "ERROR", ec.message()); return; } @@ -644,8 +645,8 @@ boost::asio::signal_set signals(io, SIGPIPE); signals.async_wait( [](const boost::system::error_code& error, int signalNumber) { - std::cerr << "signal: " << strsignal(signalNumber) << ", " - << error.message() << '\n'; + lg2::info("signal: {SIGNAL}, {ERROR}", "SIGNAL", + strsignal(signalNumber), "ERROR", error.message()); }); io.run();
diff --git a/src/NVMeSubsys.cpp b/src/NVMeSubsys.cpp index e2ae09c..0ae9a2f 100644 --- a/src/NVMeSubsys.cpp +++ b/src/NVMeSubsys.cpp
@@ -183,9 +183,8 @@ findPrimary = controllers.find(secCntlrList->sc_entry[0].pcid); if (findPrimary == controllers.end()) { - std::cerr << "fail to match primary controller from " - "identify sencondary cntrl list" - << '\n'; + lg2::error("fail to match primary controller from " + "identify secondary cntrl list"); status = Status::Aborting; markFunctional(false); markAvailable(false); @@ -206,9 +205,8 @@ auto findSecondary = controllers.find(secCntlrList->sc_entry[i].scid); if (findSecondary == controllers.end()) { - std::cerr << "fail to match secondary controller from " - "identify sencondary cntrl list" - << '\n'; + lg2::error("fail to match secondary controller from " + "identify secondary cntrl list"); break; } @@ -232,13 +230,12 @@ self->fillDrive(yield); self->updateVolumes(yield); self->querySupportedFormats(yield); - std::cerr << "finished NS enum" << '\n'; + lg2::info("finished NS enum"); } catch (const std::exception& e) { - std::cerr << std::format("[{}] failed starting the subsystem: {}", - self->name, e.what()) - << '\n'; + lg2::error("failed starting the subsystem: {ERROR}", "SUBSYSTEM", + self->name, "ERROR", e.what()); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -354,9 +351,8 @@ if (!posted) { - std::cerr - << "Failed to flush operations, subsystem has stalled!" - << '\n'; + lg2::error( + "Failed to flush operations, subsystem has stalled!"); } } @@ -412,8 +408,9 @@ if (ec || ctrlList.empty()) { // TODO: mark the subsystem invalid and reschedule refresh - std::cerr << "fail to scan controllers for the nvme subsystem" - << (ec ? ": " + ec.message() : "") << '\n'; + lg2::error( + "fail to scan controllers for the nvme subsystem: {ERROR}", + "ERROR", ec.message()); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -451,9 +448,9 @@ } catch (const std::exception& e) { - std::cerr << "failed to create controller: " - << std::to_string(*index) - << ", reason: " << e.what() << '\n'; + lg2::error( + "failed to create controller: {CONTROLLER}, reason: {REASON}", + "CONTROLLER", *index, "REASON", e.what()); } index++; @@ -493,8 +490,7 @@ std::span<uint8_t> data) { if (ex || data.size() < sizeof(nvme_secondary_ctrl_list)) { - std::cerr << "fail to identify secondary controller list" - << '\n'; + lg2::error("fail to identify secondary controller list"); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -506,8 +502,7 @@ if (listHdr->num == 0) { - std::cerr << "empty identify secondary controller list" - << '\n'; + lg2::error("empty identify secondary controller list"); self->status = Status::Aborting; self->markFunctional(false); self->markAvailable(false); @@ -546,8 +541,9 @@ { if (!primaryController) { - std::cerr << "dbus call for inactive NVMe subsystem " << name - << ". Returning Unavailable\n"; + lg2::error( + "dbus call for inactive NVMe subsystem {SUBSYSTEM}. Returning Unavailable", + "SUBSYSTEM", name); throw sdbusplus::xyz::openbmc_project::Common::Error::Unavailable(); } return primaryController; @@ -589,7 +585,8 @@ std::vector<thresholds::Threshold> sensorThresholds; if (!parseThresholdsFromConfig(config, sensorThresholds)) { - std::cerr << "error populating thresholds for " << *sensorName << "\n"; + lg2::error("error populating thresholds for {SENSOR}", "SENSOR", + *sensorName); throw std::runtime_error("error populating thresholds for " + *sensorName); } @@ -606,10 +603,8 @@ auto sensorBase = config.find(configInterfaceName(nvme::sensorType)); if (sensorBase == config.end()) { - std::cerr << "Warning: " << name - << ": cannot find sensor config " + - configInterfaceName(nvme::sensorType) - << '\n'; + lg2::warning("cannot find sensor config {CONFIG} for {NAME}", "CONFIG", + configInterfaceName(nvme::sensorType), "NAME", name); } else { @@ -666,8 +661,9 @@ // The device is physically absent if (error == std::errc::no_such_device) { - std::cerr << "error reading ctemp from subsystem" - << ", reason:" << error.message() << "\n"; + lg2::error( + "error reading ctemp from subsystem, reason: {ERROR}", + "ERROR", error.message()); self->markFunctional(false); self->markAvailable(false); return; @@ -675,15 +671,16 @@ // other communication errors if (error) { - std::cerr << "error reading ctemp from subsystem" - << ", reason:" << error.message() << "\n"; + lg2::error( + "error reading ctemp from subsystem, reason: {ERROR}", + "ERROR", error.message()); self->ctemp->incrementError(); return; } if (status == nullptr) { - std::cerr << "empty data returned by data fetcher" << '\n'; + lg2::error("empty data returned by data fetcher"); self->markFunctional(false); return; } @@ -694,10 +691,9 @@ ((flags & NVMeBasicIntf::StatusFlags:: NVME_MI_BASIC_SFLGS_DRIVE_FUNCTIONAL) == 0)) { - std::cerr - << self->name - << ": health poll returns drive not ready or drive not functional" - << '\n'; + lg2::error( + "{NAME}: health poll returns drive not ready or drive not functional", + "NAME", self->name); self->markFunctional(false); return; } @@ -728,8 +724,7 @@ // do not poll the health status if the subsystem is intiatilzing if (self->status == Status::Intiatilzing) { - std::cerr << "subsystem is intiatilzing, cancel the health poll" - << '\n'; + lg2::info("subsystem is initializing, cancel the health poll"); cb(std::make_error_code(std::errc::operation_canceled), nullptr); return; @@ -749,25 +744,22 @@ if (error == std::errc::operation_canceled) { - std::cerr << "processing health data has been cancelled" - << '\n'; + lg2::info("processing health data has been cancelled"); return; } if (self->status == Status::Intiatilzing) { - // on initialization, the subsystem will not update the status. - std::cerr - << "subsystem is intiatilzing, do not process the status" - << '\n'; + lg2::info( + "subsystem is initializing, do not process the status"); return; } if (error == std::errc::no_such_device) { - std::cerr << "error reading ctemp " - "from subsystem" - << ", reason:" << error.message() << "\n"; + lg2::error( + "error reading ctemp from subsystem, reason: {ERROR}", + "ERROR", error.message()); // stop the subsystem self->markFunctional(false); self->markAvailable(false); @@ -776,9 +768,9 @@ } if (error) { - std::cerr << "error reading ctemp " - "from subsystem" - << ", reason:" << error.message() << "\n"; + lg2::error( + "error reading ctemp from subsystem, reason: {ERROR}", + "ERROR", error.message()); self->ctemp->incrementError(); if (self->ctemp->inError()) { @@ -797,8 +789,8 @@ if (!df) { // stop the subsystem - std::cerr << self->name << ": health poll returns df status 0" - << '\n'; + lg2::error("{NAME}: health poll returns df status 0", "NAME", + self->name); self->markFunctional(false); return; } @@ -827,7 +819,7 @@ if (status == Status::Intiatilzing) { - std::cerr << "status init" << '\n'; + lg2::debug("status init"); auto timer = std::make_shared<boost::asio::steady_timer>( io, std::chrono::milliseconds(100)); timer->async_wait( @@ -841,7 +833,7 @@ } else { - std::cerr << "status else" << '\n'; + lg2::debug("status else"); markFunctional(false); // There's been an explicit request to stop the subsystem. If it has @@ -904,8 +896,8 @@ auto self = weak.lock(); if (!self) { - std::cerr << "createNamespace completed while nvmesensor was " - "exiting\n"; + lg2::warning( + "createNamespace completed while nvmesensor was exiting"); return; } // The NS create has completed (either successfully or not) @@ -982,8 +974,8 @@ } catch (const std::exception& e) { - std::cerr << "Unhandled error in createVolumeFinished: " << e.what() - << "\n"; + lg2::error("Unhandled error in createVolumeFinished: {ERROR}", "ERROR", + e.what()); } } @@ -1072,7 +1064,7 @@ uint16_t num = ::le16toh(list.num); if (num == NVME_ID_CTRL_LIST_MAX) { - std::cerr << "Warning: full ctrl list returned\n"; + lg2::warning("full ctrl list returned"); } for (auto i = 0; i < num; i++) @@ -1131,9 +1123,10 @@ std::set_difference(existing.begin(), existing.end(), ns.begin(), ns.end(), std::back_inserter(deletions)); - std::cerr << std::format( - "[{}] subsystem enum {} NS, {} will be added, {} will be deleted\n", - name, ns.size(), additions.size(), deletions.size()); + 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(), + "DELETIONS", deletions.size()); for (auto n : deletions) { @@ -1200,8 +1193,8 @@ { if (volPath.parent_path() != path + "/volumes") { - std::cerr << "getVolume path '" << volPath.str - << "' doesn't match parent " << path << "\n"; + lg2::error("getVolume path '{PATH}' doesn't match parent {PARENT_PATH}", + "PATH", volPath.str, "PARENT_PATH", path); return nullptr; } @@ -1210,14 +1203,14 @@ auto e = std::from_chars(id.data(), id.data() + id.size(), nsid); if (e.ptr != id.data() + id.size() || e.ec != std::errc()) { - std::cerr << "getVolume path '" << volPath.str << "' bad nsid\n"; + lg2::error("getVolume path '{PATH}' bad nsid", "PATH", volPath.str); return nullptr; } auto v = volumes.find(nsid); if (v == volumes.end()) { - std::cerr << "getVolume nsid " << nsid << " not found\n"; + lg2::error("getVolume nsid {NSID} not found", "NSID", nsid); return nullptr; } @@ -1230,7 +1223,7 @@ if (!controllers.contains(ctrlId)) { - std::cerr << "attachedVolumes bad controller " << ctrlId << '\n'; + lg2::error("attachedVolumes bad controller {CTRLID}", "CTRLID", ctrlId); return vols; } @@ -1262,7 +1255,8 @@ throw std::runtime_error(std::format("attachCtrlVolume bad ns {}", ns)); } attached[c].insert(ns); - std::cout << name << " attached insert " << c << " " << ns << "\n"; + lg2::info("{NAME} attached insert {C} {NS}", "NAME", name, "C", c, "NS", + ns); controllers[c].first->updateAssociation(); } @@ -1283,7 +1277,7 @@ throw std::runtime_error(std::format("detachCtrlVolume bad ns {}", ns)); } attached[c].erase(ns); - std::cout << name << " attached erase " << c << " " << ns << "\n"; + lg2::info("{NAME} attached erase {C} {NS}", "NAME", name, "C", c, "NS", ns); controllers[c].first->updateAssociation(); } @@ -1320,7 +1314,7 @@ { std::string errMsg = std::string("Internal error, NSID exists " + std::to_string(ns.namespaceId)); - std::cerr << errMsg << "\n"; + lg2::error("{ERROR}", "ERROR", errMsg); throw makeLibNVMeError(errMsg); } @@ -1398,15 +1392,15 @@ throw std::runtime_error(std::format("{}: Bad nlbaf {}", name, nlbaf)); } - std::cerr << name << ": Got nlbaf " << nlbaf << "\n"; + lg2::debug("{NAME}: Got nlbaf {NLBAF}", "NAME", name, "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); - std::cerr << name << ": lbaf " << i << " blocksize " << blockSize - << "\n"; + lg2::debug("{NAME}: lbaf {LBAF} blocksize {BLOCKSIZE}", "NAME", name, + "LBAF", i, "BLOCKSIZE", blockSize); formats.push_back({.index = i, .blockSize = blockSize, .metadataSize = metadataSize, @@ -1476,8 +1470,8 @@ { if (status != Status::Start) { - std::cerr << "Subsystem not in Start state, have " - << static_cast<int>(status) << '\n'; + lg2::error("Subsystem not in Start state, have {STATUS}", "STATUS", + static_cast<int>(status)); return; }
diff --git a/src/NVMeUtil.hpp b/src/NVMeUtil.hpp index bc013e5..0f80f65 100644 --- a/src/NVMeUtil.hpp +++ b/src/NVMeUtil.hpp
@@ -1,9 +1,9 @@ #pragma once #include <boost/algorithm/string/join.hpp> #include <boost/asio.hpp> +#include <phosphor-logging/lg2.hpp> #include <filesystem> -#include <iostream> #include <optional> #include <system_error> @@ -36,7 +36,8 @@ size_t dash = rootName.find('-'); if (dash == std::string::npos) { - std::cerr << "Error finding root bus for " << rootName << "\n"; + lg2::error("Error finding root bus for {ROOT_NAME}", "ROOT_NAME", + rootName); return std::nullopt; } @@ -161,12 +162,12 @@ { if (errorCode == boost::asio::error::operation_aborted || timer.expired()) { - std::cerr << "poll loop has been cancelled\n"; + lg2::info("poll loop has been cancelled"); return; } if (errorCode) { - std::cerr << errorCode.message() << "\n"; + lg2::error("{ERROR}", "ERROR", errorCode.message()); ::pollCtemp(std::move(timer), delay, dataFetcher, dataProcessor); return; }