Merge pull request #758 from AntelopeIO/huangminghuang/gelf-logging

move gelf logging to another thread

libraries/libfc/include/fc/log/appender.hpp

@@ -36,7 +36,7 @@ namespace fc {
       public:
          typedef std::shared_ptr<appender> ptr;
 
-         virtual void initialize( boost::asio::io_service& io_service ) = 0;
+         virtual void initialize() = 0;
          virtual void log( const log_message& m ) = 0;
    };
 }

libraries/libfc/include/fc/log/console_appender.hpp

@@ -3,12 +3,12 @@
 #include <fc/log/logger.hpp>
 #include <vector>
 
-namespace fc 
+namespace fc
 {
-   class console_appender final : public appender 
+   class console_appender final : public appender
    {
        public:
-            struct color 
+            struct color
             {
                 enum type {
                    red,
@@ -24,17 +24,17 @@ namespace fc
 
             struct stream { enum type { std_out, std_error }; };
 
-            struct level_color 
+            struct level_color
             {
-               level_color( log_level l=log_level::all, 
+               level_color( log_level l=log_level::all,
                             color::type c=color::console_default )
                :level(l),color(c){}
 
                log_level                         level;
                console_appender::color::type     color;
             };
 
-            struct config 
+            struct config
             {
                config()
                :format( "${timestamp} ${thread_name} ${context} ${file}:${line} ${method} ${level}]  ${message}" ),
@@ -52,10 +52,10 @@ namespace fc
             console_appender();
 
             ~console_appender();
-            void initialize( boost::asio::io_service& io_service ) {}
-            virtual void log( const log_message& m );
-            
-            void print( const std::string& text_to_print, 
+            void initialize() override {}
+            virtual void log( const log_message& m ) override;
+
+            void print( const std::string& text_to_print,
                         color::type text_color = color::console_default );
 
             void configure( const config& cfg );

libraries/libfc/include/fc/log/dmlog_appender.hpp

@@ -20,7 +20,7 @@ namespace fc {
             explicit dmlog_appender( const std::optional<config>& args) ;
 
             virtual ~dmlog_appender();
-            virtual void initialize( boost::asio::io_service& io_service ) override;
+            virtual void initialize() override;
 
             virtual void log( const log_message& m ) override;
 

libraries/libfc/include/fc/log/gelf_appender.hpp

@@ -6,14 +6,14 @@
 
 #include <regex>
 
-namespace fc 
+namespace fc
 {
   // Log appender that sends log messages in JSON format over UDP
   // https://www.graylog2.org/resources/gelf/specification
-  class gelf_appender final : public appender 
+  class gelf_appender final : public appender
   {
   public:
-    struct config 
+    struct config
     {
       static const std::vector<std::string> reserved_field_names;
       static const std::regex user_field_name_pattern;
@@ -31,11 +31,11 @@ namespace fc
      * In a single-threaded world with a boost::io_service that's not owned
      * by this library, ugly things are required.  Tough.
      */
-    void initialize(boost::asio::io_service& io_service) override;
+    void initialize() override;
     virtual void log(const log_message& m) override;
 
-  private:
     class impl;
+  private:
     std::shared_ptr<impl> my;
   };
 } // namespace fc

libraries/libfc/include/fc/log/logger_config.hpp

@@ -54,7 +54,7 @@ namespace fc {
       static logger get_logger( const fc::string& name );
       static void update_logger( const fc::string& name, logger& log );
 
-      static void initialize_appenders( boost::asio::io_service& ios );
+      static void initialize_appenders();
 
       static bool configure_logging( const logging_config& l );
 

libraries/libfc/src/log/dmlog_appender.cpp

@@ -56,7 +56,7 @@ namespace fc {
       }
    }
 
-   void dmlog_appender::initialize( boost::asio::io_service& io_service ) {}
+   void dmlog_appender::initialize() {}
 
    void dmlog_appender::log( const log_message& m ) {
       FILE* out = my->out;

libraries/libfc/src/log/gelf_appender.cpp

@@ -8,6 +8,7 @@
 #include <fc/io/json.hpp>
 #include <fc/crypto/city.hpp>
 #include <fc/compress/zlib.hpp>
+#include <fc/log/logger_config.hpp>
 
 #include <boost/lexical_cast.hpp>
 #include <iomanip>
@@ -42,10 +43,15 @@ namespace fc
   class gelf_appender::impl
   {
   public:
+    using work_guard_t = boost::asio::executor_work_guard<boost::asio::io_context::executor_type>;
     config                                         cfg;
     std::optional<boost::asio::ip::udp::endpoint>  gelf_endpoint;
+    std::thread                                    thread;
+    boost::asio::io_context                        io_context;
+    work_guard_t work_guard =                      boost::asio::make_work_guard(io_context);
     udp_socket                                     gelf_socket;
 
+
     impl(const variant& c)
     {
       mutable_variant_object mvo;
@@ -73,6 +79,10 @@ namespace fc
 
     ~impl()
     {
+       if (thread.joinable()) {
+          work_guard.reset();
+          thread.join();
+       }
     }
   };
 
@@ -81,7 +91,7 @@ namespace fc
   {
   }
 
-  void gelf_appender::initialize(boost::asio::io_service &io_service)
+  void gelf_appender::initialize()
   {
     try
     {
@@ -100,14 +110,19 @@ namespace fc
         string::size_type colon_pos = my->cfg.endpoint.find(':');
         try
         {
-          uint16_t port = boost::lexical_cast<uint16_t>(my->cfg.endpoint.substr(colon_pos + 1, my->cfg.endpoint.size()));
+          FC_ASSERT(colon_pos != std::string::npos, "The logging destination port is not specified");
+          string port = my->cfg.endpoint.substr(colon_pos + 1);
 
           string hostname = my->cfg.endpoint.substr( 0, colon_pos );
-          auto endpoints = resolve(io_service, hostname, port);
+
+          boost::asio::ip::udp::resolver resolver{ my->io_context };
+          auto endpoints = resolver.resolve(hostname, port);
+
           if (endpoints.empty())
               FC_THROW_EXCEPTION(unknown_host_exception, "The logging destination host name can not be resolved: ${hostname}",
                                  ("hostname", hostname));
-          my->gelf_endpoint = endpoints.back();
+
+          my->gelf_endpoint = *endpoints.begin();
         }
         catch (const boost::bad_lexical_cast&)
         {
@@ -117,9 +132,20 @@ namespace fc
 
       if (my->gelf_endpoint)
       {
-        my->gelf_socket.initialize(io_service);
+        my->gelf_socket.initialize(my->io_context);
         my->gelf_socket.open();
         std::cerr << "opened GELF socket to endpoint " << my->cfg.endpoint << "\n";
+
+        my->thread = std::thread([this] {
+          try {
+            fc::set_os_thread_name("gelf");
+            my->io_context.run();
+          } catch (std::exception& ex) {
+            fprintf(stderr, "GELF logger caught exception at %s:%d : %s\n", __FILE__, __LINE__, ex.what());
+          } catch (...) {
+            fprintf(stderr, "GELF logger caught exception unknown exception %s:%d\n", __FILE__, __LINE__);
+          }
+        });
       }
     }
     catch (...)
@@ -131,20 +157,15 @@ namespace fc
   gelf_appender::~gelf_appender()
   {}
 
-  void gelf_appender::log(const log_message& message)
+  void do_log(gelf_appender::impl* my, uint64_t time_ns, const log_message& message)
   {
-    if (!my->gelf_endpoint)
-      return;
-
     log_context context = message.get_context();
 
     mutable_variant_object gelf_message;
     gelf_message["version"] = "1.1";
     gelf_message["host"] = my->cfg.host;
     gelf_message["short_message"] = format_string(message.get_format(), message.get_data(), true);
 
-    // use now() instead of context.get_timestamp() because log_message construction can include user provided long running calls
-    const auto time_ns = time_point::now().time_since_epoch().count();
     gelf_message["timestamp"] = time_ns / 1000000.;
     gelf_message["_timestamp_ns"] = time_ns;
 
@@ -248,4 +269,20 @@ namespace fc
       FC_ASSERT(number_of_packets_sent == total_number_of_packets);
     }
   }
+
+  void gelf_appender::log(const log_message& message) {
+    if (!my->gelf_endpoint)
+      return;
+
+    // use now() instead of context.get_timestamp() because log_message construction can include user provided long running calls
+    boost::asio::post(my->io_context, [impl = my.get(), time_ns = time_point::now().time_since_epoch().count(), message] () {
+      try {
+        do_log(impl, time_ns, message);
+      } catch (std::exception& ex) {
+        fprintf(stderr, "GELF logger caught exception at %s:%d : %s\n", __FILE__, __LINE__, ex.what());
+      } catch (...) {
+        fprintf(stderr, "GELF logger caught exception unknown exception %s:%d\n", __FILE__, __LINE__);
+      }
+    });
+  }
 } // fc

libraries/libfc/src/log/logger_config.cpp

@@ -43,10 +43,10 @@ namespace fc {
       }
    }
 
-   void log_config::initialize_appenders( boost::asio::io_service& ios ) {
+   void log_config::initialize_appenders() {
       std::lock_guard g( log_config::get().log_mutex );
       for( auto& iter : log_config::get().appender_map )
-         iter.second->initialize( ios );
+         iter.second->initialize();
    }
 
    void configure_logging( const fc::path& lc ) {

programs/keosd/main.cpp

@@ -43,14 +43,14 @@ void logging_conf_handler() {
       ilog("Received HUP.  No log config found at ${p}, setting to default.", ("p", config_path.string()));
    }
    configure_logging(config_path);
-   fc::log_config::initialize_appenders(app().get_io_service());
+   fc::log_config::initialize_appenders();
 }
 
 void initialize_logging() {
    auto config_path = app().get_logging_conf();
    if (fc::exists(config_path))
       fc::configure_logging(config_path); // intentionally allowing exceptions to escape
-   fc::log_config::initialize_appenders(app().get_io_service());
+   fc::log_config::initialize_appenders();
 
    app().set_sighup_callback(logging_conf_handler);
 }
@@ -86,7 +86,7 @@ int main(int argc, char** argv)
 {
    try {
       appbase::scoped_app app;
-      
+
       app->set_version_string(eosio::version::version_client());
       app->set_full_version_string(eosio::version::version_full());
       bfs::path home = determine_home_directory();

programs/nodeos/main.cpp

@@ -75,7 +75,7 @@ void logging_conf_handler()
       ilog( "Received HUP.  No log config found at ${p}, setting to default.", ("p", config_path.string()) );
    }
    ::detail::configure_logging( config_path );
-   fc::log_config::initialize_appenders( app().get_io_service() );
+   fc::log_config::initialize_appenders();
 }
 
 void initialize_logging()
@@ -89,7 +89,7 @@ void initialize_logging()
       fc::configure_logging( ::detail::add_deep_mind_logger(cfg) );
    }
 
-   fc::log_config::initialize_appenders( app().get_io_service() );
+   fc::log_config::initialize_appenders();
 
    app().set_sighup_callback(logging_conf_handler);
 }