UNDO getMxId() and extra debug

Author: diablodale

include/depthai/xlink/XLinkConnection.hpp

@@ -153,6 +153,11 @@ class XLinkConnection {
     constexpr static std::chrono::milliseconds WAIT_FOR_BOOTUP_TIMEOUT{15000};
     constexpr static std::chrono::milliseconds WAIT_FOR_CONNECT_TIMEOUT{5000};
     constexpr static std::chrono::milliseconds POLLING_DELAY_TIME{10};
+
+  public:
+    std::string getMxId() const {
+        return deviceInfo.getMxId();
+    }
 };
 
 }  // namespace dai

include/depthai/xlink/XLinkStream.hpp

@@ -77,6 +77,9 @@ class XLinkStream {
     [[deprecated]] void readRawRelease();
 
     streamId_t getStreamId() const;
+    std::string getMxId() const {
+        return connection->getMxId();
+    }
 };
 
 struct XLinkError : public std::runtime_error {

src/device/DeviceBase.cpp

@@ -487,7 +487,7 @@ void DeviceBase::close() {
 void DeviceBase::closeImpl() {
     using namespace std::chrono;
     auto t1 = steady_clock::now();
-    pimpl->logger.debug("Device about to be closed...");
+    pimpl->logger.warn("Device mxid({}) about to be closed...", deviceInfo.getMxId());
 
     // Close connection first; causes Xlink internal calls to unblock semaphore waits and
     // return error codes, which then allows queues to unblock
@@ -513,7 +513,7 @@ void DeviceBase::closeImpl() {
     // At the end stop the monitor thread
     if(monitorThread.joinable()) monitorThread.join();
 
-    pimpl->logger.debug("Device closed, {}", duration_cast<milliseconds>(steady_clock::now() - t1).count());
+    pimpl->logger.warn("Device mxid({}) closed, {}", deviceInfo.getMxId(), duration_cast<milliseconds>(steady_clock::now() - t1).count());
 }
 
 // This function is thread-unsafe. The idea of "isClosed" is ephemerial and
@@ -608,7 +608,7 @@ void DeviceBase::init2(Config cfg, const dai::Path& pathToMvcmd, tl::optional<co
             pimpl->logger.debug("Found an actual device by given DeviceInfo: {}", deviceInfo.toString());
         } else {
             deviceInfo.state = X_LINK_ANY_STATE;
-            pimpl->logger.debug("Searched, but no actual device found by given DeviceInfo");
+            pimpl->logger.warn("Searched, but no actual device found by given DeviceInfo");
         }
     }
 
@@ -693,14 +693,14 @@ void DeviceBase::init2(Config cfg, const dai::Path& pathToMvcmd, tl::optional<co
                 auto t1 = steady_clock::now();
                 bl.bootMemory(fwWithConfig);
                 auto t2 = steady_clock::now();
-                pimpl->logger.debug("Booting FW with Bootloader. Version {}, Time taken: {}", version.toString(), duration_cast<milliseconds>(t2 - t1));
+                pimpl->logger.warn("Booting FW with Bootloader. Version {}, Time taken: {}", version.toString(), duration_cast<milliseconds>(t2 - t1));
 
                 // After that the state will be expectedBootState
                 deviceInfo.state = expectedBootState;
             } else {
                 // Boot into USB ROM BOOTLOADER
                 bl.bootUsbRomBootloader();
-                pimpl->logger.debug("Booting FW by jumping to USB ROM Bootloader first. Bootloader Version {}", version.toString());
+                pimpl->logger.warn("Booting FW by jumping to USB ROM Bootloader first. Bootloader Version {}", version.toString());
 
                 // After that the state will be UNBOOTED
                 deviceInfo.state = X_LINK_UNBOOTED;
@@ -742,7 +742,7 @@ void DeviceBase::init2(Config cfg, const dai::Path& pathToMvcmd, tl::optional<co
                 return rpcStream->read();
             } catch(const std::exception& e) {
                 // If any exception is thrown, log it and rethrow
-                implLogger.debug("RPC error: {}", e.what());
+                implLogger.warn("RPC mxid({}) error: {}", rpcStream->getMxId(), e.what());
                 throw std::system_error(std::make_error_code(std::errc::io_error), "Device already closed or disconnected");
             }
         });

src/xlink/XLinkConnection.cpp

@@ -311,7 +311,7 @@ void XLinkConnection::close() {
 
         const auto ret = XLinkResetRemoteTimeout(deviceLinkId, static_cast<int>(std::chrono::duration_cast<std::chrono::milliseconds>(RESET_TIMEOUT).count()));
         if(ret != X_LINK_SUCCESS) {
-            logger::debug("XLinkResetRemoteTimeout({}) returned: {}", previousLinkId, XLinkErrorToStr(ret));
+            logger::warn("XLinkResetRemoteTimeout({}) mxid({}) returned: {}", previousLinkId, deviceInfo.getMxId(), XLinkErrorToStr(ret));
         }
 
         deviceLinkId = -1;
@@ -331,20 +331,24 @@ void XLinkConnection::close() {
                 }
                 if(steady_clock::now() - t1 >= BOOTUP_SEARCH) {
                     if(found) {
-                        logger::debug("XLinkResetRemoteTimeout({}) post-reboot({}s) unusable state {}",
+                        logger::warn("XLinkResetRemoteTimeout({}) mxid({}) post-reboot({}s) unusable state {}",
                                       previousLinkId,
+                                      deviceInfo.getMxId(),
                                       BOOTUP_SEARCH.count(),
                                       rebootingDeviceInfo.toString());
                     } else {
-                        logger::debug("XLinkResetRemoteTimeout({}) post-reboot({}s) can't find device", previousLinkId, BOOTUP_SEARCH.count());
+                        logger::warn("XLinkResetRemoteTimeout({}) mxid({}) post-reboot({}s) can't find device",
+                                      previousLinkId,
+                                      deviceInfo.getMxId(),
+                                      BOOTUP_SEARCH.count());
                     }
                     break;
                 }
                 std::this_thread::sleep_for(POLLING_DELAY_TIME);
             };
         }
 
-        logger::debug("XLinkResetRemoteTimeout({})", previousLinkId);
+        logger::debug("XLinkResetRemoteTimeout({}) mxid({})", previousLinkId, deviceInfo.getMxId());
     }
 }
 

tests/src/multiple_devices_test.cpp

@@ -101,7 +101,10 @@ TEST_CASE("Multiple devices with 50 messages each") {
     }
 
     REQUIRE(finished);
-}
+} // the first device in vector cleanly destructs, but the 2nd and 3rd always post-reboot 5s can't find device
+  // curious as sometimes the found devices are in a different order but on destruct its always the 2nd and 3rd
+  // c++ std has no rule or guarantee for the order of vector element destruction -- fact that it differs in std lib implementations
+  // http://www7.open-std.org/JTC1/SC22/WG21/docs/papers/2017/p0752r0.md
 
 TEST_CASE("Multiple devices created and destroyed in parallel") {
     constexpr auto TEST_TIMEOUT = 30s;