syncevo-dbus-server stdout: split at lines (MB #5042)

syncevo-dbus-server is the first usage of LogRedirect which also
redirects stdout. In turn, the main usage is catching of "synccompare"
output. It turns out that the assumption for stderr so far that writes
are atomic doesn't hold for stdout of synccompare. Lines often are
interrupted in the middle.

In addition, SE_LOG(SHOW) always inserts a newline.

This patch deals with this by treating data received for stdout as a
data stream. It buffers incomplete lines and appends the rest of the
line when the next chunk comes in.

This delays printing such an incomplete line. flush() is introduced
to get that last, incomplete line logged.

For stderr, keeping text in memory instead of printing it as soon
as received is considered undesirable, therefore that code path
is not changed.

src/syncevo-dbus-server.cpp

@@ -74,6 +74,7 @@ using namespace SyncEvo;
 
 static GMainLoop *loop = NULL;
 static bool shutdownRequested = false;
+static LogRedirect *redirectPtr;
 
 /**
  * Anything that can be owned by a client, like a connection
@@ -2009,6 +2010,9 @@ public:
         } catch (...) {
             Exception::handle();
         }
+        // always forward all currently pending redirected output
+        // before closing the session
+        redirectPtr->flush();
     }
 };
 
@@ -5797,6 +5801,7 @@ int main(int argc, char **argv)
         signal(SIGINT, niam);
 
         LogRedirect redirect(true);
+        redirectPtr = &redirect;
 
         // make daemon less chatty - long term this should be a command line option
         LoggerBase::instance().setLevel(LoggerBase::INFO);

src/syncevo/LogRedirect.cpp

@@ -285,11 +285,44 @@ void LogRedirect::process(FDs &fds) throw()
             // out known noise.
             const char *prefix = NULL;
             Logger::Level level = Logger::DEV;
-            const char *text = m_buffer;
+            char *text = m_buffer;
 
             if (fds.m_original == STDOUT_FILENO) {
                 // stdout: not sure what this could be, so show it
-                level = Logger::INFO;
+                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;
+                        LoggerBase::instance().message(level, prefix,
+                                                       NULL, 0, NULL,
+                                                       "%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,
@@ -345,6 +378,19 @@ void LogRedirect::process() throw()
 }
 
 
+
+void LogRedirect::flush() throw()
+{
+    process();
+    if (!m_stdoutData.empty()) {
+        LoggerBase::instance().message(Logger::SHOW, NULL,
+                                       NULL, 0, NULL,
+                                       "%s", m_stdoutData.c_str());
+        m_stdoutData.clear();
+    }
+}
+
+
 #ifdef ENABLE_UNIT_TESTS
 
 class LogRedirectTest : public CppUnit::TestFixture {

src/syncevo/LogRedirect.h

@@ -76,9 +76,14 @@ SE_BEGIN_CXX
  *
  * Redirection and signal handlers are disabled if the environment
  * variable SYNCEVOLUTION_DEBUG is set (regardless of its value).
+ *
+ * In contrast to stderr, stdout is only passed into the logging
+ * system as complete lines. That's because it may include data (like
+ * synccompare output) which is not printed line-oriented and
+ * inserting line breaks (as the logging system does) is undesirable.
+ * If an output packet does not end in a line break, that last line
+ * is buffered and written together with the next packet, or in flush().
  */
-
-
 class LogRedirect : public LoggerStdout
 {
     struct FDs {
@@ -89,6 +94,7 @@ class LogRedirect : public LoggerStdout
     } m_stdout, m_stderr;
     FILE *m_out;            /** a stream for the normal LogStdout which isn't redirected */
     char *m_buffer;         /** typically fairly small buffer for reading */
+    std::string m_stdoutData;  /**< incomplete stdout line */
     size_t m_len;           /** total length of buffer */
     bool m_processing;      /** flag to detect recursive process() calls */
     static LogRedirect *m_redirect; /**< single active instance, for signal handler */
@@ -108,6 +114,9 @@ class LogRedirect : public LoggerStdout
 
     void process() throw();
 
+    /** same as process(), but also dump all cached output */
+    void flush() throw();
+
     /** format log messages via normal LogStdout and print to a valid stream owned by us */
     virtual void messagev(Level level,
                           const char *prefix,