hcq/MaxScale
hcq/MaxScale
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

MXS-2050 Clean up session log checking

Browse Source 
Also moved constants around.
This commit is contained in:
Esa Korhonen 2019-02-11 17:22:29 +02:00
parent c5763beb28
commit 311704cdd9
2 changed files with 207 additions and 180 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

282
server/modules/filter/qlafilter/qlafilter.cc
View File

@ -49,38 +49,28 @@
using std::string;
/* Log file save mode flags */
#define CONFIG_FILE_SESSION (1 << 0) // Default value, session specific files
#define CONFIG_FILE_UNIFIED (1 << 1) // One file shared by all sessions
/* Default values for logged data */
#define LOG_DATA_DEFAULT "date,user,query"
static const char PARAM_MATCH[] = "match";
static const char PARAM_EXCLUDE[] = "exclude";
static const char PARAM_USER[] = "user";
static const char PARAM_SOURCE[] = "source";
static const char PARAM_FILEBASE[] = "filebase";
static const char PARAM_OPTIONS[] = "options";
static const char PARAM_LOG_TYPE[] = "log_type";
static const char PARAM_LOG_DATA[] = "log_data";
static const char PARAM_FLUSH[] = "flush";
static const char PARAM_APPEND[] = "append";
static const char PARAM_NEWLINE[] = "newline_replacement";
static const char PARAM_SEPARATOR[] = "separator";
/* Flags for controlling extra log entry contents */
enum log_options
namespace
{
LOG_DATA_SERVICE = (1 << 0),
LOG_DATA_SESSION = (1 << 1),
LOG_DATA_DATE = (1 << 2),
LOG_DATA_USER = (1 << 3),
LOG_DATA_QUERY = (1 << 4),
LOG_DATA_REPLY_TIME = (1 << 5),
};
static const MXS_ENUM_VALUE option_values[] =
const char HEADER_ERROR[] = "Failed to print header to file %s. Error %i: '%s'.";
const char PARAM_MATCH[] = "match";
const char PARAM_EXCLUDE[] = "exclude";
const char PARAM_USER[] = "user";
const char PARAM_SOURCE[] = "source";
const char PARAM_FILEBASE[] = "filebase";
const char PARAM_OPTIONS[] = "options";
const char PARAM_LOG_TYPE[] = "log_type";
const char PARAM_LOG_DATA[] = "log_data";
const char PARAM_FLUSH[] = "flush";
const char PARAM_APPEND[] = "append";
const char PARAM_NEWLINE[] = "newline_replacement";
const char PARAM_SEPARATOR[] = "separator";
const MXS_ENUM_VALUE option_values[] =
{
{"ignorecase", PCRE2_CASELESS},
{"case", 0 },
@ -88,24 +78,80 @@ static const MXS_ENUM_VALUE option_values[] =
{NULL}
};
static const MXS_ENUM_VALUE log_type_values[] =
const MXS_ENUM_VALUE log_type_values[] =
{
{"session", CONFIG_FILE_SESSION},
{"unified", CONFIG_FILE_UNIFIED},
{"session", QlaInstance::LOG_FILE_SESSION},
{"unified", QlaInstance::LOG_FILE_UNIFIED},
{NULL}
};
static const MXS_ENUM_VALUE log_data_values[] =
const MXS_ENUM_VALUE log_data_values[] =
{
{"service", LOG_DATA_SERVICE },
{"session", LOG_DATA_SESSION },
{"date", LOG_DATA_DATE },
{"user", LOG_DATA_USER },
{"query", LOG_DATA_QUERY },
{"reply_time", LOG_DATA_REPLY_TIME},
{"service", QlaInstance::LOG_DATA_SERVICE },
{"session", QlaInstance::LOG_DATA_SESSION },
{"date", QlaInstance::LOG_DATA_DATE },
{"user", QlaInstance::LOG_DATA_USER },
{"query", QlaInstance::LOG_DATA_QUERY },
{"reply_time", QlaInstance::LOG_DATA_REPLY_TIME},
{NULL}
};
/**
* Open a file if it doesn't exist.
*
* @param filename Filename
* @param ppFile Double pointer to old file. The file can be null.
* @return True if new file was opened successfully. False, if file already existed or if new file
* could not be opened. If false is returned, the caller should check that the file object exists.
*/
bool check_replace_file(const string& filename, FILE** ppFile)
{
auto zfilename = filename.c_str();
const char retry_later[] = "Logging to file is disabled. The operation will be retried later.";
bool newfile = false;
// Check if file exists and create it if not.
int fd = open(zfilename, O_WRONLY | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR);
if (fd < 0)
{
// EEXIST is the expected error code.
if (errno != EEXIST)
{
MXS_ERROR("Could not open log file '%s'. open() failed with error code %i: '%s'. %s",
zfilename, errno, mxs_strerror(errno), retry_later);
// Do not close the existing file in this case since it was not touched. Likely though,
// writing to it will fail.
}
// Otherwise the file already exists and the existing file stream should be valid.
}
else
{
MXS_INFO("Log file '%s' recreated.", zfilename);
// File was created. Close the original file stream since it's pointing to a moved file.
auto fp = *ppFile;
if (fp)
{
fclose(fp);
}
fp = fdopen(fd, "w");
if (fp)
{
newfile = true;
}
else
{
MXS_ERROR("Could not convert file descriptor of '%s' to stream. fdopen() "
"failed with error code %i: '%s'. %s",
filename.c_str(), errno, mxs_strerror(errno), retry_later);
::close(fd);
}
*ppFile = fp;
}
return newfile;
}
}
QlaInstance::QlaInstance(const string& name, MXS_CONFIG_PARAMETER* params)
: m_settings(params)
, m_name(name)
@ -126,8 +172,8 @@ QlaInstance::Settings::Settings(MXS_CONFIG_PARAMETER* params)
, exclude(params->get_string(PARAM_EXCLUDE))
{
auto log_file_types = params->get_enum(PARAM_LOG_TYPE, log_type_values);
write_session_log = (log_file_types & CONFIG_FILE_SESSION);
write_unified_log = (log_file_types & CONFIG_FILE_UNIFIED);
write_session_log = (log_file_types & LOG_FILE_SESSION);
write_unified_log = (log_file_types & LOG_FILE_UNIFIED);
}
QlaInstance::~QlaInstance()
@ -195,22 +241,13 @@ QlaInstance* QlaInstance::create(const std::string name, MXS_CONFIG_PARAMETER* p
// Try to open the unified log file
if (my_instance->m_settings.write_unified_log)
{
string unified_filename = my_instance->m_settings.filebase + ".unified";
my_instance->m_unified_filename = my_instance->m_settings.filebase + ".unified";
// Open the file. It is only closed at program exit.
FILE* unified_fp = my_instance->open_log_file(my_instance->m_settings.log_file_data_flags,
unified_filename.c_str());
if (unified_fp != NULL)
if (!my_instance->open_unified_logfile())
{
my_instance->m_unified_filename = unified_filename;
my_instance->m_unified_fp = unified_fp;
}
else
{
MXS_ERROR("Opening output file for qla-filter failed due to %d, %s",
errno,
mxs_strerror(errno));
delete my_instance;
my_instance = NULL;
error = true;
}
}
}
@ -273,17 +310,10 @@ bool QlaFilterSession::prepare()
// Only open the session file if the corresponding mode setting is used.
if (!error && settings.write_session_log)
{
string filename = mxb::string_printf("%s.%" PRIu64, settings.filebase.c_str(), m_ses_id);
m_logfile = m_instance.open_log_file(m_instance.m_session_data_flags, filename.c_str());
if (m_logfile)
m_filename = mxb::string_printf("%s.%" PRIu64, settings.filebase.c_str(), m_ses_id);
m_logfile = m_instance.open_session_log_file(m_filename);
if (!m_logfile)
{
m_filename = filename;
}
else
{
MXS_ERROR("Opening output file %s' for qla-filter failed due to %d, %s",
filename.c_str(), errno, mxs_strerror(errno));
error = true;
}
}
@ -385,45 +415,20 @@ json_t* QlaInstance::diagnostics_json() const
return rval;
}
void QlaFilterSession::check_session_log_rotation(const string& filename, FILE** ppFile)
void QlaFilterSession::check_session_log_rotation()
{
auto pFile = *ppFile;
const char retry_later[] = "Logging to file is disabled. The operation will be retried later.";
// Check if file exists and create it if not.
int fd = open(filename.c_str(), O_WRONLY | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR);
if (fd < 0)
if (check_replace_file(m_filename, &m_logfile))
{
// EEXIST is the expected error code.
if (errno != EEXIST)
// New file created, print the log header.
string header = m_instance.generate_log_header(m_instance.m_session_data_flags);
if (!m_instance.write_to_logfile(m_logfile, header))
{
MXS_ERROR("Could not open log file '%s'. open() failed with error code %i: '%s'. %s",
filename.c_str(), errno, mxs_strerror(errno), retry_later);
fclose(pFile);
pFile = nullptr;
}
// Otherwise the file already exists and the existing file stream should be valid.
}
else
{
MXS_INFO("Log file '%s' recreated.", filename.c_str());
// File was created. Close the original file stream since it's pointing to a moved file.
fclose(pFile);
pFile = fdopen(fd, "w");
if (pFile)
{
// Print the log header.
string header = m_instance.generate_log_header(m_instance.m_session_data_flags);
m_instance.write_to_logfile(&pFile, header);
}
else
{
MXS_ERROR("Could not convert file descriptor of '%s' to stream. fdopen() "
"failed with error code %i: '%s'. %s",
filename.c_str(), errno, mxs_strerror(errno), retry_later);
::close(fd);
MXS_ERROR(HEADER_ERROR, m_filename.c_str(), errno, mxs_strerror(errno));
fclose(m_logfile);
m_logfile = nullptr;
}
}
*ppFile = pFile;
// Either the old file existed or file creation failed.
}
/**
@ -445,7 +450,7 @@ void QlaFilterSession::write_log_entries(const char* date_string, const char* qu
{
if (m_file_check_timer.split().secs() > check_interval)
{
check_session_log_rotation(m_filename, &m_logfile);
check_session_log_rotation();
m_file_check_timer.restart();
}
// In this case there is no need to write the session number into the files.
@ -486,17 +491,17 @@ int QlaFilterSession::routeQuery(GWBUF* queue)
{
const uint32_t data_flags = m_instance.m_settings.log_file_data_flags;
LogEventData& event = m_event_data;
if (data_flags & LOG_DATA_DATE)
if (data_flags & QlaInstance::LOG_DATA_DATE)
{
// Print current date to a buffer. Use the buffer in the event data struct even if execution time
// is not needed.
const time_t utc_seconds = time(NULL);
tm local_time;
localtime_r(&utc_seconds, &local_time);
strftime(event.query_date, QLA_DATE_BUFFER_SIZE, "%F %T", &local_time);
strftime(event.query_date, LogEventData::DATE_BUF_SIZE, "%F %T", &local_time);
}
if (data_flags & LOG_DATA_REPLY_TIME)
if (data_flags & QlaInstance::LOG_DATA_REPLY_TIME)
{
// Have to measure reply time from server. Save query data for printing during clientReply.
// If old event data exists, it is erased. This only happens if client sends a query before
@ -506,7 +511,7 @@ int QlaFilterSession::routeQuery(GWBUF* queue)
event.clear();
}
clock_gettime(CLOCK_MONOTONIC, &event.begin_time);
if (data_flags & LOG_DATA_QUERY)
if (data_flags & QlaInstance::LOG_DATA_QUERY)
{
event.query_clone = gwbuf_clone(queue);
}
@ -528,11 +533,11 @@ int QlaFilterSession::clientReply(GWBUF* queue)
if (event.has_message)
{
const uint32_t data_flags = m_instance.m_settings.log_file_data_flags;
mxb_assert(data_flags & LOG_DATA_REPLY_TIME);
mxb_assert(data_flags & QlaInstance::LOG_DATA_REPLY_TIME);
char* query = NULL;
int query_len = 0;
if (data_flags & LOG_DATA_QUERY)
if (data_flags & QlaInstance::LOG_DATA_QUERY)
{
modutil_extract_SQL(event.query_clone, &query, &query_len);
}
@ -549,41 +554,64 @@ int QlaFilterSession::clientReply(GWBUF* queue)
return up.clientReply(up.instance, up.session, queue);
}
FILE* QlaInstance::open_log_file(uint32_t data_flags, const string& fname)
FILE* QlaInstance::open_session_log_file(const string& filename) const
{
auto filename = fname.c_str();
return open_log_file(m_session_data_flags, filename);
}
bool QlaInstance::open_unified_logfile()
{
mxb_assert(!m_unified_fp);
m_unified_fp = open_log_file(m_settings.log_file_data_flags, m_unified_filename);
return m_unified_fp != nullptr;
}
/**
* Open a log file for writing and print a header if file did not exist.
*
* @param data_flags Data save settings flags
* @param filename Target file path
* @return A valid file on success, null otherwise.
*/
FILE* QlaInstance::open_log_file(uint64_t data_flags, const string& filename) const
{
auto zfilename = filename.c_str();
bool file_existed = false;
FILE* fp = NULL;
if (m_settings.append == false)
{
// Just open the file (possibly overwriting) and then print header.
fp = fopen(filename, "w");
fp = fopen(zfilename, "w");
}
else
{
/**
* Using fopen() with 'a+' means we will always write to the end but can read
* anywhere. Depending on the "append"-setting the file has been
* opened in different modes, which should be considered if file handling
* changes later (e.g. rewinding).
* anywhere.
*/
if ((fp = fopen(filename, "a+")) != NULL)
if ((fp = fopen(zfilename, "a+")) != NULL)
{
// Check to see if file already has contents
fseek(fp, 0, SEEK_END);
if (ftell(fp) > 0) // Any errors in ftell cause overwriting
if (ftell(fp) > 0)
{
file_existed = true;
}
}
}
if (fp && !file_existed && data_flags != 0)
if (!fp)
{
MXS_ERROR("Failed to open file '%s'. Error %i: '%s'.", zfilename, errno, mxs_strerror(errno));
}
else if (!file_existed && data_flags != 0)
{
string header = generate_log_header(data_flags);
if (!write_to_logfile(&fp, header))
if (!write_to_logfile(fp, header))
{
MXS_ERROR("Failed to print header to file %s.", filename);
MXS_ERROR(HEADER_ERROR, zfilename, errno, mxs_strerror(errno));
fclose(fp);
fp = nullptr;
}
}
return fp;
@ -636,27 +664,19 @@ string QlaInstance::generate_log_header(uint64_t data_flags) const
return header.str();
}
bool QlaInstance::write_to_logfile(FILE** ppLogFile, const std::string& contents)
bool QlaInstance::write_to_logfile(FILE* fp, const std::string& contents) const
{
bool error = false;
auto pFile = *ppLogFile;
int written = fprintf(pFile, "%s", contents.c_str());
int written = fprintf(fp, "%s", contents.c_str());
if (written < 0)
{
error = true;
}
else if (m_settings.flush_writes && (fflush(pFile) != 0))
else if (m_settings.flush_writes && (fflush(fp) != 0))
{
error = true;
}
// Writing or flushing failed. Close file.
if (error)
{
fclose(pFile);
pFile = nullptr;
*ppLogFile = pFile;
}
return !error;
}
@ -739,32 +759,32 @@ bool QlaFilterSession::write_log_entry(FILE* logfile, uint32_t data_flags, const
string curr_sep; // Use empty string as the first separator
const string& real_sep = m_instance.m_settings.separator;
if (data_flags & LOG_DATA_SERVICE)
if (data_flags & QlaInstance::LOG_DATA_SERVICE)
{
output << m_service;
curr_sep = real_sep;
}
if (data_flags & LOG_DATA_SESSION)
if (data_flags & QlaInstance::LOG_DATA_SESSION)
{
output << curr_sep << m_ses_id;
curr_sep = real_sep;
}
if (data_flags & LOG_DATA_DATE)
if (data_flags & QlaInstance::LOG_DATA_DATE)
{
output << curr_sep << time_string;
curr_sep = real_sep;
}
if (data_flags & LOG_DATA_USER)
if (data_flags & QlaInstance::LOG_DATA_USER)
{
output << curr_sep << m_user << "@" << m_remote;
curr_sep = real_sep;
}
if (data_flags & LOG_DATA_REPLY_TIME)
if (data_flags & QlaInstance::LOG_DATA_REPLY_TIME)
{
output << curr_sep << elapsed_ms;
curr_sep = real_sep;
}
if (data_flags & LOG_DATA_QUERY)
if (data_flags & QlaInstance::LOG_DATA_QUERY)
{
output << curr_sep;
if (!m_instance.m_settings.query_newline.empty())
@ -781,7 +801,7 @@ bool QlaFilterSession::write_log_entry(FILE* logfile, uint32_t data_flags, const
}
output << "\n";
return m_instance.write_to_logfile(&logfile, output.str());
return m_instance.write_to_logfile(logfile, output.str());
}
namespace

105
server/modules/filter/qlafilter/qlafilter.hh
View File

@ -21,44 +21,8 @@
#include <maxscale/filter.hh>
#include <maxscale/pcre2.h>
/* Date string buffer size */
#define QLA_DATE_BUFFER_SIZE 20
class QlaFilterSession;
/**
* Helper struct for holding data before it's written to file.
*/
class LogEventData
{
public:
LogEventData(const LogEventData&) = delete;
LogEventData& operator=(const LogEventData&) = default;
LogEventData() = default;
~LogEventData()
{
mxb_assert(query_clone == NULL);
}
/**
* Resets event data.
*
* @param event Event to reset
*/
void clear()
{
gwbuf_free(query_clone);
*this = LogEventData();
}
bool has_message {false}; // Does message data exist?
GWBUF* query_clone {nullptr}; // Clone of the query buffer.
char query_date[QLA_DATE_BUFFER_SIZE]; // Text representation of date.
timespec begin_time {0, 0}; // Timer value at the moment of receiving query.
};
/**
* A instance structure, the assumption is that the option passed
* to the filter is simply a base for the filename to which the queries
@ -76,6 +40,18 @@ public:
QlaInstance(const std::string& name, MXS_CONFIG_PARAMETER* params);
~QlaInstance();
/* Log file save mode flags. */
static const int64_t LOG_FILE_SESSION = (1 << 0); /**< Default value, session specific files */
static const int64_t LOG_FILE_UNIFIED = (1 << 1); /**< One file shared by all sessions */
/* Flags for controlling extra log entry contents */
static const int64_t LOG_DATA_SERVICE = (1 << 0);
static const int64_t LOG_DATA_SESSION = (1 << 1);
static const int64_t LOG_DATA_DATE = (1 << 2);
static const int64_t LOG_DATA_USER = (1 << 3);
static const int64_t LOG_DATA_QUERY = (1 << 4);
static const int64_t LOG_DATA_REPLY_TIME = (1 << 5);
/**
* Associate a new session with this instance of the filter. Creates a session-specific logfile.
*
@ -106,18 +82,10 @@ public:
void diagnostics(DCB* dcb) const;
json_t* diagnostics_json() const;
/**
* Open the log file and print a header if appropriate.
*
* @param data_flags Data save settings flags
* @param fname Target file path
* @return A valid file on success, null otherwise.
*/
FILE* open_log_file(uint32_t data_flags, const std::string& fname);
std::string generate_log_header(uint64_t data_flags) const;
bool write_to_logfile(FILE** ppFile, const std::string& contents);
FILE* open_session_log_file(const std::string& filename) const;
bool write_to_logfile(FILE* fp, const std::string& contents) const;
class Settings
{
@ -152,14 +120,18 @@ public:
uint64_t m_session_data_flags {0}; /* What data is printed to session files */
bool m_write_warning_given {false}; /* Avoid repeatedly printing some errors/warnings. */
private:
bool open_unified_logfile();
FILE* open_log_file(uint64_t data_flags, const std::string& filename) const;
};
/* The session structure for this QLA filter. */
class QlaFilterSession : public MXS_FILTER_SESSION
{
public:
QlaFilterSession(const QlaFilterSession&);
QlaFilterSession& operator=(const QlaFilterSession&);
QlaFilterSession(const QlaFilterSession&) = delete;
QlaFilterSession& operator=(const QlaFilterSession&) = delete;
QlaFilterSession(QlaInstance& instance, MXS_SESSION* session);
~QlaFilterSession();
@ -209,9 +181,44 @@ private:
FILE* m_logfile {nullptr}; /* The session-specific log file */
mxb::StopWatch m_file_check_timer; /* When was file checked for rotation */
/**
* Helper struct for holding data before it's written to file.
*/
class LogEventData
{
public:
LogEventData(const LogEventData&) = delete;
LogEventData& operator=(const LogEventData&) = default;
LogEventData() = default;
~LogEventData()
{
mxb_assert(query_clone == NULL);
}
/* Date string buffer size */
static const int DATE_BUF_SIZE = 20;
/**
* Resets event data.
*
* @param event Event to reset
*/
void clear()
{
gwbuf_free(query_clone);
*this = LogEventData();
}
bool has_message {false}; // Does message data exist?
GWBUF* query_clone {nullptr}; // Clone of the query buffer.
char query_date[DATE_BUF_SIZE] {'\0'}; // Text representation of date.
timespec begin_time {0, 0}; // Timer value at the moment of receiving query.
};
LogEventData m_event_data; /* Information about the latest event, used if logging execution time. */
void check_session_log_rotation(const std::string& filename, FILE** ppFile);
void check_session_log_rotation();
void write_log_entries(const char* date_string, const char* query, int querylen, int elapsed_ms);
bool write_log_entry(FILE* logfile, uint32_t data_flags, const char* time_string,
const char* sql_string, size_t sql_str_len, int elapsed_ms);