src/syncevo/LogRedirect.cpp

   1 /*
   2  * Copyright (C) 2009 Patrick Ohly <patrick.ohly@gmx.de>
   3  * Copyright (C) 2009 Intel Corporation
   4  *
   5  * This library is free software; you can redistribute it and/or
   6  * modify it under the terms of the GNU Lesser General Public
   7  * License as published by the Free Software Foundation; either
   8  * version 2.1 of the License, or (at your option) version 3.
   9  *
  10  * This library is distributed in the hope that it will be useful,
  11  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  12  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  13  * Lesser General Public License for more details.
  14  *
  15  * You should have received a copy of the GNU Lesser General Public
  16  * License along with this library; if not, write to the Free Software
  17  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
  18  * 02110-1301  USA
  19  */
  20
  21 #include "config.h"
  22 #include <syncevo/LogRedirect.h>
  23 #include <syncevo/Logging.h>
  24 #include "test.h"
  25 #include <syncevo/util.h>
  26 #include <sys/types.h>
  27 #include <sys/socket.h>
  28 #include <netinet/in.h>
  29 #include <arpa/inet.h>
  30 #include <unistd.h>
  31 #include <sys/stat.h>
  32 #include <fcntl.h>
  33 #include <signal.h>
  34 #include <errno.h>
  35
  36 #include <boost/algorithm/string/find_iterator.hpp>
  37 #include <boost/algorithm/string/predicate.hpp>
  38 #include <boost/noncopyable.hpp>
  39 #include <boost/foreach.hpp>
  40
  41 #include <algorithm>
  42 #include <iostream>
  43
  44 #ifdef HAVE_GLIB
  45 # include <glib.h>
  46 #endif
  47
  48
  49 #include <syncevo/declarations.h>
  50 using namespace std;
  51 SE_BEGIN_CXX
  52
  53 LogRedirect *LogRedirect::m_redirect;
  54 std::set<std::string> LogRedirect::m_knownErrors;
  55
  56 void LogRedirect::abortHandler(int sig) throw()
  57 {
  58     // Don't know state of logging system, don't log here!
  59     // SE_LOG_ERROR(NULL, "caught signal %d, shutting down", sig);
  60
  61     // Shut down redirection, also flushes to log. This involves
  62     // unsafe calls. For example, we may have to allocate new memory,
  63     // which deadlocks if glib detected memory corruption and
  64     // called abort() (see FDO #76375).
  65     //
  66     // But flushing the log is the whole point of the abortHandler, so
  67     // we can't just skip this. To handle cases where the work that we
  68     // need to do fails, we set a timeout and let the process be
  69     // killed that way. alarm() and sigaction() are async-signal-safe.
  70     {
  71         struct sigaction new_action, old_action;
  72         memset(&new_action, 0, sizeof(new_action));
  73         new_action.sa_handler = SIG_DFL; // Terminates the process.
  74         sigemptyset(&new_action.sa_mask);
  75         sigaction(SIGALRM, &new_action, &old_action);
  76         alarm(5);
  77
  78         RecMutex::Guard guard = lock();
  79         if (m_redirect) {
  80             m_redirect->restore();
  81         }
  82     }
  83
  84     // Raise same signal again. Because our handler
  85     // is automatically removed, this will abort
  86     // for real now.
  87     raise(sig);
  88 }
  89
  90 void LogRedirect::init()
  91 {
  92     m_processing = false;
  93     m_buffer = NULL;
  94     m_len = 0;
  95     m_out = NULL;
  96     m_err = NULL;
  97     m_streams = false;
  98     m_stderr.m_original =
  99         m_stderr.m_read =
 100         m_stderr.m_write =
 101         m_stderr.m_copy = -1;
 102     m_stdout.m_original =
 103         m_stdout.m_read =
 104         m_stdout.m_write =
 105         m_stdout.m_copy = -1;
 106
 107     const char *lines = getenv("SYNCEVOLUTION_SUPPRESS_ERRORS");
 108     if (lines) {
 109         typedef boost::split_iterator<const char *> string_split_iterator;
 110         string_split_iterator it =
 111             boost::make_split_iterator(lines, boost::first_finder("\n", boost::is_iequal()));
 112         while (it != string_split_iterator()) {
 113             m_knownErrors.insert(std::string(it->begin(), it->end()));
 114             ++it;
 115         }
 116     }
 117
 118     // CONSOLEPRINTF in libsynthesis.
 119     m_knownErrors.insert("SYSYNC   Rejected with error:");
 120     // libneon 'Request ends, status 207 class 2xx, error line:'
 121     m_knownErrors.insert("xx, error line:\n");
 122     // some internal Qt warning (?)
 123     m_knownErrors.insert("Qt: Session management error: None of the authentication protocols specified are supported");
 124 }
 125
 126 LogRedirect::LogRedirect(Mode mode, const char *filename)
 127 {
 128     init();
 129     m_processing = true;
 130     if (!getenv("SYNCEVOLUTION_DEBUG")) {
 131         redirect(STDERR_FILENO, m_stderr);
 132         if (mode == STDERR_AND_STDOUT) {
 133             redirect(STDOUT_FILENO, m_stdout);
 134             m_out = filename ?
 135                 fopen(filename, "w") :
 136                 fdopen(dup(m_stdout.m_copy), "w");
 137             if (!m_out) {
 138                 restore(m_stdout);
 139                 restore(m_stderr);
 140                 perror(filename ? filename : "LogRedirect fdopen");
 141             }
 142         } else if (filename) {
 143             m_out = fopen(filename, "w");
 144             if (!m_out) {
 145                 perror(filename);
 146             }
 147         }
 148         // Separate FILE, will write into same file as normal output
 149         // if a filename was given (for testing), otherwise to original
 150         // stderr.
 151         m_err = fdopen(dup((filename && m_out) ?
 152                            fileno(m_out) :
 153                            m_stderr.m_copy), "w");
 154     }
 155
 156     // Modify process state while holding the Logger mutex.
 157     RecMutex::Guard guard = lock();
 158     if (m_redirect) {
 159         SE_LOG_WARNING(NULL, "LogRedirect already instantiated?!");
 160     }
 161     m_redirect = this;
 162
 163     if (!getenv("SYNCEVOLUTION_DEBUG")) {
 164         struct sigaction new_action, old_action;
 165         memset(&new_action, 0, sizeof(new_action));
 166         new_action.sa_handler = abortHandler;
 167         sigemptyset(&new_action.sa_mask);
 168         // disable handler after it was called once
 169         new_action.sa_flags = SA_RESETHAND;
 170         // block signals while we handler is active
 171         // to prevent recursive calls
 172         sigaddset(&new_action.sa_mask, SIGABRT);
 173         sigaddset(&new_action.sa_mask, SIGSEGV);
 174         sigaddset(&new_action.sa_mask, SIGBUS);
 175         sigaction(SIGABRT, &new_action, &old_action);
 176         sigaction(SIGSEGV, &new_action, &old_action);
 177         sigaction(SIGBUS, &new_action, &old_action);
 178     }
 179     m_processing = false;
 180 }
 181
 182 LogRedirect::LogRedirect(ExecuteFlags flags)
 183 {
 184     init();
 185
 186     // This instance does not modify process state and
 187     // doesn't have to be thread-safe.
 188     m_streams = true;
 189     if (!(flags & EXECUTE_NO_STDERR)) {
 190         redirect(STDERR_FILENO, m_stderr);
 191     }
 192     if (!(flags & EXECUTE_NO_STDOUT)) {
 193         redirect(STDOUT_FILENO, m_stdout);
 194     }
 195 }
 196
 197 LogRedirect::~LogRedirect() throw()
 198 {
 199     RecMutex::Guard guard;
 200     if (!m_streams) {
 201         guard = lock();
 202     }
 203     if (m_redirect == this) {
 204         m_redirect = NULL;
 205     }
 206     process();
 207     restore();
 208     m_processing = true;
 209     if (m_out) {
 210         fclose(m_out);
 211     }
 212     if (m_err) {
 213         fclose(m_err);
 214     }
 215     if (m_buffer) {
 216         free(m_buffer);
 217     }
 218 }
 219
 220 void LogRedirect::remove() throw()
 221 {
 222     restore();
 223 }
 224
 225 void LogRedirect::removeRedirect() throw()
 226 {
 227     if (m_redirect) {
 228         // We were forked. Ignore mutex (might be held by thread which was not
 229         // forked) and restore the forked process' state to the one it was
 230         // before setting up redirection.
 231         //
 232         // Do the minimal amount of work possible in restore(), i.e.,
 233         // suppress the processing of streams.
 234         m_redirect->m_streams = false;
 235
 236         m_redirect->restore(m_redirect->m_stdout);
 237         m_redirect->restore(m_redirect->m_stderr);
 238     }
 239 }
 240
 241 void LogRedirect::restore() throw()
 242 {
 243     RecMutex::Guard guard;
 244     if (!m_streams) {
 245         guard = lock();
 246     }
 247
 248     if (m_processing) {
 249         return;
 250     }
 251     m_processing = true;
 252
 253     restore(m_stdout);
 254     restore(m_stderr);
 255
 256     m_processing = false;
 257 }
 258
 259 void LogRedirect::messagev(const MessageOptions &options,
 260                            const char *format,
 261                            va_list args)
 262 {
 263     RecMutex::Guard guard = lock();
 264
 265     // check for other output first
 266     process();
 267     if (!(options.m_flags & MessageOptions::ONLY_GLOBAL_LOG)) {
 268         // Choose output channel: SHOW goes to original stdout,
 269         // everything else to stderr.
 270         LoggerStdout::write(options.m_level == SHOW ?
 271                             (m_out ? m_out : stdout) :
 272                             (m_err ? m_err : stderr),
 273                             options.m_level, getLevel(),
 274                             options.m_prefix,
 275                             options.m_processName,
 276                             format,
 277                             args);
 278     }
 279 }
 280
 281 void LogRedirect::redirect(int original, FDs &fds) throw()
 282 {
 283     fds.m_original = original;
 284     fds.m_write = fds.m_read = -1;
 285     fds.m_copy = dup(fds.m_original);
 286     if (fds.m_copy >= 0) {
 287         if (m_streams) {
 288             // According to Stevens, Unix Network Programming, "Unix
 289             // domain datagram sockets are similar to UDP sockets: the
 290             // provide an *unreliable* datagram service that preserves
 291             // record boundaries." (14.4 Socket Functions,
 292             // p. 378). But unit tests showed that they do block on
 293             // Linux and thus seem reliable. Not sure what the official
 294             // spec is.
 295             //
 296             // To avoid the deadlock risk, we must use UDP. But when we
 297             // want "reliable" behavior *and* detect that all output was
 298             // processed, we have to use streams despite loosing
 299             // the write() boundaries, because Unix domain datagram sockets
 300             // do not flag "end of data".
 301             int sockets[2];
 302 #define USE_UNIX_DOMAIN_DGRAM 0
 303             if (!socketpair(AF_LOCAL,
 304                             USE_UNIX_DOMAIN_DGRAM ? SOCK_DGRAM : SOCK_STREAM,
 305                             0, sockets)) {
 306                 // success
 307                 fds.m_write = sockets[0];
 308                 fds.m_read = sockets[1];
 309                 return;
 310             } else {
 311                 perror("LogRedirect::redirect() socketpair");
 312             }
 313         } else {
 314             int write = socket(AF_INET, SOCK_DGRAM, 0);
 315             if (write >= 0) {
 316                 int read = socket(AF_INET, SOCK_DGRAM, 0);
 317                 if (read >= 0) {
 318                     struct sockaddr_in addr;
 319                     memset(&addr, 0, sizeof(addr));
 320                     addr.sin_family = AF_INET;
 321                     addr.sin_addr.s_addr = inet_addr("127.0.0.1");
 322                     bool bound = false;
 323                     for (int port = 1025; !bound && port < 10000; port++) {
 324                         addr.sin_port = htons(port);
 325                         if (!bind(read, (struct sockaddr *)&addr, sizeof(addr))) {
 326                             bound = true;
 327                         }
 328                     }
 329
 330                     if (bound) {
 331                         if (!connect(write, (struct sockaddr *)&addr, sizeof(addr))) {
 332                             if (dup2(write, fds.m_original) >= 0) {
 333                                 // success
 334                                 fds.m_write = write;
 335                                 fds.m_read = read;
 336                                 return;
 337                             }
 338                             perror("LogRedirect::redirect() dup2");
 339                         }
 340                         perror("LogRedirect::redirect connect");
 341                     }
 342                     close(read);
 343                 }
 344                 close(write);
 345             }
 346         }
 347         close(fds.m_copy);
 348         fds.m_copy = -1;
 349     } else {
 350         perror("LogRedirect::redirect() dup");
 351     }
 352 }
 353
 354 void LogRedirect::restore(FDs &fds) throw()
 355 {
 356     if (!m_streams && fds.m_copy >= 0) {
 357         // flush our own redirected output and process what they might have written
 358         if (fds.m_original == STDOUT_FILENO) {
 359             fflush(stdout);
 360             std::cout << std::flush;
 361         } else {
 362             fflush(stderr);
 363             std::cerr << std::flush;
 364         }
 365         process(fds);
 366
 367         dup2(fds.m_copy, fds.m_original);
 368     }
 369
 370     if (fds.m_copy >= 0) {
 371         close(fds.m_copy);
 372     }
 373     if (fds.m_write >= 0) {
 374         close(fds.m_write);
 375     }
 376     if (fds.m_read >= 0) {
 377         close(fds.m_read);
 378     }
 379     fds.m_copy =
 380         fds.m_write =
 381         fds.m_read = -1;
 382 }
 383
 384 bool LogRedirect::process(FDs &fds) throw()
 385 {
 386     bool have_message;
 387     bool data_read = false;
 388
 389     if (fds.m_read <= 0) {
 390         return data_read;
 391     }
 392
 393     ssize_t available = 0;
 394     do {
 395         have_message = false;
 396
 397         // keep peeking at the data with increasing buffer sizes until
 398         // we are sure that we don't truncate it
 399         size_t newlen = std::max((size_t)1024, m_len);
 400         while (true) {
 401             // increase buffer?
 402             if (newlen > m_len) {
 403                 void *buffer = realloc(m_buffer, newlen);
 404                 if (!buffer) {
 405                     // Nothing changed.
 406                     if (available) {
 407                         // We already read some data of a
 408                         // datagram. Give up on the rest of the data,
 409                         // process what we have below.
 410                         if ((size_t)available == m_len) {
 411                             // Need the byte for nul termination.
 412                             available--;
 413                         }
 414                         have_message = true;
 415                         break;
 416                     } else {
 417                         // Give up.
 418                         Exception::throwError(SE_HERE, "out of memory");
 419                         return false;
 420                     }
 421                 } else {
 422                     m_buffer = (char *)buffer;
 423                     m_len = newlen;
 424                 }
 425             }
 426             // read, but leave space for nul byte;
 427             // when using datagrams, we only peek here and remove the
 428             // datagram below, without rereading the data
 429             if (!USE_UNIX_DOMAIN_DGRAM && m_streams) {
 430                 available = recv(fds.m_read, m_buffer, m_len - 1, MSG_DONTWAIT);
 431                 if (available == 0) {
 432                     return data_read;
 433                 } else if (available == -1) {
 434                     if (errno == EAGAIN) {
 435                         // pretend that data was read, so that caller invokes us again
 436                         return true;
 437                     } else {
 438                         Exception::throwError(SE_HERE, "reading output", errno);
 439                         return false;
 440                     }
 441                 } else {
 442                     // data read, process it
 443                     data_read = true;
 444                     break;
 445                 }
 446             } else {
 447                 available = recv(fds.m_read, m_buffer, m_len - 1, MSG_DONTWAIT|MSG_PEEK);
 448                 have_message = available >= 0;
 449             }
 450             if (available < (ssize_t)m_len - 1) {
 451                 break;
 452             } else {
 453                 // try again with twice the buffer
 454                 newlen *= 2;
 455             }
 456         }
 457         if (have_message) {
 458             if (USE_UNIX_DOMAIN_DGRAM || !m_streams) {
 459                 // swallow packet, even if empty or we couldn't receive it
 460                 recv(fds.m_read, NULL, 0, MSG_DONTWAIT);
 461             }
 462             data_read = true;
 463         }
 464
 465         if (available > 0) {
 466             m_buffer[available] = 0;
 467             // Now pass it to logger, with a level determined by
 468             // the channel. This is the point where we can filter
 469             // out known noise.
 470             std::string prefix;
 471             Logger::Level level = Logger::DEV;
 472             char *text = m_buffer;
 473
 474             if (fds.m_original == STDOUT_FILENO) {
 475                 // stdout: not sure what this could be, so show it
 476                 level = Logger::SHOW;
 477                 char *eol = strchr(text, '\n');
 478                 if (!m_stdoutData.empty()) {
 479                     // try to complete previous line, can be done
 480                     // if text contains a line break
 481                     if (eol) {
 482                         m_stdoutData.append(text, eol - text);
 483                         text = eol + 1;
 484                         Logger::instance().message(level, prefix.empty() ? NULL : &prefix,
 485                                                    NULL, 0, NULL,
 486                                                    "%s", m_stdoutData.c_str());
 487                         m_stdoutData.clear();
 488                     }
 489                 }
 490
 491                 // avoid sending incomplete line at end of text,
 492                 // must be done when there is no line break or
 493                 // it is not at the end of the buffer
 494                 eol = strrchr(text, '\n');
 495                 if (eol != m_buffer + available - 1) {
 496                     if (eol) {
 497                         m_stdoutData.append(eol + 1);
 498                         *eol = 0;
 499                     } else {
 500                         m_stdoutData.append(text);
 501                         *text = 0;
 502                     }
 503                 }
 504
 505                 // output might have been processed as part of m_stdoutData,
 506                 // don't log empty string below
 507                 if (!*text) {
 508                     continue;
 509                 }
 510             } else if (fds.m_original == STDERR_FILENO) {
 511                 // stderr: not normally useful for users, so we
 512                 // can filter it more aggressively. For example,
 513                 // swallow extra line breaks, glib inserts those.
 514                 while (*text == '\n') {
 515                     text++;
 516                 }
 517                 const char *glib_debug_prefix = "** ("; // ** (client-test:875): WARNING **:
 518                 const char *glib_msg_prefix = "** Message:";
 519                 prefix = "stderr";
 520                 if ((!strncmp(text, glib_debug_prefix, strlen(glib_debug_prefix)) &&
 521                      strstr(text, " **:")) ||
 522                     !strncmp(text, glib_msg_prefix, strlen(glib_msg_prefix))) {
 523                     level = Logger::DEBUG;
 524                     prefix = "glib";
 525                 } else {
 526                     level = Logger::DEV;
 527                 }
 528
 529                 // If the text contains the word "error", it probably
 530                 // is severe enough to show to the user, regardless of
 531                 // who produced it... except for errors suppressed
 532                 // explicitly.
 533                 if (strcasestr(text, "error") &&
 534                     !ignoreError(text)) {
 535                     level = Logger::ERROR;
 536                 }
 537             }
 538
 539             // avoid explicit newline at end of output,
 540             // logging will add it for each message()
 541             // invocation
 542             size_t len = strlen(text);
 543             if (len > 0 && text[len - 1] == '\n') {
 544                 text[len - 1] = 0;
 545             }
 546             Logger::instance().message(level, prefix.empty() ? NULL : &prefix,
 547                                        NULL, 0, NULL,
 548                                        "%s", text);
 549             available = 0;
 550         }
 551     } while(have_message);
 552
 553     return data_read;
 554 }
 555
 556 void LogRedirect::addIgnoreError(const std::string &error)
 557 {
 558     RecMutex::Guard guard = Logger::lock();
 559     m_knownErrors.insert(error);
 560 }
 561
 562 bool LogRedirect::ignoreError(const std::string &text)
 563 {
 564     RecMutex::Guard guard = Logger::lock();
 565     BOOST_FOREACH(const std::string &entry, m_knownErrors) {
 566         if (text.find(entry) != text.npos) {
 567             return true;
 568         }
 569     }
 570     return false;
 571 }
 572
 573 void LogRedirect::process()
 574 {
 575     RecMutex::Guard guard;
 576
 577     if (m_streams) {
 578         // iterate until both sockets are closed by peer
 579         while (true) {
 580             fd_set readfds;
 581             fd_set errfds;
 582             int maxfd = 0;
 583             FD_ZERO(&readfds);
 584             FD_ZERO(&errfds);
 585             if (m_stdout.m_read >= 0) {
 586                 FD_SET(m_stdout.m_read, &readfds);
 587                 FD_SET(m_stdout.m_read, &errfds);
 588                 maxfd = m_stdout.m_read;
 589             }
 590             if (m_stderr.m_read >= 0) {
 591                 FD_SET(m_stderr.m_read, &readfds);
 592                 FD_SET(m_stderr.m_read, &errfds);
 593                 if (m_stderr.m_read > maxfd) {
 594                     maxfd = m_stderr.m_read;
 595                 }
 596             }
 597             if (maxfd == 0) {
 598                 // both closed
 599                 return;
 600             }
 601
 602             int res = select(maxfd + 1, &readfds, NULL, &errfds, NULL);
 603             switch (res) {
 604             case -1:
 605                 // fatal, cannot continue
 606                 Exception::throwError(SE_HERE, "waiting for output", errno);
 607                 return;
 608                 break;
 609             case 0:
 610                 // None ready? Try again.
 611                 break;
 612             default:
 613                 if (m_stdout.m_read >= 0 && FD_ISSET(m_stdout.m_read, &readfds)) {
 614                     if (!process(m_stdout)) {
 615                         // Exact status of a Unix domain datagram socket upon close
 616                         // of the remote end is a bit uncertain. For TCP, we would end
 617                         // up here: marked by select as "ready for read", but no data -> EOF.
 618                         close(m_stdout.m_read);
 619                         m_stdout.m_read = -1;
 620                     }
 621                 }
 622                 if (m_stdout.m_read >= 0 && FD_ISSET(m_stdout.m_read, &errfds)) {
 623                     // But in practice, Unix domain sockets don't mark the stream
 624                     // as "closed". This is an attempt to detect that situation
 625                     // via the FDs exception status, but that also doesn't work.
 626                     close(m_stdout.m_read);
 627                     m_stdout.m_read = -1;
 628                 }
 629                 if (m_stderr.m_read >= 0 && FD_ISSET(m_stderr.m_read, &readfds)) {
 630                     if (!process(m_stderr)) {
 631                         close(m_stderr.m_read);
 632                         m_stderr.m_read = -1;
 633                     }
 634                 }
 635                 if (m_stderr.m_read >= 0 && FD_ISSET(m_stderr.m_read, &errfds)) {
 636                     close(m_stderr.m_read);
 637                     m_stderr.m_read = -1;
 638                 }
 639                 break;
 640             }
 641         }
 642     } else {
 643         guard = lock();
 644     }
 645
 646     if (m_processing) {
 647         return;
 648     }
 649     m_processing = true;
 650
 651     process(m_stdout);
 652     process(m_stderr);
 653
 654     // avoid hanging onto excessive amounts of memory
 655     m_len = std::min((size_t)(4 * 1024), m_len);
 656     m_buffer = (char *)realloc(m_buffer, m_len);
 657     if (!m_buffer) {
 658         m_len = 0;
 659     }
 660
 661     m_processing = false;
 662 }
 663
 664
 665
 666 void LogRedirect::flush() throw()
 667 {
 668     RecMutex::Guard guard = lock();
 669
 670     process();
 671     if (!m_stdoutData.empty()) {
 672         std::string buffer;
 673         std::swap(buffer, m_stdoutData);
 674         Logger::instance().message(Logger::SHOW, NULL,
 675                                    NULL, 0, NULL,
 676                                    "%s", buffer.c_str());
 677     }
 678 }
 679
 680
 681 #ifdef ENABLE_UNIT_TESTS
 682
 683 class LogRedirectTest : public CppUnit::TestFixture {
 684     CPPUNIT_TEST_SUITE(LogRedirectTest);
 685     CPPUNIT_TEST(simple);
 686     CPPUNIT_TEST(largeChunk);
 687     CPPUNIT_TEST(streams);
 688     CPPUNIT_TEST(overload);
 689 #ifdef HAVE_GLIB
 690     CPPUNIT_TEST(glib);
 691 #endif
 692     CPPUNIT_TEST_SUITE_END();
 693
 694     /**
 695      * redirect stdout/stderr, then intercept the log messages and
 696      * store them for inspection
 697      */
 698     class LogBuffer : public Logger, private boost::noncopyable
 699     {
 700     public:
 701         std::stringstream m_streams[DEBUG + 1];
 702         PushLogger<LogRedirect> m_redirect;
 703
 704         LogBuffer(LogRedirect::Mode mode = LogRedirect::STDERR_AND_STDOUT)
 705         {
 706             m_redirect.reset(new LogRedirect(mode));
 707             addLogger(boost::shared_ptr<Logger>(this, NopDestructor()));
 708         }
 709         ~LogBuffer()
 710         {
 711             removeLogger(this);
 712             m_redirect.reset();
 713         }
 714
 715         virtual void messagev(const MessageOptions &options,
 716                               const char *format,
 717                               va_list args)
 718         {
 719             CPPUNIT_ASSERT(options.m_level <= DEBUG && options.m_level >= 0);
 720             m_streams[options.m_level] << StringPrintfV(format, args);
 721         }
 722     };
 723
 724 public:
 725     void simple()
 726     {
 727         LogBuffer buffer;
 728
 729         static const char *simpleMessage = "hello world";
 730         CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(simpleMessage), write(STDOUT_FILENO, simpleMessage, strlen(simpleMessage)));
 731         buffer.m_redirect->flush();
 732
 733         CPPUNIT_ASSERT_EQUAL(buffer.m_streams[Logger::SHOW].str(), std::string(simpleMessage));
 734     }
 735
 736     void largeChunk()
 737     {
 738         LogBuffer buffer;
 739
 740         std::string large;
 741         large.append(60 * 1024, 'h');
 742         CPPUNIT_ASSERT_EQUAL((ssize_t)large.size(), write(STDOUT_FILENO, large.c_str(), large.size()));
 743         buffer.m_redirect->flush();
 744
 745         CPPUNIT_ASSERT_EQUAL(large.size(), buffer.m_streams[Logger::SHOW].str().size());
 746         CPPUNIT_ASSERT_EQUAL(large, buffer.m_streams[Logger::SHOW].str());
 747     }
 748
 749     void streams()
 750     {
 751         LogBuffer buffer;
 752
 753         static const char *simpleMessage = "hello world";
 754         CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(simpleMessage), write(STDOUT_FILENO, simpleMessage, strlen(simpleMessage)));
 755         static const char *errorMessage = "such a cruel place";
 756         CPPUNIT_ASSERT_EQUAL((ssize_t)strlen(errorMessage), write(STDERR_FILENO, errorMessage, strlen(errorMessage)));
 757
 758         // process() keeps unfinished STDOUT lines buffered
 759         buffer.m_redirect->process();
 760         CPPUNIT_ASSERT_EQUAL(std::string(errorMessage), buffer.m_streams[Logger::DEV].str());
 761         CPPUNIT_ASSERT_EQUAL(string(""), buffer.m_streams[Logger::SHOW].str());
 762
 763         // flush() makes them available
 764         buffer.m_redirect->flush();
 765         CPPUNIT_ASSERT_EQUAL(std::string(errorMessage), buffer.m_streams[Logger::DEV].str());
 766         CPPUNIT_ASSERT_EQUAL(std::string(simpleMessage), buffer.m_streams[Logger::SHOW].str());
 767     }
 768
 769     void overload()
 770     {
 771         LogBuffer buffer;
 772
 773         std::string large;
 774         large.append(1024, 'h');
 775         for (int i = 0; i < 4000; i++) {
 776             CPPUNIT_ASSERT_EQUAL((ssize_t)large.size(), write(STDOUT_FILENO, large.c_str(), large.size()));
 777         }
 778         buffer.m_redirect->flush();
 779
 780         CPPUNIT_ASSERT(buffer.m_streams[Logger::SHOW].str().size() > large.size());
 781     }
 782
 783 #ifdef HAVE_GLIB
 784     void glib()
 785     {
 786         fflush(stdout);
 787         fflush(stderr);
 788
 789         static const char *filename = "LogRedirectTest_glib.out";
 790         int new_stdout = open(filename, O_RDWR|O_CREAT|O_TRUNC, S_IRWXU);
 791
 792         // check that intercept all glib message and don't print anything to stdout
 793         int orig_stdout = -1;
 794         try {
 795             // need to restore the current state below; would be nice
 796             // to query it instead of assuming that Logger::glogFunc
 797             // is the current log handler
 798             g_log_set_default_handler(g_log_default_handler, NULL);
 799
 800             orig_stdout = dup(STDOUT_FILENO);
 801             dup2(new_stdout, STDOUT_FILENO);
 802
 803             LogBuffer buffer(LogRedirect::STDERR);
 804
 805             fprintf(stdout, "normal message stdout\n");
 806             fflush(stdout);
 807
 808             fprintf(stderr, "normal message stderr\n");
 809             fflush(stderr);
 810
 811             // ** (process:13552): WARNING **: test warning
 812             g_warning("test warning");
 813             // ** Message: test message
 814             g_message("test message");
 815             // ** (process:13552): CRITICAL **: test critical
 816             g_critical("test critical");
 817             // would abort:
 818             // g_error("error")
 819             // ** (process:13552): DEBUG: test debug
 820             g_debug("test debug");
 821
 822             buffer.m_redirect->process();
 823
 824             std::string error = buffer.m_streams[Logger::ERROR].str();
 825             std::string warning = buffer.m_streams[Logger::WARNING].str();
 826             std::string show = buffer.m_streams[Logger::SHOW].str();
 827             std::string info = buffer.m_streams[Logger::INFO].str();
 828             std::string dev = buffer.m_streams[Logger::DEV].str();
 829             std::string debug = buffer.m_streams[Logger::DEBUG].str();
 830             CPPUNIT_ASSERT_EQUAL(string(""), error);
 831             CPPUNIT_ASSERT_EQUAL(string(""), warning);
 832             CPPUNIT_ASSERT_EQUAL(string(""), show);
 833             CPPUNIT_ASSERT_EQUAL(string(""), info);
 834             CPPUNIT_ASSERT_EQUAL(string(""), error);
 835             CPPUNIT_ASSERT(dev.find("normal message stderr") != dev.npos);
 836             CPPUNIT_ASSERT(debug.find("test warning") != debug.npos);
 837         } catch(...) {
 838             g_log_set_default_handler(Logger::glogFunc, NULL);
 839             dup2(orig_stdout, STDOUT_FILENO);
 840             throw;
 841         }
 842         g_log_set_default_handler(Logger::glogFunc, NULL);
 843         dup2(orig_stdout, STDOUT_FILENO);
 844
 845         lseek(new_stdout, 0, SEEK_SET);
 846         char out[128];
 847         ssize_t l = read(new_stdout, out, sizeof(out) - 1);
 848         CPPUNIT_ASSERT(l > 0);
 849         out[l] = 0;
 850         CPPUNIT_ASSERT(boost::starts_with(std::string(out), "normal message stdout"));
 851     }
 852 #endif
 853 };
 854
 855 SYNCEVOLUTION_TEST_SUITE_REGISTRATION(LogRedirectTest);
 856
 857 #endif // ENABLE_UNIT_TESTS
 858
 859
 860 SE_END_CXX