Split log into separate logs per stream to avoid synchronization

issues when running multiple streams or container in parallel

src/Container.cpp

@@ -60,8 +60,12 @@ Container::Container(const fs::path& aCfbfContainer, ParserConfig aCfg) :
     const fs::path extractTo = fs::temp_directory_path() / "OpenOrCadParser" / uuid;
     mCtx.mExtractedCfbfPath = extractContainer(aCfbfContainer, extractTo);
 
-    spdlog::debug("Using parser configuration:");
-    spdlog::debug(to_string(mCfg));
+    // @todo This is a hack, since mExtractedCfbfPath is not available at construction of the context
+    const fs::path logPath = extractTo / "logs" / "OpenOrCadParser.log";
+    mCtx.configureLogger(logPath);
+
+    mCtx.mLogger.debug("Using parser configuration:");
+    mCtx.mLogger.debug(to_string(mCfg));
 }
 
 
@@ -72,7 +76,7 @@ Container::~Container()
         // Remove temporary extracted files
         fs::remove_all(mCtx.mExtractedCfbfPath.parent_path());
 
-        spdlog::debug("Deleted CFBF container at `{}`", mCtx.mExtractedCfbfPath.string());
+        mCtx.mLogger.debug("Deleted CFBF container at `{}`", mCtx.mExtractedCfbfPath.string());
     }
 }
 
@@ -125,9 +129,9 @@ std::vector<std::vector<ElementType*>> equallyDistributeElementsIntoLists(
  */
 void Container::parseLibrary()
 {
-    spdlog::info("Using {} threads", mCtx.mCfg.mThreadCount);
+    mCtx.mLogger.info("Using {} threads", mCtx.mCfg.mThreadCount);
 
-    spdlog::info("Start parsing library located at {}", mCtx.mExtractedCfbfPath.string());
+    mCtx.mLogger.info("Start parsing library located at {}", mCtx.mExtractedCfbfPath.string());
 
     // Parse all streams in the container i.e. files in the file system
     for(const auto& dir_entry : fs::recursive_directory_iterator(mCtx.mExtractedCfbfPath))
@@ -155,14 +159,14 @@ void Container::parseLibrary()
 
     for(std::size_t i{0U}; i < threadJobList.size(); ++i)
     {
-        spdlog::info("Assigning thread {} with the following {}/{} jobs:",
+        mCtx.mLogger.info("Assigning thread {} with the following {}/{} jobs:",
             i, threadJobList.at(i).size(), mFileCtr);
 
         const auto& threadJobs = threadJobList.at(i);
 
         for(const auto& job : threadJobs)
         {
-            spdlog::debug("    {}", (*job)->mCtx.mInputStream.string());
+            mCtx.mLogger.debug("    {}", (*job)->mCtx.mInputStream.string());
         }
     }
 
@@ -194,9 +198,9 @@ void Container::parseLibrary()
     errCtrStr = fmt::format((mFileErrCtr == 0u) ? fg(fmt::color::green) : fg(fmt::color::crimson),
         errCtrStr);
 
-    spdlog::info(errCtrStr);
+    mCtx.mLogger.info(errCtrStr);
 
-    // spdlog::info(to_string(mLibrary));
+    // mCtx.mLogger.info(to_string(mLibrary));
 }
 
 
@@ -208,17 +212,17 @@ void Container::exceptionHandling()
     }
     catch(const std::exception& e)
     {
-        spdlog::error(fmt::format(fg(fmt::color::crimson), "--------ERROR REPORT--------"));
-        spdlog::error(fmt::format(fg(fmt::color::crimson), "Input Container: {}", mCtx.mInputCfbfFile.string()));
+        mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "--------ERROR REPORT--------"));
+        mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "Input Container: {}", mCtx.mInputCfbfFile.string()));
         // @todo
