MXS-2592 Add configuration for session specific in-memory log

When enabled each session will write log messages in the in-memory log.
If session ends in error this log is written to the actual log in disk.

include/maxscale/session.h

@@ -679,6 +679,17 @@ session_dump_statements_t session_get_dump_statements();
  */
 const char* session_get_dump_statements_str();
 
+
+void session_set_session_trace(uint32_t value);
+
+uint32_t session_get_session_trace();
+
+const char* session_get_session_log(MXS_SESSION* pSession);
+
+void session_append_log(MXS_SESSION* pSession, const char* log);
+
+void session_dump_log(MXS_SESSION* pSession);
+
 /**
  * @brief Route the query again after a delay
  *

maxctrl/lib/show.js

@@ -59,7 +59,8 @@ const session_fields = [
     {'Idle': 'attributes.idle'},
     {'Connections': 'attributes.connections[].server'},
     {'Connection IDs': 'attributes.connections[].protocol_diagnostics.connection_id'},
-    {'Queries': 'attributes.queries[].statement'}
+    {'Queries': 'attributes.queries[].statement'},
+    {'Log': 'attributes.log'}
 ]
 
 const filter_fields = [

maxutils/maxbase/include/maxbase/log.h

@@ -85,6 +85,8 @@ typedef struct MXB_LOG_THROTTLING
  */
 typedef size_t (* mxb_log_context_provider_t)(char* buffer, size_t len);
 
+typedef void (* mxb_in_memory_log_t)(const char* buffer, size_t len);
+
 /**
  * @brief Initialize the log
  *
@@ -105,7 +107,8 @@ bool mxb_log_init(const char* ident,
                   const char* logdir,
                   const char* filename,
                   mxb_log_target_t target,
-                  mxb_log_context_provider_t context_provider);
+                  mxb_log_context_provider_t context_provider,
+                  mxb_in_memory_log_t in_memory_log);
 
 /**
  * @brief Finalize the log
@@ -150,6 +153,8 @@ const char* mxb_log_get_filename();
  */
 bool mxb_log_set_priority_enabled(int priority, bool enabled);
 
+bool mxb_log_get_session_trace();
+
 /**
  * Query whether a particular syslog priority is enabled.
  *
@@ -233,6 +238,14 @@ void mxb_log_get_throttling(MXB_LOG_THROTTLING* throttling);
  */
 void mxs_log_redirect_stdout(bool redirect);
 
+/**
+ * Set session specific in-memory log
+ *
+ * @param enabled True or false to enable or disable session in-memory logging
+ */
+void mxb_log_set_session_trace(bool enabled);
+
+
 /**
  * Log a message of a particular priority.
  *
@@ -278,7 +291,7 @@ int mxb_log_oom(const char* message);
  *            MXB_ERROR, MXB_WARNING, etc. macros instead.
  */
 #define MXB_LOG_MESSAGE(priority, format, ...) \
-    (mxb_log_is_priority_enabled(priority)   \
+    (mxb_log_is_priority_enabled(priority) || mxb_log_get_session_trace()  \
      ? mxb_log_message(priority, MXB_MODULE_NAME, __FILE__, __LINE__, __func__, format, ##__VA_ARGS__)  \
      : 0)
 

maxutils/maxbase/include/maxbase/log.hh

@@ -30,7 +30,7 @@
  */
 inline bool mxb_log_init(mxb_log_target_t target = MXB_LOG_TARGET_FS)
 {
-    return mxb_log_init(nullptr, ".", nullptr, target, nullptr);
+    return mxb_log_init(nullptr, ".", nullptr, target, nullptr, nullptr);
 }
 
 namespace maxbase
@@ -52,16 +52,17 @@ public:
         const char* logdir,
         const char* filename,
         mxb_log_target_t target,
-        mxb_log_context_provider_t context_provider)
+        mxb_log_context_provider_t context_provider,
+        mxb_in_memory_log_t in_memory_log)
     {
-        if (!mxb_log_init(ident, logdir, filename, target, context_provider))
+        if (!mxb_log_init(ident, logdir, filename, target, context_provider, in_memory_log))
         {
             throw std::runtime_error("Failed to initialize the log.");
         }
     }
 
     Log(mxb_log_target_t target = MXB_LOG_TARGET_FS)
