diff --git a/include/maxscale/session.hh b/include/maxscale/session.hh index a9ae524c9..d840ee71c 100644 --- a/include/maxscale/session.hh +++ b/include/maxscale/session.hh @@ -602,6 +602,16 @@ void session_dump_statements(MXS_SESSION* pSession); */ void session_set_dump_statements(session_dump_statements_t value); +void session_set_session_trace(uint32_t value); + +uint32_t session_get_session_trace(); + +std::string session_get_session_log(MXS_SESSION* pSession); + +void session_append_log(MXS_SESSION* pSession, std::string log); + +void session_dump_log(MXS_SESSION* pSession); + /** * @brief Returns in what contexts statements should be dumped. * diff --git a/maxctrl/lib/common.js b/maxctrl/lib/common.js index f1e58f9ac..caea62d8f 100644 --- a/maxctrl/lib/common.js +++ b/maxctrl/lib/common.js @@ -144,7 +144,7 @@ module.exports = function() { str = str.replace( /\x1B\[[(?);]{0,2}(;?\d)*./g, '') // Trim trailing whitespace that cli-table generates - str = str.split(os.EOL).map(s => s.split('\t').map(s => s.trimEnd()).join('\t')).join(os.EOL) + str = str.split(os.EOL).map(s => s.split('\t').map(s => s.trim()).join('\t')).join(os.EOL) } return str } diff --git a/maxctrl/lib/show.js b/maxctrl/lib/show.js index 0a4fb534e..b29e3613e 100644 --- a/maxctrl/lib/show.js +++ b/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 = [ diff --git a/maxscale-system-test/mysqlmon_multimaster.cpp b/maxscale-system-test/mysqlmon_multimaster.cpp index 6022f5a55..7423c16e3 100644 --- a/maxscale-system-test/mysqlmon_multimaster.cpp +++ b/maxscale-system-test/mysqlmon_multimaster.cpp @@ -56,7 +56,7 @@ json_t* get_json_data(TestConnections& test, const char* query) char* output = test.maxscales->ssh_node_output(0, query, true, &exit_code); if (output == NULL) { - test.add_result(1, "Query '%s' execution error, no output.\ni", output); + test.add_result(1, "Query '%s' execution error, no output.", query); } else { diff --git a/maxutils/maxbase/include/maxbase/log.h b/maxutils/maxbase/include/maxbase/log.h index 0700f5cd3..a42065836 100644 --- a/maxutils/maxbase/include/maxbase/log.h +++ b/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) diff --git a/maxutils/maxbase/include/maxbase/log.hh b/maxutils/maxbase/include/maxbase/log.hh index a8a0187d0..ba04fa576 100644 --- a/maxutils/maxbase/include/maxbase/log.hh +++ b/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) { } diff --git a/maxutils/maxbase/include/maxbase/maxbase.hh b/maxutils/maxbase/include/maxbase/maxbase.hh index 13799f65d..51ff4bbcf 100644 --- a/maxutils/maxbase/include/maxbase/maxbase.hh +++ b/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) { } diff --git a/maxutils/maxbase/src/log.cc b/maxutils/maxbase/src/log.cc index c465f7ae0..7f4b46835 100644 --- a/maxutils/maxbase/src/log.cc +++ b/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 sLogger; std::unique_ptr 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; + } } } } diff --git a/maxutils/maxbase/src/maxbase.cc b/maxutils/maxbase/src/maxbase.cc index 80dfa9718..9a1683a4d 100644 --- a/maxutils/maxbase/src/maxbase.cc +++ b/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) { diff --git a/server/core/config.cc b/server/core/config.cc index 3a74257a6..7ca0818d7 100644 --- a/server/core/config.cc +++ b/server/core/config.cc @@ -172,6 +172,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"; @@ -393,6 +394,11 @@ const MXS_MODULE_PARAM config_service_params[] = MXS_MODULE_PARAM_INT, "-1" }, + { + CN_SESSION_TRACE, + MXS_MODULE_PARAM_BOOL, + "false" + }, { CN_CLUSTER, MXS_MODULE_PARAM_STRING @@ -2729,6 +2735,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); diff --git a/server/core/gateway.cc b/server/core/gateway.cc index a55446c06..3103b8100 100644 --- a/server/core/gateway.cc +++ b/server/core/gateway.cc @@ -433,6 +433,7 @@ static void sigfatal_handler(int i) if (dcb->session) { session_dump_statements(dcb->session); + session_dump_log(dcb->session); } } diff --git a/server/core/internal/session.hh b/server/core/internal/session.hh index d52c28e35..5708b8ef3 100644 --- a/server/core/internal/session.hh +++ b/server/core/internal/session.hh @@ -160,7 +160,7 @@ public: }; typedef std::deque QueryInfos; - + using Log = std::deque; using FilterList = std::vector; Session(const SListener& listener); @@ -187,8 +187,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) { @@ -214,6 +217,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 */ }; } diff --git a/server/core/log.cc b/server/core/log.cc index e8d8363ff..e1f3223c2 100644 --- a/server/core/log.cc +++ b/server/core/log.cc @@ -54,13 +54,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 diff --git a/server/core/session.cc b/server/core/session.cc index 8c735b178..ad90c90ed 100644 --- a/server/core/session.cc +++ b/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 }; } @@ -803,6 +805,9 @@ json_t* session_json_data(const Session* session, const char* host, bool rdns) 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())); @@ -1012,6 +1017,28 @@ 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, std::string log) +{ + { + static_cast(pSession)->append_session_log(log); + } +} + +void session_dump_log(MXS_SESSION* pSession) +{ + static_cast(pSession)->dump_session_log(); +} + class DelayedRoutingTask { DelayedRoutingTask(const DelayedRoutingTask&) = delete; @@ -1277,6 +1304,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()) @@ -1635,3 +1674,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()); + } +} \ No newline at end of file diff --git a/server/modules/protocol/MySQL/mariadbclient/mysql_client.cc b/server/modules/protocol/MySQL/mariadbclient/mysql_client.cc index eac982388..2e6b8f903 100644 --- a/server/modules/protocol/MySQL/mariadbclient/mysql_client.cc +++ b/server/modules/protocol/MySQL/mariadbclient/mysql_client.cc @@ -1709,6 +1709,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)}; diff --git a/server/modules/protocol/MySQL/rwbackend.cc b/server/modules/protocol/MySQL/rwbackend.cc index 83e5664a5..94337f2b1 100644 --- a/server/modules/protocol/MySQL/rwbackend.cc +++ b/server/modules/protocol/MySQL/rwbackend.cc @@ -304,6 +304,7 @@ void RWBackend::process_packets(GWBUF* result) auto it = buffer.begin(); MXB_AT_DEBUG(size_t total_len = buffer.length()); MXB_AT_DEBUG(size_t used_len = 0); + mxb_assert(dcb()->session->service->capabilities & (RCAP_TYPE_PACKET_OUTPUT | RCAP_TYPE_STMT_OUTPUT)); while (it != buffer.end()) { diff --git a/server/modules/routing/readwritesplit/rwsplit_route_stmt.cc b/server/modules/routing/readwritesplit/rwsplit_route_stmt.cc index 735f4c614..298913fae 100644 --- a/server/modules/routing/readwritesplit/rwsplit_route_stmt.cc +++ b/server/modules/routing/readwritesplit/rwsplit_route_stmt.cc @@ -359,7 +359,7 @@ bool RWSplitSession::route_single_stmt(GWBUF* querybuf) succp = true; MXS_INFO("Delaying routing: %s", extract_sql(querybuf).c_str()); } - else + else if (m_config.master_failure_mode != RW_ERROR_ON_WRITE) { MXS_ERROR("Could not find valid server for target type %s, closing " "connection.", route_target_to_string(route_target)); diff --git a/server/modules/routing/readwritesplit/rwsplitsession.cc b/server/modules/routing/readwritesplit/rwsplitsession.cc index 378b9aac8..438845661 100644 --- a/server/modules/routing/readwritesplit/rwsplitsession.cc +++ b/server/modules/routing/readwritesplit/rwsplitsession.cc @@ -366,6 +366,7 @@ static void log_unexpected_response(RWBackend* backend, GWBUF* buffer, GWBUF* cu backend->current_command(), sql.c_str()); session_dump_statements(backend->dcb()->session); + session_dump_log(backend->dcb()->session); mxb_assert(false); } } @@ -1005,7 +1006,9 @@ void RWSplitSession::handleError(GWBUF* errmsgbuf, MXS_INFO("Master '%s' failed: %s", backend->name(), extract_error(errmsgbuf).c_str()); /** The connection to the master has failed */ - if (!backend->is_waiting_result()) + bool expected_response = backend->is_waiting_result(); + + if (!expected_response) { /** The failure of a master is not considered a critical * failure as partial functionality still remains. If @@ -1041,14 +1044,6 @@ void RWSplitSession::handleError(GWBUF* errmsgbuf, can_continue = true; send_readonly_error(m_client); } - - // Decrement the expected response count only if we know we can continue the sesssion. - // This keeps the internal logic sound even if another query is routed before the session - // is closed. - if (can_continue) - { - m_expected_responses--; - } } if (session_trx_is_active(session) && m_otrx_state == OTRX_INACTIVE) @@ -1076,6 +1071,14 @@ void RWSplitSession::handleError(GWBUF* errmsgbuf, } } + // Decrement the expected response count only if we know we can continue the sesssion. + // This keeps the internal logic sound even if another query is routed before the session + // is closed. + if (can_continue && expected_response) + { + m_expected_responses--; + } + backend->close(); backend->set_close_reason("Master connection failed: " + extract_error(errmsgbuf)); } diff --git a/server/modules/routing/schemarouter/schemarouterinstance.cc b/server/modules/routing/schemarouter/schemarouterinstance.cc index fc94f4254..0090abe14 100644 --- a/server/modules/routing/schemarouter/schemarouterinstance.cc +++ b/server/modules/routing/schemarouter/schemarouterinstance.cc @@ -264,9 +264,12 @@ json_t* SchemaRouter::diagnostics_json() const return rval; } +static const uint64_t CAPABILITIES = RCAP_TYPE_CONTIGUOUS_INPUT | RCAP_TYPE_PACKET_OUTPUT + | RCAP_TYPE_RUNTIME_CONFIG; + uint64_t SchemaRouter::getCapabilities() { - return RCAP_TYPE_CONTIGUOUS_INPUT | RCAP_TYPE_RUNTIME_CONFIG; + return schemarouter::CAPABILITIES; } } @@ -280,7 +283,6 @@ uint64_t SchemaRouter::getCapabilities() */ extern "C" MXS_MODULE* MXS_CREATE_MODULE() { - static uint64_t caps = RCAP_TYPE_CONTIGUOUS_INPUT | RCAP_TYPE_RUNTIME_CONFIG; static auto desc = "A database sharding router for simple sharding"; static MXS_MODULE info = { @@ -289,7 +291,7 @@ extern "C" MXS_MODULE* MXS_CREATE_MODULE() MXS_ROUTER_VERSION, desc, "V1.0.0", - caps, + schemarouter::CAPABILITIES, &schemarouter::SchemaRouter::s_object, NULL, NULL, diff --git a/server/modules/routing/schemarouter/schemaroutersession.cc b/server/modules/routing/schemarouter/schemaroutersession.cc index 1b7605a19..fa322fca3 100644 --- a/server/modules/routing/schemarouter/schemaroutersession.cc +++ b/server/modules/routing/schemarouter/schemaroutersession.cc @@ -1192,11 +1192,13 @@ char* get_lenenc_str(void* data) return rval; } +static const std::set always_ignore = {"mysql", "information_schema", "performance_schema"}; + bool SchemaRouterSession::ignore_duplicate_database(const char* data) { bool rval = false; - if (m_config->ignored_dbs.find(data) != m_config->ignored_dbs.end()) + if (m_config->ignored_dbs.count(data) || always_ignore.count(data)) { rval = true; } @@ -1379,8 +1381,7 @@ void SchemaRouterSession::query_databases() "LEFT JOIN information_schema.tables AS t ON s.schema_name = t.table_schema " "WHERE t.table_name IS NULL " "UNION " - "SELECT CONCAT (table_schema, '.', table_name) FROM information_schema.tables " - "WHERE table_schema NOT IN ('information_schema', 'performance_schema', 'mysql');"); + "SELECT CONCAT (table_schema, '.', table_name) FROM information_schema.tables"); gwbuf_set_type(buffer, GWBUF_TYPE_COLLECT_RESULT); for (SSRBackendList::iterator it = m_backends.begin(); it != m_backends.end(); it++)