Refactor logging, improve error handling workflow, clang-format. (#3385)

include/util/exception_utils.hpp

@@ -0,0 +1,15 @@
+#ifndef SOURCE_MACROS_HPP
+#define SOURCE_MACROS_HPP
+#include <cstring>
+
+// Helper macros, don't use these ones
+// STRIP the OSRM_PROJECT_DIR from the front of a filename.  Expected to come
+// from CMake's CURRENT_SOURCE_DIR, which doesn't have a trailing /, hence the +1
+#define _PROJECT_RELATIVE_PATH(x) std::string(x).substr(strlen(OSRM_PROJECT_DIR) + 1)
+// Return the path of a file, relative to the OSRM_PROJECT_DIR
+#define _OSRM_SOURCE_FILE _PROJECT_RELATIVE_PATH(__FILE__)
+
+// This is the macro to use
+#define SOURCE_REF std::string(" (at ") + _OSRM_SOURCE_FILE + ":" + std::to_string(__LINE__) + ")"
+
+#endif // SOURCE_MACROS_HPP

include/util/fingerprint_impl.hpp.in

@@ -1,4 +1,5 @@
 #include "util/exception.hpp"
+#include "util/exception_utils.hpp"
 
 #include <boost/uuid/name_generator.hpp>
 #include <boost/uuid/uuid_generators.hpp>
@@ -57,7 +58,7 @@ bool FingerPrint::TestGraphUtil(const FingerPrint &other) const
 {
     if (!IsMagicNumberOK(other))
     {
-        throw exception("hsgr input file misses magic number. Check or reprocess the file");
+        throw exception(std::string("hsgr input file misses magic number. Check or reprocess the file") + SOURCE_REF);
     }
     return std::equal(md5_graph, md5_graph + 32, other.md5_graph);
 }
@@ -66,7 +67,7 @@ bool FingerPrint::TestContractor(const FingerPrint &other) const
 {
     if (!IsMagicNumberOK(other))
     {
-        throw exception("osrm input file misses magic number. Check or reprocess the file");
+        throw exception(std::string("osrm input file misses magic number. Check or reprocess the file") + SOURCE_REF);
     }
     return std::equal(md5_prepare, md5_prepare + 32, other.md5_prepare);
 }
@@ -75,7 +76,7 @@ bool FingerPrint::TestRTree(const FingerPrint &other) const
 {
     if (!IsMagicNumberOK(other))
     {
-        throw exception("r-tree input file misses magic number. Check or reprocess the file");
+        throw exception(std::string("r-tree input file misses magic number. Check or reprocess the file") + SOURCE_REF);
     }
     return std::equal(md5_tree, md5_tree + 32, other.md5_tree);
 }
@@ -84,7 +85,7 @@ bool FingerPrint::TestQueryObjects(const FingerPrint &other) const
 {
     if (!IsMagicNumberOK(other))
     {
-        throw exception("missing magic number. Check or reprocess the file");
+        throw exception(std::string("missing magic number. Check or reprocess the file") + SOURCE_REF);
     }
     return std::equal(md5_objects, md5_objects + 32, other.md5_objects);
 }

include/util/geojson_debug_logger.hpp

@@ -7,7 +7,7 @@
 
 #include "util/json_container.hpp"
 #include "util/json_renderer.hpp"
-#include "util/simple_logger.hpp"
+#include "util/log.hpp"
 
 namespace osrm
 {
@@ -92,7 +92,7 @@ class GeojsonLogger
         // out on log output. Such a sad life
         if (ofs.is_open())
         {
-            util::SimpleLogger().Write(logWARNING)
+            util::Log(logWARNING)
                 << "Overwriting " << logfile
                 << ". Is this desired behaviour? If this message occurs more than once rethink the "
                    "location of your Logger Guard.";

include/util/graph_loader.hpp

@@ -8,7 +8,7 @@
 #include "storage/io.hpp"
 #include "util/exception.hpp"
 #include "util/fingerprint.hpp"
-#include "util/simple_logger.hpp"
+#include "util/log.hpp"
 #include "util/typedefs.hpp"
 
 #include <boost/assert.hpp>
@@ -60,7 +60,7 @@ NodeID loadNodesFromFile(storage::io::FileReader &file_reader,
                          std::vector<extractor::QueryNode> &node_array)
 {
     NodeID number_of_nodes = file_reader.ReadElementCount32();
-    SimpleLogger().Write() << "Importing number_of_nodes new = " << number_of_nodes << " nodes ";
+    Log() << "Importing number_of_nodes new = " << number_of_nodes << " nodes ";
 
     node_array.resize(number_of_nodes);
 
@@ -99,14 +99,14 @@ inline NodeID loadEdgesFromFile(storage::io::FileReader &file_reader,
     BOOST_ASSERT(sizeof(EdgeID) == sizeof(number_of_edges));
 
     edge_list.resize(number_of_edges);
-    SimpleLogger().Write() << " and " << number_of_edges << " edges ";
+    Log() << " and " << number_of_edges << " edges ";
 
     file_reader.ReadInto(edge_list.data(), number_of_edges);
 
     BOOST_ASSERT(edge_list.size() > 0);
 
 #ifndef NDEBUG
-    SimpleLogger().Write() << "Validating loaded edges...";
+    Log() << "Validating loaded edges...";
     tbb::parallel_sort(
         edge_list.begin(),
         edge_list.end(),
@@ -129,7 +129,7 @@ inline NodeID loadEdgesFromFile(storage::io::FileReader &file_reader,
     }
 #endif
 
-    SimpleLogger().Write() << "Graph loaded ok and has " << edge_list.size() << " edges";
+    Log() << "Graph loaded ok and has " << edge_list.size() << " edges";
 
     return number_of_edges;
 }

include/util/guidance/toolkit.hpp

@@ -11,8 +11,8 @@
 #include "util/attributes.hpp"
 #include "util/guidance/bearing_class.hpp"
 #include "util/guidance/entry_class.hpp"
+#include "util/log.hpp"
 #include "util/name_table.hpp"
-#include "util/simple_logger.hpp"
 
 #include <algorithm>
 #include <string>

include/util/io.hpp

@@ -1,7 +1,7 @@
 #ifndef OSRM_INCLUDE_UTIL_IO_HPP_
 #define OSRM_INCLUDE_UTIL_IO_HPP_
 
-#include "util/simple_logger.hpp"
+#include "util/log.hpp"
 
 #include <boost/filesystem.hpp>
 #include <boost/numeric/conversion/cast.hpp>
@@ -125,9 +125,10 @@ void deserializeAdjacencyArray(const std::string &filename,
 
     // offsets have to match up with the size of the data
     if (offsets.empty() || (offsets.back() != boost::numeric_cast<std::uint32_t>(data.size())))
-        throw util::exception("Error in " + filename + (offsets.empty()
-                                                            ? "Offsets are empty"
-                                                            : "Offset and data size do not match"));
+        throw util::exception(
+            "Error in " + filename +
+            (offsets.empty() ? "Offsets are empty" : "Offset and data size do not match") +
+            SOURCE_REF);
 }
 
 inline bool serializeFlags(const boost::filesystem::path &path, const std::vector<bool> &flags)
@@ -153,8 +154,7 @@ inline bool serializeFlags(const boost::filesystem::path &path, const std::vecto
         ++chunk_count;
         flag_stream.write(reinterpret_cast<const char *>(&chunk), sizeof(chunk));
     }
-    SimpleLogger().Write() << "Wrote " << number_of_bits << " bits in " << chunk_count
-                           << " chunks (Flags).";
+    Log() << "Wrote " << number_of_bits << " bits in " << chunk_count << " chunks (Flags).";
     return static_cast<bool>(flag_stream);
 }
 

include/util/log.hpp

@@ -0,0 +1,70 @@
+#ifndef LOG_HPP
+#define LOG_HPP
+
+#include <atomic>
+#include <mutex>
+#include <sstream>
+
+enum LogLevel
+{
+    logINFO,
+    logWARNING,
+    logERROR,
+    logDEBUG
+};
+
+namespace osrm
+{
+namespace util
+{
+
+class LogPolicy
+{
+  public:
+    void Unmute();
+
+    void Mute();
+
+    bool IsMute() const;
+
+    static LogPolicy &GetInstance();
+
+    LogPolicy(const LogPolicy &) = delete;
+    LogPolicy &operator=(const LogPolicy &) = delete;
+
+  private:
+    LogPolicy() : m_is_mute(true) {}
+    std::atomic<bool> m_is_mute;
+};
+
+class Log
+{
+  public:
+    Log(LogLevel level_ = logINFO);
+    Log(LogLevel level_, std::ostream &ostream);
+
+    virtual ~Log();
+    std::mutex &get_mutex();
+
+    template <typename T> inline std::ostream &operator<<(const T &data) { return stream << data; }
+
+  protected:
+    LogLevel level;
+    std::ostringstream buffer;
+    std::ostream &stream;
+};
+
+/**
+ * Modified logger - this one doesn't buffer - it writes directly to stdout,
+ * and the final newline is only printed when the object is destructed.
+ * Useful for logging situations where you don't want to newline right away
+ */
+class UnbufferedLog : public Log
+{
+  public:
+    UnbufferedLog(LogLevel level_ = logINFO);
+};
+}
+}
+
+#endif /* LOG_HPP */

include/util/percent.hpp

@@ -5,6 +5,7 @@
 #include <iostream>
 
 #include "util/isatty.hpp"
+#include "util/log.hpp"
 
 namespace osrm
 {
@@ -13,8 +14,13 @@ namespace util
 
 class Percent
 {
+    Log &log;
+
   public:
-    explicit Percent(unsigned max_value, unsigned step = 5) { Reinit(max_value, step); }
+    explicit Percent(Log &log_, unsigned max_value, unsigned step = 5) : log{log_}
+    {
+        Reinit(max_value, step);
+    }
 
     // Reinitializes
     void Reinit(unsigned max_value, unsigned step = 5)
@@ -36,7 +42,7 @@ class Percent
             PrintPercent(current_value / static_cast<double>(m_max_value) * 100.);
         }
         if (current_value + 1 == m_max_value)
-            std::cout << " 100%" << std::endl;
+            log << " 100%";
     }
 
     void PrintIncrement()
@@ -67,19 +73,17 @@ class Percent
             m_last_percent += m_step;
             if (m_last_percent % 10 == 0)
             {
-                std::cout << " " << m_last_percent << "% ";
+                log << " " << m_last_percent << "% ";
             }
             else
             {
-                std::cout << ".";
+                log << ".";
             }
 
             // When not on a TTY, print newlines after each progress indicator so
             // so that progress is visible to line-buffered logging systems
             if (!IsStdoutATTY())
-                std::cout << std::endl;
-
-            std::cout.flush();
+                log << "" << std::endl;
         }
     }
 };

include/util/shared_memory_vector_wrapper.hpp

@@ -3,7 +3,7 @@
 
 #include <boost/assert.hpp>
 
-#include "util/simple_logger.hpp"
+#include "util/log.hpp"
 
 #include <cstddef>
 

include/util/simple_logger.hpp

@@ -1,55 +0,0 @@
-#ifndef SIMPLE_LOGGER_HPP
-#define SIMPLE_LOGGER_HPP
-
-#include <atomic>
-#include <mutex>
-#include <sstream>
-
-enum LogLevel
-{
-    logINFO,
-    logWARNING,
-    logDEBUG
-};
-
-namespace osrm
-{
-namespace util
-{
-
-class LogPolicy
-{
-  public:
-    void Unmute();
-
-    void Mute();
-
-    bool IsMute() const;
-
-    static LogPolicy &GetInstance();
-
-    LogPolicy(const LogPolicy &) = delete;
-    LogPolicy &operator=(const LogPolicy &) = delete;
-
-  private:
-    LogPolicy() : m_is_mute(true) {}
-    std::atomic<bool> m_is_mute;
-};
-
-class SimpleLogger
-{
-  public:
-    SimpleLogger();
-
-    virtual ~SimpleLogger();
-    std::mutex &get_mutex();
-    std::ostringstream &Write(LogLevel l = logINFO) noexcept;
-
-  private:
-    std::ostringstream os;
-    LogLevel level;
-};
-}
-}
-
-#endif /* SIMPLE_LOGGER_HPP */

include/util/static_rtree.hpp

@@ -378,7 +378,8 @@ class StaticRTree
         catch (const std::exception &exc)
         {
             throw exception(boost::str(boost::format("Leaf file %1% mapping failed: %2%") %
-                                       leaf_file % exc.what()));
+                                       leaf_file % exc.what()) +
+                            SOURCE_REF);
         }
     }