-        : Log(nullptr, ".", nullptr, target, nullptr)
+        : Log(nullptr, ".", nullptr, target, nullptr, nullptr)
     {
     }
 

maxutils/maxbase/include/maxbase/maxbase.hh

@@ -78,7 +78,8 @@ public:
             const char* zLogdir,
             const char* zFilename,
             mxb_log_target_t target,
-            mxb_log_context_provider_t context_provider);
+            mxb_log_context_provider_t context_provider,
+            mxb_in_memory_log_t in_memory_log);
 
     /**
      * @brief Initializes MaxBase and the MaxBase log.
@@ -88,7 +89,7 @@ public:
      * @throws std::runtime_error if the initialization failed.
      */
     MaxBase(mxb_log_target_t target)
-        : MaxBase(nullptr, ".", nullptr, target, nullptr)
+        : MaxBase(nullptr, ".", nullptr, target, nullptr, nullptr)
     {
     }
 

maxutils/maxbase/src/log.cc

@@ -386,10 +386,12 @@ struct this_unit
     bool                             do_syslog;         // Can change during the lifetime of log_manager.
     bool                             do_maxlog;         // Can change during the lifetime of log_manager.
     bool                             redirect_stdout;
+    bool                             session_trace;
     MXB_LOG_THROTTLING               throttling;        // Can change during the lifetime of log_manager.
     std::unique_ptr<mxb::Logger>     sLogger;
     std::unique_ptr<MessageRegistry> sMessage_registry;
     size_t                           (* context_provider)(char* buffer, size_t len);
+    void                             (* in_memory_log)(const char* buffer, size_t len);
 } this_unit =
 {
     DEFAULT_LOG_AUGMENTATION,   // augmentation
@@ -397,6 +399,7 @@ struct this_unit
     true,                       // do_syslog
     true,                       // do_maxlog
     false,                      // redirect_stdout
+    false,                      // session_trace
     DEFAULT_LOG_THROTTLING,     // throttling
 };
 
@@ -449,7 +452,8 @@ bool mxb_log_init(const char* ident,
                   const char* logdir,
                   const char* filename,
                   mxb_log_target_t target,
-                  mxb_log_context_provider_t context_provider)
+                  mxb_log_context_provider_t context_provider,
+                  mxb_in_memory_log_t in_memory_log)
 {
     assert(!this_unit.sLogger && !this_unit.sMessage_registry);
 
@@ -511,6 +515,7 @@ bool mxb_log_init(const char* ident,
     if (this_unit.sLogger && this_unit.sMessage_registry)
     {
         this_unit.context_provider = context_provider;
+        this_unit.in_memory_log = in_memory_log;
 
         openlog(ident, LOG_PID | LOG_ODELAY, LOG_USER);
     }
@@ -614,6 +619,16 @@ void mxs_log_redirect_stdout(bool redirect)
     this_unit.redirect_stdout = redirect;
 }
 
+void mxb_log_set_session_trace(bool enabled)
+{
+    this_unit.session_trace = enabled;
+}
+
+bool mxb_log_get_session_trace()
+{
+    return this_unit.session_trace;
+}
+
 bool mxb_log_rotate()
 {
     bool rval = this_unit.sLogger->rotate();
@@ -874,7 +889,19 @@ int mxb_log_message(int priority,
                 // Add a final newline into the message
                 msg.push_back('\n');
 
-                err = this_unit.sLogger->write(msg.c_str(), msg.length()) ? 0 : -1;
+                if (this_unit.session_trace)
+                {
+                    this_unit.in_memory_log(msg.c_str(), msg.length());
+                }
+
+                if (mxb_log_is_priority_enabled(priority))
+                {
+                    err = this_unit.sLogger->write(msg.c_str(), msg.length()) ? 0 : -1;
+                }
+                else
+                {
+                    err = 0;
+                }
             }
         }
     }

maxutils/maxbase/src/maxbase.cc