-        // spdlog::error(fmt::format(fg(fmt::color::crimson), "Current File:    {}", mCtx.mInputStream.string()));
-        // spdlog::error(fmt::format(fg(fmt::color::crimson), mCtx.mDs.getCurrentOffsetStrMsg()));
-        spdlog::error(fmt::format(fg(fmt::color::crimson), "\nError Message: {}\n\n", e.what()));
+        // mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "Current File:    {}", mCtx.mInputStream.string()));
+        // mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), mCtx.mDs.getCurrentOffsetStrMsg()));
+        mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "\nError Message: {}\n\n", e.what()));
     }
     catch(...)
     {
-        spdlog::error(fmt::format(fg(fmt::color::crimson), "--------ERROR REPORT--------"));
-        spdlog::error(fmt::format(fg(fmt::color::crimson), "Unknown exception caught!\n"));
+        mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "--------ERROR REPORT--------"));
+        mCtx.mLogger.error(fmt::format(fg(fmt::color::crimson), "Unknown exception caught!\n"));
     }
 }
 

src/ContainerContext.hpp

@@ -11,6 +11,7 @@
 #include <vector>
 
 #include <fmt/core.h>
+#include <spdlog/sinks/basic_file_sink.h>
 #include <spdlog/spdlog.h>
 
 #include "General.hpp"
@@ -47,6 +48,20 @@ class CfbfStreamLocation
         mStreamLocation = std::move(streamLocation);
     }
 
+    fs::path get_relative_fs_path() const
+    {
+        const auto vec = get_vector();
+
+        fs::path fsPath{};
+
+        for(const auto& part : vec)
+        {
+            fsPath = fsPath / part;
+        }
+
+        return fsPath;
+    }
+
     const std::vector<std::string>& get_vector() const
     {
         return mStreamLocation;
@@ -154,22 +169,44 @@ class ContainerContext
 public:
 
     ContainerContext(const fs::path& aInputCfbfFile,
-        const fs::path& aExtractedCfbfPath, ParserConfig aCfg, Container& aContainer) : mContainer{aContainer}
+        const fs::path& aExtractedCfbfPath, ParserConfig aCfg, Container& aContainer) : mContainer{aContainer},
+            mLogger{"tmp"}
     {
         mInputCfbfFile = aInputCfbfFile;
         mExtractedCfbfPath = aExtractedCfbfPath;
         mCfg = aCfg;
         mFileFormatVersion = FileFormatVersion::C;
         mFileType = FileType::Library;
+        mLogLevel = spdlog::level::trace;
+
+        const fs::path logPath = mExtractedCfbfPath / "logs" / "OpenOrCadParser.log";
+        configureLogger(logPath);
     }
 
-    ContainerContext(const ContainerContext& aCtx) : mContainer{aCtx.mContainer}
+    ContainerContext(const ContainerContext& aCtx) : mContainer{aCtx.mContainer}, mLogger{"tmp"}
     {
         mInputCfbfFile = aCtx.mInputCfbfFile;
         mExtractedCfbfPath = aCtx.mExtractedCfbfPath;
         mCfg = aCtx.mCfg;
         mFileFormatVersion = aCtx.mFileFormatVersion;
         mFileType = aCtx.mFileType;
+        mLogLevel = aCtx.mLogLevel;
+    }
+
+    void configureLogger(const fs::path& aLogPath)
+    {
+        if(aLogPath.has_parent_path())
+        {
+            fs::create_directories(aLogPath.parent_path());
+        }
+
+        auto file_sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(aLogPath);
+        mLogger = spdlog::logger{"file logger", {file_sink}};
+        mLogger.set_pattern("[%^%l%$] %v");
+        mLogger.set_level(mLogLevel);
+
+        mLogger.info("Created log file at {}", aLogPath.string());
+        spdlog::info("Created log file at {}", aLogPath.string());
     }
 
     Container& mContainer;
@@ -181,6 +218,9 @@ class ContainerContext
 
     FileFormatVersion mFileFormatVersion;
     FileType mFileType;
+
+    spdlog::level::level_enum mLogLevel;
+    spdlog::logger mLogger;
 };
 
 

src/DataStream.cpp

@@ -8,6 +8,7 @@
 
 #include "DataStream.hpp"
 #include "General.hpp"
+#include "StreamContext.hpp"
 
 
 void DataStream::discardBytes(size_t aLen)
@@ -58,7 +59,7 @@ std::string DataStream::readStringZeroTerm()
         const std::string msg = fmt::format("Loop canceled because the string is unexpectedly large.\n"
             "More than {} characters! The following string was read until now:\n{}", max_chars, str);
 
