855 lines
28 KiB
C++
855 lines
28 KiB
C++
/*
|
|
* Copyright (C) 2009 Patrick Ohly <patrick.ohly@gmx.de>
|
|
* Copyright (C) 2009 Intel Corporation
|
|
*
|
|
* This library is free software; you can redistribute it and/or
|
|
* modify it under the terms of the GNU Lesser General Public
|
|
* License as published by the Free Software Foundation; either
|
|
* version 2.1 of the License, or (at your option) version 3.
|
|
*
|
|
* This library is distributed in the hope that it will be useful,
|
|
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
|
|
* Lesser General Public License for more details.
|
|
*
|
|
* You should have received a copy of the GNU Lesser General Public
|
|
* License along with this library; if not, write to the Free Software
|
|
* Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
|
|
* 02110-1301 USA
|
|
*/
|
|
|
|
#include "config.h"
|
|
#include <syncevo/LogRedirect.h>
|
|
#include <syncevo/Logging.h>
|
|
#include "test.h"
|
|
#include <syncevo/util.h>
|
|
#include <sys/types.h>
|
|
#include <sys/socket.h>
|
|
#include <netinet/in.h>
|
|
#include <arpa/inet.h>
|
|
#include <unistd.h>
|
|
#include <sys/stat.h>
|
|
#include <fcntl.h>
|
|
#include <signal.h>
|
|
#include <errno.h>
|
|
|
|
#include <boost/algorithm/string/find_iterator.hpp>
|
|
#include <boost/algorithm/string/predicate.hpp>
|
|
#include <boost/noncopyable.hpp>
|
|
|
|
#include <algorithm>
|
|
#include <iostream>
|
|
|
|
#ifdef HAVE_GLIB
|
|
# include <glib.h>
|
|
#endif
|
|
|
|
|
|
#include <syncevo/declarations.h>
|
|
SE_BEGIN_CXX
|
|
|
|
LogRedirect *LogRedirect::m_redirect;
|
|
std::set<std::string> LogRedirect::m_knownErrors;
|
|
|
|
void LogRedirect::abortHandler(int sig) throw()
|
|
{
|
|
// Don't know state of logging system, don't log here!
|
|
// SE_LOG_ERROR(NULL, "caught signal %d, shutting down", sig);
|
|
|
|
// Shut down redirection, also flushes to log. This involves
|
|
// unsafe calls. For example, we may have to allocate new memory,
|
|
// which deadlocks if glib detected memory corruption and
|
|
// called abort() (see FDO #76375).
|
|
//
|
|
// But flushing the log is the whole point of the abortHandler, so
|
|
// we can't just skip this. To handle cases where the work that we
|
|
// need to do fails, we set a timeout and let the process be
|
|
// killed that way. alarm() and sigaction() are async-signal-safe.
|
|
{
|
|
struct sigaction new_action, old_action;
|
|
memset(&new_action, 0, sizeof(new_action));
|
|
new_action.sa_handler = SIG_DFL; // Terminates the process.
|
|
sigemptyset(&new_action.sa_mask);
|
|
sigaction(SIGALRM, &new_action, &old_action);
|
|
alarm(5);
|
|
|
|
RecMutex::Guard guard = lock();
|
|
if (m_redirect) {
|
|
m_redirect->restore();
|
|
}
|
|
}
|
|
|
|
// Raise same signal again. Because our handler
|
|
// is automatically removed, this will abort
|
|
// for real now.
|
|
raise(sig);
|
|
}
|
|
|
|
void LogRedirect::init()
|
|
{
|
|
m_processing = false;
|
|
m_buffer = nullptr;
|
|
m_len = 0;
|
|
m_out = nullptr;
|
|
m_err = nullptr;
|
|
m_streams = false;
|
|
m_stderr.m_original =
|
|
m_stderr.m_read =
|
|
m_stderr.m_write =
|
|
m_stderr.m_copy = -1;
|
|
m_stdout.m_original =
|
|
m_stdout.m_read =
|
|
m_stdout.m_write =
|
|
m_stdout.m_copy = -1;
|
|
|
|
const char *lines = getenv("SYNCEVOLUTION_SUPPRESS_ERRORS");
|
|
if (lines) {
|
|
for (const auto &match: make_iterator_range(boost::make_split_iterator(lines, boost::first_finder("\n", boost::is_iequal())))) {
|
|
m_knownErrors.insert(std::string(match.begin(), match.end()));
|
|
}
|
|
}
|
|
|
|
// CONSOLEPRINTF in libsynthesis.
|
|
m_knownErrors.insert("SYSYNC Rejected with error:");
|
|
// libneon 'Request ends, status 207 class 2xx, error line:'
|
|
m_knownErrors.insert("xx, error line:\n");
|
|
// some internal Qt warning (?)
|
|
m_knownErrors.insert("Qt: Session management error: None of the authentication protocols specified are supported");
|
|
}
|
|
|
|
LogRedirect::LogRedirect(Mode mode, const char *filename)
|
|
{
|
|
init();
|
|
m_processing = true;
|
|
if (!getenv("SYNCEVOLUTION_DEBUG")) {
|
|
redirect(STDERR_FILENO, m_stderr);
|
|
if (mode == STDERR_AND_STDOUT) {
|
|
redirect(STDOUT_FILENO, m_stdout);
|
|
m_out = filename ?
|
|
fopen(filename, "w") :
|
|
fdopen(dup(m_stdout.m_copy), "w");
|
|
if (!m_out) {
|
|
restore(m_stdout);
|
|
restore(m_stderr);
|
|
perror(filename ? filename : "LogRedirect fdopen");
|
|
}
|
|
} else if (filename) {
|
|
m_out = fopen(filename, "w");
|
|
if (!m_out) {
|
|
perror(filename);
|
|
}
|
|
}
|
|
// Separate FILE, will write into same file as normal output
|
|
// if a filename was given (for testing), otherwise to original
|
|
// stderr.
|
|
m_err = fdopen(dup((filename && m_out) ?
|
|
fileno(m_out) :
|
|
m_stderr.m_copy), "w");
|
|
}
|
|
|
|
// Modify process state while holding the Logger mutex.
|
|
RecMutex::Guard guard = lock();
|
|
if (m_redirect) {
|
|
SE_LOG_WARNING(NULL, "LogRedirect already instantiated?!");
|
|
}
|
|
m_redirect = this;
|
|
|
|
if (!getenv("SYNCEVOLUTION_DEBUG")) {
|
|
struct sigaction new_action, old_action;
|
|
memset(&new_action, 0, sizeof(new_action));
|
|
new_action.sa_handler = abortHandler;
|
|
sigemptyset(&new_action.sa_mask);
|
|
// disable handler after it was called once
|
|
new_action.sa_flags = SA_RESETHAND;
|
|
// block signals while we handler is active
|
|
// to prevent recursive calls
|
|
sigaddset(&new_action.sa_mask, SIGABRT);
|
|
sigaddset(&new_action.sa_mask, SIGSEGV);
|
|
sigaddset(&new_action.sa_mask, SIGBUS);
|
|
sigaction(SIGABRT, &new_action, &old_action);
|
|
sigaction(SIGSEGV, &new_action, &old_action);
|
|
sigaction(SIGBUS, &new_action, &old_action);
|
|
}
|
|
m_processing = false;
|
|
}
|
|
|
|
LogRedirect::LogRedirect(ExecuteFlags flags)
|
|
{
|
|
init();
|
|
|
|
// This instance does not modify process state and
|
|
// doesn't have to be thread-safe.
|
|
m_streams = true;
|
|
if (!(flags & EXECUTE_NO_STDERR)) {
|
|
redirect(STDERR_FILENO, m_stderr);
|
|
}
|
|
if (!(flags & EXECUTE_NO_STDOUT)) {
|
|
redirect(STDOUT_FILENO, m_stdout);
|
|
}
|
|
}
|
|
|
|
LogRedirect::~LogRedirect() throw()
|
|
{
|
|
RecMutex::Guard guard;
|
|
if (!m_streams) {
|
|
guard = lock();
|
|
}
|
|
if (m_redirect == this) {
|
|
m_redirect = nullptr;
|
|
}
|
|
process();
|
|
restore();
|
|
m_processing = true;
|
|
if (m_out) {
|
|
fclose(m_out);
|
|
}
|
|
if (m_err) {
|
|
fclose(m_err);
|
|
}
|
|
if (m_buffer) {
|
|
free(m_buffer);
|
|
}
|
|
}
|
|
|
|
void LogRedirect::remove() throw()
|
|
{
|
|
restore();
|
|
}
|
|
|
|
void LogRedirect::removeRedirect() throw()
|
|
{
|
|
if (m_redirect) {
|
|
// We were forked. Ignore mutex (might be held by thread which was not
|
|
// forked) and restore the forked process' state to the one it was
|
|
// before setting up redirection.
|
|
//
|
|
// Do the minimal amount of work possible in restore(), i.e.,
|
|
// suppress the processing of streams.
|
|
m_redirect->m_streams = false;
|
|
|
|
m_redirect->restore(m_redirect->m_stdout);
|
|
m_redirect->restore(m_redirect->m_stderr);
|
|
}
|
|
}
|
|
|
|
void LogRedirect::restore() throw()
|
|
{
|
|
RecMutex::Guard guard;
|
|
if (!m_streams) {
|
|
guard = lock();
|
|
}
|
|
|
|
if (m_processing) {
|
|
return;
|
|
}
|
|
m_processing = true;
|
|
|
|
restore(m_stdout);
|
|
restore(m_stderr);
|
|
|
|
m_processing = false;
|
|
}
|
|
|
|
void LogRedirect::messagev(const MessageOptions &options,
|
|
const char *format,
|
|
va_list args)
|
|
{
|
|
RecMutex::Guard guard = lock();
|
|
|
|
// check for other output first
|
|
process();
|
|
if (!(options.m_flags & MessageOptions::ONLY_GLOBAL_LOG)) {
|
|
// Choose output channel: SHOW goes to original stdout,
|
|
// everything else to stderr.
|
|
LoggerStdout::write(options.m_level == SHOW ?
|
|
(m_out ? m_out : stdout) :
|
|
(m_err ? m_err : stderr),
|
|
options.m_level, getLevel(),
|
|
options.m_prefix,
|
|
options.m_processName,
|
|
format,
|
|
args);
|
|
}
|
|
}
|
|
|
|
void LogRedirect::redirect(int original, FDs &fds) throw()
|
|
{
|
|
fds.m_original = original;
|
|
fds.m_write = fds.m_read = -1;
|
|
fds.m_copy = dup(fds.m_original);
|
|
if (fds.m_copy >= 0) {
|
|
if (m_streams) {
|
|
// According to Stevens, Unix Network Programming, "Unix
|
|
// domain datagram sockets are similar to UDP sockets: the
|
|
// provide an *unreliable* datagram service that preserves
|
|
// record boundaries." (14.4 Socket Functions,
|
|
// p. 378). But unit tests showed that they do block on
|
|
// Linux and thus seem reliable. Not sure what the official
|
|
// spec is.
|
|
//
|
|
// To avoid the deadlock risk, we must use UDP. But when we
|
|
// want "reliable" behavior *and* detect that all output was
|
|
// processed, we have to use streams despite loosing
|
|
// the write() boundaries, because Unix domain datagram sockets
|
|
// do not flag "end of data".
|
|
int sockets[2];
|
|
#define USE_UNIX_DOMAIN_DGRAM 0
|
|
if (!socketpair(AF_LOCAL,
|
|
USE_UNIX_DOMAIN_DGRAM ? SOCK_DGRAM : SOCK_STREAM,
|
|
0, sockets)) {
|
|
// success
|
|
fds.m_write = sockets[0];
|
|
fds.m_read = sockets[1];
|
|
return;
|
|
} else {
|
|
perror("LogRedirect::redirect() socketpair");
|
|
}
|
|
} else {
|
|
int write = socket(AF_INET, SOCK_DGRAM, 0);
|
|
if (write >= 0) {
|
|
int read = socket(AF_INET, SOCK_DGRAM, 0);
|
|
if (read >= 0) {
|
|
struct sockaddr_in addr;
|
|
memset(&addr, 0, sizeof(addr));
|
|
addr.sin_family = AF_INET;
|
|
addr.sin_addr.s_addr = inet_addr("127.0.0.1");
|
|
bool bound = false;
|
|
for (int port = 1025; !bound && port < 10000; port++) {
|
|
addr.sin_port = htons(port);
|
|
if (!bind(read, (struct sockaddr *)&addr, sizeof(addr))) {
|
|
bound = true;
|
|
}
|
|
}
|
|
|
|
if (bound) {
|
|
if (!connect(write, (struct sockaddr *)&addr, sizeof(addr))) {
|
|
if (dup2(write, fds.m_original) >= 0) {
|
|
// success
|
|
fds.m_write = write;
|
|
fds.m_read = read;
|
|
return;
|
|
}
|
|
perror("LogRedirect::redirect() dup2");
|
|
}
|
|
perror("LogRedirect::redirect connect");
|
|
}
|
|
close(read);
|
|
}
|
|
close(write);
|
|
}
|
|
}
|
|
close(fds.m_copy);
|
|
fds.m_copy = -1;
|
|
} else {
|
|
perror("LogRedirect::redirect() dup");
|
|
}
|
|
}
|
|
|
|
void LogRedirect::restore(FDs &fds) throw()
|
|
{
|
|
if (!m_streams && fds.m_copy >= 0) {
|
|
// flush our own redirected output and process what they might have written
|
|
if (fds.m_original == STDOUT_FILENO) {
|
|
fflush(stdout);
|
|
std::cout << std::flush;
|
|
} else {
|
|
fflush(stderr);
|
|
std::cerr << std::flush;
|
|
}
|
|
process(fds);
|
|
|
|
dup2(fds.m_copy, fds.m_original);
|
|
}
|
|
|
|
if (fds.m_copy >= 0) {
|
|
close(fds.m_copy);
|
|
}
|
|
if (fds.m_write >= 0) {
|
|
close(fds.m_write);
|
|
}
|
|
if (fds.m_read >= 0) {
|
|
close(fds.m_read);
|
|
}
|
|
fds.m_copy =
|
|
fds.m_write =
|
|
fds.m_read = -1;
|
|
}
|
|
|
|
bool LogRedirect::process(FDs &fds) throw()
|
|
{
|
|
bool have_message;
|
|
bool data_read = false;
|
|
|
|
if (fds.m_read <= 0) {
|
|
return data_read;
|
|
}
|
|
|
|
ssize_t available = 0;
|
|
do {
|
|
have_message = false;
|
|
|
|
// keep peeking at the data with increasing buffer sizes until
|
|
// we are sure that we don't truncate it
|
|
size_t newlen = std::max((size_t)1024, m_len);
|
|
while (true) {
|
|
// increase buffer?
|
|
if (newlen > m_len) {
|
|
void *buffer = realloc(m_buffer, newlen);
|
|
if (!buffer) {
|
|
// Nothing changed.
|
|
if (available) {
|
|
// We already read some data of a
|
|
// datagram. Give up on the rest of the data,
|
|
// process what we have below.
|
|
if ((size_t)available == m_len) {
|
|
// Need the byte for nul termination.
|
|
available--;
|
|
}
|
|
have_message = true;
|
|
break;
|
|
} else {
|
|
// Give up.
|
|
Exception::throwError(SE_HERE, "out of memory");
|
|
return false;
|
|
}
|
|
} else {
|
|
m_buffer = (char *)buffer;
|
|
m_len = newlen;
|
|
}
|
|
}
|
|
// read, but leave space for nul byte;
|
|
// when using datagrams, we only peek here and remove the
|
|
// datagram below, without rereading the data
|
|
if (!USE_UNIX_DOMAIN_DGRAM && m_streams) {
|
|
available = recv(fds.m_read, m_buffer, m_len - 1, MSG_DONTWAIT);
|
|
if (available == 0) {
|
|
return data_read;
|
|
} else if (available == -1) {
|
|
if (errno == EAGAIN) {
|
|
// pretend that data was read, so that caller invokes us again
|
|
return true;
|
|
} else {
|
|
Exception::throwError(SE_HERE, "reading output", errno);
|
|
return false;
|
|
}
|
|
} else {
|
|
// data read, process it
|
|
data_read = true;
|
|
break;
|
|
}
|
|
} else {
|
|
available = recv(fds.m_read, m_buffer, m_len - 1, MSG_DONTWAIT|MSG_PEEK);
|
|
have_message = available >= 0;
|
|
}
|
|
if (available < (ssize_t)m_len - 1) {
|
|
break;
|
|
} else {
|
|
// try again with twice the buffer
|
|
newlen *= 2;
|
|
}
|
|
}
|
|
if (have_message) {
|
|
if (USE_UNIX_DOMAIN_DGRAM || !m_streams) {
|
|
// swallow packet, even if empty or we couldn't receive it
|
|
recv(fds.m_read, nullptr, 0, MSG_DONTWAIT);
|
|
}
|
|
data_read = true;
|
|
}
|
|
|
|
if (available > 0) {
|
|
m_buffer[available] = 0;
|
|
// Now pass it to logger, with a level determined by
|
|
// the channel. This is the point where we can filter
|
|
// out known noise.
|
|
std::string prefix;
|
|
Logger::Level level = Logger::DEV;
|
|
char *text = m_buffer;
|
|
|
|
if (fds.m_original == STDOUT_FILENO) {
|
|
// stdout: not sure what this could be, so show it
|
|
level = Logger::SHOW;
|
|
char *eol = strchr(text, '\n');
|
|
if (!m_stdoutData.empty()) {
|
|
// try to complete previous line, can be done
|
|
// if text contains a line break
|
|
if (eol) {
|
|
m_stdoutData.append(text, eol - text);
|
|
text = eol + 1;
|
|
Logger::instance().message(level, prefix.empty() ? nullptr : &prefix,
|
|
nullptr, 0, nullptr,
|
|
"%s", m_stdoutData.c_str());
|
|
m_stdoutData.clear();
|
|
}
|
|
}
|
|
|
|
// avoid sending incomplete line at end of text,
|
|
// must be done when there is no line break or
|
|
// it is not at the end of the buffer
|
|
eol = strrchr(text, '\n');
|
|
if (eol != m_buffer + available - 1) {
|
|
if (eol) {
|
|
m_stdoutData.append(eol + 1);
|
|
*eol = 0;
|
|
} else {
|
|
m_stdoutData.append(text);
|
|
*text = 0;
|
|
}
|
|
}
|
|
|
|
// output might have been processed as part of m_stdoutData,
|
|
// don't log empty string below
|
|
if (!*text) {
|
|
continue;
|
|
}
|
|
} else if (fds.m_original == STDERR_FILENO) {
|
|
// stderr: not normally useful for users, so we
|
|
// can filter it more aggressively. For example,
|
|
// swallow extra line breaks, glib inserts those.
|
|
while (*text == '\n') {
|
|
text++;
|
|
}
|
|
const char *glib_debug_prefix = "** ("; // ** (client-test:875): WARNING **:
|
|
const char *glib_msg_prefix = "** Message:";
|
|
prefix = "stderr";
|
|
if ((!strncmp(text, glib_debug_prefix, strlen(glib_debug_prefix)) &&
|
|
strstr(text, " **:")) ||
|
|
!strncmp(text, glib_msg_prefix, strlen(glib_msg_prefix))) {
|
|
level = Logger::DEBUG;
|
|
prefix = "glib";
|
|
} else {
|
|
level = Logger::DEV;
|
|
}
|
|
|
|
// If the text contains the word "error", it probably
|
|
// is severe enough to show to the user, regardless of
|
|
// who produced it... except for errors suppressed
|
|
// explicitly.
|
|
if (strcasestr(text, "error") &&
|
|
!ignoreError(text)) {
|
|
level = Logger::ERROR;
|
|
}
|
|
}
|
|
|
|
// avoid explicit newline at end of output,
|
|
// logging will add it for each message()
|
|
// invocation
|
|
size_t len = strlen(text);
|
|
if (len > 0 && text[len - 1] == '\n') {
|
|
text[len - 1] = 0;
|
|
}
|
|
Logger::instance().message(level, prefix.empty() ? nullptr : &prefix,
|
|
nullptr, 0, nullptr,
|
|
"%s", text);
|
|
available = 0;
|
|
}
|
|
} while(have_message);
|
|
|
|
return data_read;
|
|
}
|
|
|
|
void LogRedirect::addIgnoreError(const std::string &error)
|
|
{
|
|
RecMutex::Guard guard = Logger::lock();
|
|
m_knownErrors.insert(error);
|
|
}
|
|
|
|
bool LogRedirect::ignoreError(const std::string &text)
|
|
{
|
|
RecMutex::Guard guard = Logger::lock();
|
|
for (const std::string &entry: m_knownErrors) {
|
|
if (text.find(entry) != text.npos) {
|
|
return true;
|
|
}
|
|
}
|
|
return false;
|
|
}
|
|
|
|
void LogRedirect::process()
|
|
{
|
|
RecMutex::Guard guard;
|
|
|
|
if (m_streams) {
|
|
// iterate until both sockets are closed by peer
|
|
while (true) {
|
|
fd_set readfds;
|
|
fd_set errfds;
|
|
int maxfd = 0;
|
|
FD_ZERO(&readfds);
|
|
FD_ZERO(&errfds);
|
|
if (m_stdout.m_read >= 0) {
|
|
FD_SET(m_stdout.m_read, &readfds);
|
|
FD_SET(m_stdout.m_read, &errfds);
|
|
maxfd = m_stdout.m_read;
|
|
}
|
|
if (m_stderr.m_read >= 0) {
|
|
FD_SET(m_stderr.m_read, &readfds);
|
|
FD_SET(m_stderr.m_read, &errfds);
|
|
if (m_stderr.m_read > maxfd) {
|
|
maxfd = m_stderr.m_read;
|
|
}
|
|
}
|
|
if (maxfd == 0) {
|
|
// both closed
|
|
return;
|
|
}
|
|
|
|
int res = select(maxfd + 1, &readfds, nullptr, &errfds, nullptr);
|
|
switch (res) {
|
|
case -1:
|
|
// fatal, cannot continue
|
|
Exception::throwError(SE_HERE, "waiting for output", errno);
|
|
return;
|
|
break;
|
|
case 0:
|
|
// None ready? Try again.
|
|
break;
|
|
default:
|
|
if (m_stdout.m_read >= 0 && FD_ISSET(m_stdout.m_read, &readfds)) {
|
|
if (!process(m_stdout)) {
|
|
// Exact status of a Unix domain datagram socket upon close
|
|
// of the remote end is a bit uncertain. For TCP, we would end
|
|
// up here: marked by select as "ready for read", but no data -> EOF.
|
|
close(m_stdout.m_read);
|
|
m_stdout.m_read = -1;
|
|
}
|
|
}
|
|
if (m_stdout.m_read >= 0 && FD_ISSET(m_stdout.m_read, &errfds)) {
|
|
// But in practice, Unix domain sockets don't mark the stream
|
|
// as "closed". This is an attempt to detect that situation
|
|
// via the FDs exception status, but that also doesn't work.
|
|
close(m_stdout.m_read);
|
|
m_stdout.m_read = -1;
|
|
}
|
|
if (m_stderr.m_read >= 0 && FD_ISSET(m_stderr.m_read, &readfds)) {
|
|
if (!process(m_stderr)) {
|
|
close(m_stderr.m_read);
|
|
m_stderr.m_read = -1;
|
|
}
|
|
}
|
|
if (m_stderr.m_read >= 0 && FD_ISSET(m_stderr.m_read, &errfds)) {
|
|
close(m_stderr.m_read);
|
|
m_stderr.m_read = -1;
|
|
}
|
|
break;
|
|
}
|
|
}
|
|
} else {
|
|
guard = lock();
|
|
}
|
|
|
|
if (m_processing) {
|
|
return;
|
|
}
|
|
m_processing = true;
|
|
|
|
process(m_stdout);
|
|
process(m_stderr);
|
|
|
|
// avoid hanging onto excessive amounts of memory
|
|
m_len = std::min((size_t)(4 * 1024), m_len);
|
|
m_buffer = (char *)realloc(m_buffer, m_len);
|
|
if (!m_buffer) {
|
|
m_len = 0;
|
|
}
|
|
|
|
m_processing = false;
|
|
}
|
|
|
|
|
|
|
|
void LogRedirect::flush() throw()
|
|
{
|
|
RecMutex::Guard guard = lock();
|
|
|
|
process();
|
|
if (!m_stdoutData.empty()) {
|
|
std::string buffer;
|
|
std::swap(buffer, m_stdoutData);
|
|
Logger::instance().message(Logger::SHOW, nullptr,
|
|
nullptr, 0, nullptr,
|
|
"%s", buffer.c_str());
|
|
}
|
|
}
|
|
|
|
|
|
#ifdef ENABLE_UNIT_TESTS
|
|
|
|
class LogRedirectTest : public CppUnit::TestFixture {
|
|
CPPUNIT_TEST_SUITE(LogRedirectTest);
|
|
CPPUNIT_TEST(simple);
|
|
CPPUNIT_TEST(largeChunk);
|
|
CPPUNIT_TEST(streams);
|
|
CPPUNIT_TEST(overload);
|
|
#ifdef HAVE_GLIB
|
|
CPPUNIT_TEST(glib);
|
|
#endif
|
|
CPPUNIT_TEST_SUITE_END();
|
|
|
|
/**
|
|
* redirect stdout/stderr, then intercept the log messages and
|
|
* store them for inspection
|
|
*/
|
|
class LogBuffer : public Logger, private boost::noncopyable
|
|
{
|
|
public:
|
|
std::stringstream m_streams[DEBUG + 1];
|
|
PushLogger<LogRedirect> m_redirect;
|
|
|
|
LogBuffer(LogRedirect::Mode mode = LogRedirect::STDERR_AND_STDOUT)
|
|
{
|
|
m_redirect.reset(new LogRedirect(mode));
|
|
addLogger(std::shared_ptr<Logger>(this, NopDestructor()));
|
|
}
|
|
~LogBuffer()
|
|
{
|
|
removeLogger(this);
|
|
m_redirect.reset();
|
|
}
|
|
|
|
virtual void messagev(const MessageOptions &options,
|
|
const char *format,
|
|
va_list args)
|
|
{
|
|
CPPUNIT_ASSERT(options.m_level <= DEBUG && options.m_level >= 0);
|
|
m_streams[options.m_level] << StringPrintfV(format, args);
|
|
}
|
|
};
|
|
|
|
public:
|
|
void simple()
|
|
{
|
|
LogBuffer buffer;
|
|
|
|
static const char *simpleMessage = "hello world";
|
|
CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(simpleMessage), write(STDOUT_FILENO, simpleMessage, strlen(simpleMessage)));
|
|
buffer.m_redirect->flush();
|
|
|
|
CPPUNIT_ASSERT_EQUAL(buffer.m_streams[Logger::SHOW].str(), std::string(simpleMessage));
|
|
}
|
|
|
|
void largeChunk()
|
|
{
|
|
LogBuffer buffer;
|
|
|
|
std::string large;
|
|
large.append(60 * 1024, 'h');
|
|
CPPUNIT_ASSERT_EQUAL((ssize_t)large.size(), write(STDOUT_FILENO, large.c_str(), large.size()));
|
|
buffer.m_redirect->flush();
|
|
|
|
CPPUNIT_ASSERT_EQUAL(large.size(), buffer.m_streams[Logger::SHOW].str().size());
|
|
CPPUNIT_ASSERT_EQUAL(large, buffer.m_streams[Logger::SHOW].str());
|
|
}
|
|
|
|
void streams()
|
|
{
|
|
LogBuffer buffer;
|
|
|
|
static const char *simpleMessage = "hello world";
|
|
CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(simpleMessage), write(STDOUT_FILENO, simpleMessage, strlen(simpleMessage)));
|
|
static const char *errorMessage = "such a cruel place";
|
|
CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(errorMessage), write(STDERR_FILENO, errorMessage, strlen(errorMessage)));
|
|
|
|
// process() keeps unfinished STDOUT lines buffered
|
|
buffer.m_redirect->process();
|
|
CPPUNIT_ASSERT_EQUAL(std::string(errorMessage), buffer.m_streams[Logger::DEV].str());
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), buffer.m_streams[Logger::SHOW].str());
|
|
|
|
// flush() makes them available
|
|
buffer.m_redirect->flush();
|
|
CPPUNIT_ASSERT_EQUAL(std::string(errorMessage), buffer.m_streams[Logger::DEV].str());
|
|
CPPUNIT_ASSERT_EQUAL(std::string(simpleMessage), buffer.m_streams[Logger::SHOW].str());
|
|
}
|
|
|
|
void overload()
|
|
{
|
|
LogBuffer buffer;
|
|
|
|
std::string large;
|
|
large.append(1024, 'h');
|
|
for (int i = 0; i < 4000; i++) {
|
|
CPPUNIT_ASSERT_EQUAL((ssize_t)large.size(), write(STDOUT_FILENO, large.c_str(), large.size()));
|
|
}
|
|
buffer.m_redirect->flush();
|
|
|
|
CPPUNIT_ASSERT(buffer.m_streams[Logger::SHOW].str().size() > large.size());
|
|
}
|
|
|
|
#ifdef HAVE_GLIB
|
|
void glib()
|
|
{
|
|
fflush(stdout);
|
|
fflush(stderr);
|
|
|
|
static const char *filename = "LogRedirectTest_glib.out";
|
|
int new_stdout = open(filename, O_RDWR|O_CREAT|O_TRUNC, S_IRWXU);
|
|
|
|
// check that intercept all glib message and don't print anything to stdout
|
|
int orig_stdout = -1;
|
|
try {
|
|
// need to restore the current state below; would be nice
|
|
// to query it instead of assuming that Logger::glogFunc
|
|
// is the current log handler
|
|
g_log_set_default_handler(g_log_default_handler, nullptr);
|
|
|
|
orig_stdout = dup(STDOUT_FILENO);
|
|
dup2(new_stdout, STDOUT_FILENO);
|
|
|
|
LogBuffer buffer(LogRedirect::STDERR);
|
|
|
|
fprintf(stdout, "normal message stdout\n");
|
|
fflush(stdout);
|
|
|
|
fprintf(stderr, "normal message stderr\n");
|
|
fflush(stderr);
|
|
|
|
// ** (process:13552): WARNING **: test warning
|
|
g_warning("test warning");
|
|
// ** Message: test message
|
|
g_message("test message");
|
|
// ** (process:13552): CRITICAL **: test critical
|
|
g_critical("test critical");
|
|
// would abort:
|
|
// g_error("error")
|
|
// ** (process:13552): DEBUG: test debug
|
|
g_debug("test debug");
|
|
|
|
buffer.m_redirect->process();
|
|
|
|
std::string error = buffer.m_streams[Logger::ERROR].str();
|
|
std::string warning = buffer.m_streams[Logger::WARNING].str();
|
|
std::string show = buffer.m_streams[Logger::SHOW].str();
|
|
std::string info = buffer.m_streams[Logger::INFO].str();
|
|
std::string dev = buffer.m_streams[Logger::DEV].str();
|
|
std::string debug = buffer.m_streams[Logger::DEBUG].str();
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), error);
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), warning);
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), show);
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), info);
|
|
CPPUNIT_ASSERT_EQUAL(std::string(""), error);
|
|
CPPUNIT_ASSERT(dev.find("normal message stderr") != dev.npos);
|
|
CPPUNIT_ASSERT(debug.find("test warning") != debug.npos);
|
|
} catch(...) {
|
|
g_log_set_default_handler(Logger::glogFunc, nullptr);
|
|
dup2(orig_stdout, STDOUT_FILENO);
|
|
throw;
|
|
}
|
|
g_log_set_default_handler(Logger::glogFunc, nullptr);
|
|
dup2(orig_stdout, STDOUT_FILENO);
|
|
|
|
lseek(new_stdout, 0, SEEK_SET);
|
|
char out[128];
|
|
ssize_t l = read(new_stdout, out, sizeof(out) - 1);
|
|
CPPUNIT_ASSERT(l > 0);
|
|
out[l] = 0;
|
|
CPPUNIT_ASSERT(boost::starts_with(std::string(out), "normal message stdout"));
|
|
}
|
|
#endif
|
|
};
|
|
|
|
SYNCEVOLUTION_TEST_SUITE_REGISTRATION(LogRedirectTest);
|
|
|
|
#endif // ENABLE_UNIT_TESTS
|
|
|
|
|
|
SE_END_CXX
|