@@ -92,14 +92,15 @@ MaxBase::MaxBase(const char* zIdent,
                  const char* zLogdir,
                  const char* zFilename,
                  mxb_log_target_t target,
-                 mxb_log_context_provider_t context_provider)
+                 mxb_log_context_provider_t context_provider,
+                 mxb_in_memory_log_t in_memory_log)
     : m_log_inited(false)
 {
     const char* zMessage = nullptr;
 
     if (maxbase::init())
     {
-        m_log_inited = mxb_log_init(zIdent, zLogdir, zFilename, target, context_provider);
+        m_log_inited = mxb_log_init(zIdent, zLogdir, zFilename, target, context_provider, in_memory_log);
 
         if (!m_log_inited)
         {

server/core/config.cc

@@ -160,6 +160,7 @@ const char CN_SERVER[] = "server";
 const char CN_SERVICES[] = "services";
 const char CN_SERVICE[] = "service";
 const char CN_SESSIONS[] = "sessions";
+const char CN_SESSION_TRACE[] = "session_trace";
 const char CN_SESSION_TRACK_TRX_STATE[] = "session_track_trx_state";
 const char CN_SKIP_PERMISSION_CHECKS[] = "skip_permission_checks";
 const char CN_SOCKET[] = "socket";
@@ -317,6 +318,7 @@ const MXS_MODULE_PARAM config_service_params[] =
     {CN_RETRY_ON_FAILURE,              MXS_MODULE_PARAM_BOOL,   "true"},
     {CN_SESSION_TRACK_TRX_STATE,       MXS_MODULE_PARAM_BOOL,   "false"},
     {CN_RETAIN_LAST_STATEMENTS,        MXS_MODULE_PARAM_INT,    "-1"},
+    {CN_SESSION_TRACE,                 MXS_MODULE_PARAM_INT,    "0"},
     {NULL}
 };
 
@@ -2602,6 +2604,21 @@ static int handle_global_item(const char* name, const char* value)
             return 0;
         }
     }
+    else if (strcmp(name, CN_SESSION_TRACE) == 0)
+    {
+        char* endptr;
+        int intval = strtol(value, &endptr, 0);
+        if (*endptr == '\0' && intval >= 0)
+        {
+            session_set_session_trace(intval);
+            mxb_log_set_session_trace(true);
+        }
+        else
+        {
+            MXS_ERROR("Invalid value for '%s': %s", CN_SESSION_TRACE, value);
+            return 0;
+        }
+    }
     else if (strcmp(name, CN_LOAD_PERSISTED_CONFIGS) == 0)
     {
         int b = config_truth_value(value);

server/core/gateway.cc

@@ -432,6 +432,7 @@ static void sigfatal_handler(int i)
         if (dcb->session)
         {
             session_dump_statements(dcb->session);
+            session_dump_log(dcb->session);
         }
     }
 

server/core/internal/session.hh

@@ -97,7 +97,7 @@ public:
     };
 
     typedef std::deque<QueryInfo> QueryInfos;
-
+    using Log = std::deque<std::string>;
     using FilterList = std::vector<SessionFilter>;
 
     Session(SERVICE* service);
@@ -121,8 +121,11 @@ public:
     void book_server_response(SERVER* pServer, bool final_response);
     void book_last_as_complete();
     void reset_server_bookkeeping();
+    void append_session_log(std::string);
+    void dump_session_log();
 
     json_t* queries_as_json() const;
+    json_t* log_as_json() const;
 
     void link_backend_dcb(DCB* dcb)
     {
@@ -148,6 +151,7 @@ private:
     int               m_current_query = -1;     /*< The index of the current query */
     DCBSet            m_dcb_set;                /*< Set of associated backend DCBs */
     uint32_t          m_retain_last_statements; /*< How many statements be retained */
+    Log               m_log;                    /*< Session specific in-memory log */
 };
 }
 

server/core/log.cc

@@ -47,13 +47,22 @@ size_t mxs_get_context(char* buffer, size_t len)
 
     return len;
 }
+
+void mxs_log_in_memory(const char* msg, size_t len)
+{
+    MXS_SESSION* session = session_get_current();
+    if (session)
+    {
+        session_append_log(session, msg);
+    }
+}
 }
 
 bool mxs_log_init(const char* ident, const char* logdir, mxs_log_target_t target)
 {
     mxb::Logger::set_ident("MariaDB MaxScale");
 
-    return mxb_log_init(ident, logdir, LOGFILE_NAME, target, mxs_get_context);
+    return mxb_log_init(ident, logdir, LOGFILE_NAME, target, mxs_get_context, mxs_log_in_memory);
 }
 
 namespace