-        spdlog::error(msg);
+        mCtx.mLogger.error(msg);
 
         throw std::runtime_error(msg);
     }
@@ -89,7 +90,7 @@ std::string DataStream::readStringLenTerm()
         {
             const std::string msg = "Didn't expect null byte within string!";
 
-            spdlog::error(msg);
+            mCtx.mLogger.error(msg);
 
             throw std::runtime_error(msg);
         }
@@ -103,7 +104,7 @@ std::string DataStream::readStringLenTerm()
         const std::string msg = "Loop cancled because the string is unexpectedly large. More than "
                                  + std::to_string(max_chars) + " characters!";
 
-        spdlog::error(msg);
+        mCtx.mLogger.error(msg);
 
         throw std::runtime_error(msg);
     }
@@ -126,7 +127,7 @@ std::string DataStream::readStringLenZeroTerm()
                                  + ") does not match the preceding length ("
                                  + std::to_string(len) + ") definition!";
 
-        spdlog::error(msg);
+        mCtx.mLogger.error(msg);
 
         throw std::runtime_error(msg);
     }
@@ -143,8 +144,8 @@ void DataStream::printUnknownData(size_t aLen, const std::string& aComment)
 
     if(aLen > 0u)
     {
-        spdlog::debug(aComment);
-        spdlog::debug(dataToStr(data));
+        mCtx.mLogger.debug(aComment);
+        mCtx.mLogger.debug(dataToStr(data));
     }
 }
 
@@ -160,7 +161,7 @@ void DataStream::padRest(size_t aStartOffset, size_t aBlockSize, bool aPadIsZero
                                  + " bytes but should have only been "
                                  + std::to_string(aBlockSize) + "!";
 
-        spdlog::debug(msg);
+        mCtx.mLogger.debug(msg);
 
         throw std::runtime_error(msg);
     }