server/core/session.cc

@@ -62,11 +62,13 @@ struct
     uint64_t next_session_id;
     uint32_t retain_last_statements;
     session_dump_statements_t dump_statements;
+    uint32_t session_trace;
 } this_unit =
 {
     1,
     0,
-    SESSION_DUMP_STATEMENTS_NEVER
+    SESSION_DUMP_STATEMENTS_NEVER,
+    0
 };
 
 static struct session dummy_session()
@@ -909,6 +911,9 @@ json_t* session_json_data(const Session* session, const char* host)
     json_t* queries = session->queries_as_json();
     json_object_set_new(attr, "queries", queries);
 
+    json_t* log = session->log_as_json();
+    json_object_set_new(attr, "log", log);
+
     json_object_set_new(data, CN_ATTRIBUTES, attr);
     json_object_set_new(data, CN_LINKS, mxs_json_self_link(host, CN_SESSIONS, ss.str().c_str()));
 
@@ -1111,6 +1116,32 @@ void session_dump_statements(MXS_SESSION* session)
     pSession->dump_statements();
 }
 
+void session_set_session_trace(uint32_t value)
+{
+    this_unit.session_trace = value;
+}
+
+uint32_t session_get_session_trace()
+{
+    return this_unit.session_trace;
+}
+
+void session_append_log(MXS_SESSION* pSession, const char* log)
+{
+    // Ignore dummy and listener sessions
+    if (pSession->state != SESSION_STATE_DUMMY
+        && pSession->state != SESSION_STATE_LISTENER
+        && pSession->state != SESSION_STATE_LISTENER_STOPPED)
+    {
+        static_cast<Session*>(pSession)->append_session_log(std::string(log));
+    }
+}
+
+void session_dump_log(MXS_SESSION* pSession)
+{
+    static_cast<Session*>(pSession)->dump_session_log();
+}
+
 class DelayedRoutingTask
 {
     DelayedRoutingTask(const DelayedRoutingTask&) = delete;
@@ -1365,6 +1396,18 @@ json_t* Session::queries_as_json() const
     return pQueries;
 }
 
+json_t* Session::log_as_json() const
+{
+    json_t* pLog = json_array();
+
+    for (const auto& i : m_log)
+    {
+        json_array_append_new(pLog, json_string(i.c_str()));
+    }
+
+    return pLog;
+}
+
 bool Session::setup_filters(Service* service)
 {
     for (const auto& a : service->get_filters())
@@ -1724,3 +1767,28 @@ void Session::QueryInfo::reset_server_bookkeeping()
     m_completed.tv_nsec = 0;
     m_complete = false;
 }
+
+void Session::append_session_log(std::string log)
+{
+    m_log.push_front(log);
+
+    if (m_log.size() >= this_unit.session_trace)
+    {
+        m_log.pop_back();
+    }
+}
+
+void Session::dump_session_log()
+{
+    if (!(m_log.empty()))
+    {
+        std::string log;
+
+        for (const auto& s : m_log)
+        {
+            log += s;
+        }
+
+        MXS_NOTICE("Session log for session (%" PRIu64"): \n%s ", ses_id, log.c_str());
+    }
+}

server/modules/protocol/MySQL/mariadbclient/mysql_client.cc

@@ -1585,6 +1585,11 @@ static int gw_client_hangup_event(DCB* dcb)
                 session_dump_statements(session);
             }
 
+            if (session_get_session_trace())
+            {
+                session_dump_log(session);
+            }
+
             // The client did not send a COM_QUIT packet
             std::string errmsg {"Connection killed by MaxScale"};
             std::string extra {session_get_close_reason(dcb->session)};

server/modules/routing/readwritesplit/rwsplitsession.cc

@@ -395,6 +395,7 @@ static void log_unexpected_response(SRWBackend& backend, GWBUF* buffer, GWBUF* c
                   backend->current_command(),
                   sql.c_str());
         session_dump_statements(backend->dcb()->session);
+        session_dump_log(backend->dcb()->session);
         mxb_assert(false);
     }
 }