@@ -177,7 +178,7 @@ void DataStream::padRest(size_t aStartOffset, size_t aBlockSize, bool aPadIsZero
             {
                 const std::string msg = "Padding byte is expected to be 0x00!";
 
-                spdlog::error(msg);
+                mCtx.mLogger.error(msg);
 
                 throw std::runtime_error(msg);
             }
@@ -199,7 +200,7 @@ std::string DataStream::getCurrentOffsetStrMsg()
 
 void DataStream::printData(const std::vector<uint8_t>& aData)
 {
-    spdlog::info(dataToStr(aData));
+    mCtx.mLogger.info(dataToStr(aData));
 }
 
 
@@ -272,7 +273,7 @@ void DataStream::assumeData(const std::vector<uint8_t>& aExpectedData, const std
             + "Expected:\n" + dataToStr(aExpectedData) +
             + "but got:\n" + dataToStr(data);
 
-        spdlog::debug(msg);
+        mCtx.mLogger.debug(msg);
 
         throw std::runtime_error(msg);
     }

src/DataStream.hpp

@@ -21,6 +21,7 @@
 
 class FutureDataLst;
 class Record;
+class StreamContext;
 
 
 namespace fs = std::filesystem;
@@ -30,10 +31,10 @@ class DataStream : public std::ifstream
 {
 public:
 
-    DataStream() : std::ifstream{}
-    { }
+    // DataStream() : std::ifstream{}
+    // { }
 
-    DataStream(const fs::path& aFile) : std::ifstream{aFile, std::ifstream::binary}
+    DataStream(const fs::path& aFile, StreamContext& aCtx) : std::ifstream{aFile, std::ifstream::binary}, mCtx{aCtx}
     { }
 
     // Checks whether the stream has reached the end of the file.
@@ -215,6 +216,8 @@ class DataStream : public std::ifstream
     std::string dataToStr(const std::vector<uint8_t>& aData);
 
     void assumeData(const std::vector<uint8_t>& aExpectedData, const std::string& aComment = "");
+
+    StreamContext& mCtx;
 };
 
 

src/FutureData.hpp

@@ -77,7 +77,7 @@ class FutureDataLst : public std::vector<FutureData>
 
     std::optional<FutureData> getByStartOffset(std::size_t aAbsStartOffset) const
     {
-        spdlog::debug("Searching for StartOffset 0x{:08x}", aAbsStartOffset);
+        mCtx.get().mLogger.debug("Searching for StartOffset 0x{:08x}", aAbsStartOffset);
 
         const auto cmp = [&aAbsStartOffset] (FutureData aFutureData) -> bool
             { return aFutureData.getStartOffset() == aAbsStartOffset; };
@@ -94,7 +94,7 @@ class FutureDataLst : public std::vector<FutureData>
 
     std::optional<FutureData> getByStopOffset(std::size_t aAbsStopOffset) const
     {
-        spdlog::debug("Searching for StopOffset 0x{:08x}", aAbsStopOffset);
+        mCtx.get().mLogger.debug("Searching for StopOffset 0x{:08x}", aAbsStopOffset);
 
         const auto cmp = [&aAbsStopOffset] (FutureData aFutureData) -> bool
             { return aFutureData.getStopOffset() == aAbsStopOffset; };
@@ -159,14 +159,14 @@ class FutureDataLst : public std::vector<FutureData>
                 const std::string msg = fmt::format("{}: Checkpoint position at 0x{:08x} is duplicated",
                     getMethodName(this, __func__), currOffset);
 
-                spdlog::error(msg);
+                mCtx.get().mLogger.error(msg);
                 throw std::runtime_error(msg);
             }
             else
             {
                 futureData.setParsed(true);
 
-                spdlog::debug("{}: Checkpoint at 0x{:08x} was successful",
+                mCtx.get().mLogger.debug("{}: Checkpoint at 0x{:08x} was successful",
                     getMethodName(this, __func__), currOffset);
             }
         }
@@ -177,11 +177,11 @@ class FutureDataLst : public std::vector<FutureData>
                 const std::string msg = fmt::format("{}: Checkpoint position at 0x{:08x} is incorrect",
                     getMethodName(this, __func__), currOffset);
 
-                spdlog::error(msg);
+                mCtx.get().mLogger.error(msg);
                 throw std::runtime_error(msg);
             }
 
-            spdlog::trace("{}: Checkpoint at 0x{:08x} was not found",
+            mCtx.get().mLogger.trace("{}: Checkpoint at 0x{:08x} was not found",
                 getMethodName(this, __func__), currOffset);
         }
     }
@@ -196,7 +196,7 @@ class FutureDataLst : public std::vector<FutureData>
             {
                 checkpoint_missing = true;
 
-                spdlog::debug("{}: Checkpoint missing for 0x{:08x} -> 0x{:08x}",
+                mCtx.get().mLogger.debug("{}: Checkpoint missing for 0x{:08x} -> 0x{:08x}",
                     getMethodName(this, __func__),
                     data.getStartOffset(), data.getStopOffset());
             }
@@ -207,7 +207,7 @@ class FutureDataLst : public std::vector<FutureData>
             const std::string msg = fmt::format("{}: Check your code for missing checkpoints!\n{}",
                 getMethodName(this, __func__), string());
 
-            spdlog::debug(msg);
+            mCtx.get().mLogger.debug(msg);
             throw std::runtime_error(msg);
         }
     }
@@ -266,14 +266,14 @@ class FutureDataLst : public std::vector<FutureData>
         }
         else
         {
-            spdlog::debug("{}: Did not find any future data following current offset 0x{:08x}",
+            mCtx.get().mLogger.debug("{}: Did not find any future data following current offset 0x{:08x}",
                 getMethodName(this, __func__), curPos);
         }
     }
 
     void readRestOfStructure()
     {
-        spdlog::trace(string());
+        mCtx.get().mLogger.trace(string());
 
         // We don't know anything about the
         // structure, therefore do nothing
@@ -314,7 +314,7 @@ class FutureDataLst : public std::vector<FutureData>
                 " Expected it to end at 0x{:08x} but ended at 0x{:08x}. Too large by {} Byte.",
                 getMethodName(this, __func__), endPos, curPos, std::abs(byteDiff));
 
-            spdlog::debug(msg);
+            mCtx.get().mLogger.debug(msg);
             throw std::runtime_error(msg);
         }
     }