Logging: thread-safe

Logging must be thread-safe, because the glib log callback may be
called from arbitrary threads. This becomes more important with EDS
3.8, because it shifts the execution of synchronous calls into
threads.

Thread-safe logging will also be required for running the Synthesis
engine multithreaded, to overlap SyncML client communication with
preparing the sources.

To achieve this, the core Logging module protects its global data with
a recursive mutex. A recursive mutes is used because logging calls
themselves may be recursive, so ensuring single-lock semantic would be
hard.

Ref-counted boost pointers are used to track usage of Logger
instances.  This allows removal of an instance from the logging stack
while it may still be in use. Destruction then will be delayed until
the last user of the instance drops it. The instance itself must be
prepared to handle this.

The Logging mutex is available to users of the Logging module. Code
which holds the logging mutex should not lock any other mutex, to
avoid deadlocks. The new code is a bit fuzzy on that, because it calls
other modules (glib, Synthesis engine) while holding the mutex. If
that becomes a problem, then the mutex can be unlocked, at the risk of
leading to reordered log messages in different channels (see
ServerLogger).

Making all loggers follow the new rules uses different
approaches.

Loggers like the one in the local transport child which use a parent
logger and an additional ref-counted class like the D-Bus helper keep
a weak reference to the helper and lock it before use. If it is gone
already, the second logging part is skipped. This is the recommended
approach.

In cases where introducing ref-counting for the second class would
have been too intrusive (Server and SessionHelper), a fake
boost::shared_ptr without a destructor is used as an intermediate step
towards the recommended approach. To avoid race conditions while the
instance these fake pointers refer to destructs, an explicit
"remove()" method is necessary which must hold the Logging
mutex. Using the potentially removed pointer must do the same. Such
fake ref-counted Loggers cannot be used as parent logger of other
loggers, because then remove() would not be able to drop the last
reference to the fake boost::shared_ptr.

Loggers with fake boost::shared_ptr must keep a strong reference,
because no-one else does. The goal is to turn this into weak
references eventually.

LogDir must protect concurrent access to m_report and the Synthesis
engine.

The LogRedirectLogger assumes that it is still the active logger while
disabling itself. The remove() callback method will always be invoked
before removing a logger from the stack.

1 files changed, 40 insertions, 40 deletions

diff --git a/src/dbus/server/session.cpp b/src/dbus/server/session.cpp
index 64819b63..acae499c 100644
--- a/src/dbus/server/session.cpp
+++ b/src/dbus/server/session.cpp
@@ -204,7 +204,7 @@ void Session::setNamedConfig(const std::string &configName,
                              bool update, bool temporary,
                              const ReadOperations::Config_t &config)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation != SessionCommon::OP_NULL) {
         string msg = StringPrintf("%s started, cannot change configuration at this time", runOpToString(m_runOperation).c_str());
         SE_THROW_EXCEPTION(InvalidCall, msg);
@@ -323,7 +323,7 @@ void Session::setNamedConfig(const std::string &configName,
 
 void Session::initServer(SharedBuffer data, const std::string &messageType)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     m_serverMode = true;
     m_initialMessage = data;
     m_initialMessageType = messageType;
@@ -331,7 +331,7 @@ void Session::initServer(SharedBuffer data, const std::string &messageType)
 
 void Session::sync(const std::string &mode, const SessionCommon::SourceModes_t &sourceModes)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation == SessionCommon::OP_SYNC) {
         string msg = StringPrintf("%s started, cannot start again", runOpToString(m_runOperation).c_str());
         SE_THROW_EXCEPTION(InvalidCall, msg);
@@ -352,7 +352,7 @@ void Session::sync(const std::string &mode, const SessionCommon::SourceModes_t &
 
 void Session::sync2(const std::string &mode, const SessionCommon::SourceModes_t &sourceModes)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (!m_forkExecParent || !m_helper) {
         SE_THROW("syncing cannot continue, helper died");
     }
@@ -415,7 +415,7 @@ void Session::sync2(const std::string &mode, const SessionCommon::SourceModes_t
 
 void Session::abort()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation != SessionCommon::OP_SYNC && m_runOperation != SessionCommon::OP_CMDLINE) {
         SE_THROW_EXCEPTION(InvalidCall, "sync not started, cannot abort at this time");
     }
@@ -436,7 +436,7 @@ void Session::abort()
 
 void Session::suspend()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation != SessionCommon::OP_SYNC && m_runOperation != SessionCommon::OP_CMDLINE) {
         SE_THROW_EXCEPTION(InvalidCall, "sync not started, cannot suspend at this time");
     }
@@ -453,7 +453,7 @@ void Session::suspend()
 
 void Session::abortAsync(const SimpleResult &result)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (!m_forkExecParent) {
         result.done();
     } else {
@@ -470,7 +470,7 @@ void Session::getStatus(std::string &status,
                         uint32_t &error,
                         SourceStatuses_t &sources)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     status = syncStatusToString(m_syncStatus);
     if (m_stepIsWaiting) {
         status += ";waiting";
@@ -483,14 +483,14 @@ void Session::getStatus(std::string &status,
 void Session::getProgress(int32_t &progress,
                           SourceProgresses_t &sources)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     progress = m_progData.getProgress();
     sources = m_sourceProgress;
 }
 
 void Session::fireStatus(bool flush)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     std::string status;
     uint32_t error;
     SourceStatuses_t sources;
@@ -507,7 +507,7 @@ void Session::fireStatus(bool flush)
 
 void Session::fireProgress(bool flush)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     int32_t progress;
     SourceProgresses_t sources;
 
@@ -595,13 +595,13 @@ Session::Session(Server &server,
 
 void Session::passwordRequest(const std::string &descr, const ConfigPasswordKey &key)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     m_passwordRequest = m_server.passwordRequest(descr, key, m_me);
 }
 
 void Session::dbusResultCb(const std::string &operation, bool success, const std::string &error) throw()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         SE_LOG_DEBUG(NULL, "%s helper call completed, %s",
                      operation.c_str(),
@@ -625,7 +625,7 @@ void Session::dbusResultCb(const std::string &operation, bool success, const std
 
 void Session::failureCb() throw()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         if (m_status == SESSION_DONE) {
             // ignore errors that happen after session already closed,
@@ -666,7 +666,7 @@ void Session::failureCb() throw()
 
 void Session::doneCb(bool success) throw()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         if (m_status == SESSION_DONE) {
             return;
@@ -730,7 +730,7 @@ static void raiseChildTermError(int status, const SimpleResult &result)
 void Session::runOperationAsync(SessionCommon::RunOperation op,
                                 const SuccessCb_t &helperReady)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     m_server.addSyncSession(this);
     m_runOperation = op;
     m_status = SESSION_RUNNING;
@@ -743,7 +743,7 @@ void Session::runOperationAsync(SessionCommon::RunOperation op,
 
 void Session::useHelperAsync(const SimpleResult &result)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         if (m_helper) {
             // exists already, invoke callback directly
@@ -810,9 +810,9 @@ void Session::messagev(const MessageOptions &options,
 {
     // log with session path and empty process name,
     // just like the syncevo-dbus-helper does
-    m_server.messagev(options,
-                      format, args,
-                      getPath(), "");
+    m_server.message2DBus(options,
+                          format, args,
+                          getPath(), "");
 }
 
 static void Logging2Server(Server &server,
@@ -829,7 +829,7 @@ static void Logging2Server(Server &server,
 
 void Session::useHelper2(const SimpleResult &result, const boost::signals2::connection &c)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         // helper is running, don't call result.failed() when it quits
         // sometime in the future
@@ -872,7 +872,7 @@ void Session::useHelper2(const SimpleResult &result, const boost::signals2::conn
 
 void Session::onConnect(const GDBusCXX::DBusConnectionPtr &conn) throw ()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         SE_LOG_DEBUG(NULL, "helper has connected");
         m_helper.reset(new SessionProxy(conn));
@@ -891,7 +891,7 @@ void Session::onConnect(const GDBusCXX::DBusConnectionPtr &conn) throw ()
 
 void Session::onQuit(int status) throw ()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         SE_LOG_DEBUG(NULL, "helper quit with return code %d, was %s",
                      status,
@@ -936,7 +936,7 @@ void Session::onQuit(int status) throw ()
 
 void Session::onFailure(SyncMLStatus status, const std::string &explanation) throw ()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         SE_LOG_DEBUG(NULL, "helper failed, status code %d = %s, %s",
                      status,
@@ -949,7 +949,7 @@ void Session::onFailure(SyncMLStatus status, const std::string &explanation) thr
 
 void Session::onOutput(const char *buffer, size_t length)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     // treat null-bytes inside the buffer like line breaks
     size_t off = 0;
     do {
@@ -960,7 +960,7 @@ void Session::onOutput(const char *buffer, size_t length)
 
 void Session::activateSession()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_status != SESSION_IDLE) {
         SE_THROW("internal error, session changing from non-idle to active");
     }
@@ -981,7 +981,7 @@ void Session::activateSession()
 
 void Session::passwordResponse(bool timedOut, bool aborted, const std::string &password)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_helper) {
         // Ignore communicaton failures with helper here,
         // we'll notice that elsewhere
@@ -994,7 +994,7 @@ void Session::passwordResponse(bool timedOut, bool aborted, const std::string &p
 void Session::syncProgress(sysync::TProgressEventEnum type,
                            int32_t extra1, int32_t extra2, int32_t extra3)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     switch(type) {
     case sysync::PEV_CUSTOM_START:
         m_cmdlineOp = (RunOperation)extra1;
@@ -1047,7 +1047,7 @@ void Session::sourceProgress(sysync::TProgressEventEnum type,
                              SyncMode sourceSyncMode,
                              int32_t extra1, int32_t extra2, int32_t extra3)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     // a command line operation can be many things, helper must have told us
     SessionCommon::RunOperation op = m_runOperation == SessionCommon::OP_CMDLINE ?
         m_cmdlineOp :
@@ -1165,7 +1165,7 @@ void Session::sourceProgress(sysync::TProgressEventEnum type,
 
 bool Session::setFilters(SyncConfig &config)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     /** apply temporary configs to config */
     config.setConfigFilter(true, "", m_syncFilter);
     // set all sources in the filter to config
@@ -1177,7 +1177,7 @@ bool Session::setFilters(SyncConfig &config)
 
 void Session::setWaiting(bool isWaiting)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     // if stepInfo doesn't change, then ignore it to avoid duplicate status info
     if(m_stepIsWaiting != isWaiting) {
         m_stepIsWaiting = isWaiting;
@@ -1187,7 +1187,7 @@ void Session::setWaiting(bool isWaiting)
 
 void Session::restore(const string &dir, bool before, const std::vector<std::string> &sources)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation == SessionCommon::OP_RESTORE) {
         string msg = StringPrintf("restore started, cannot restore again");
         SE_THROW_EXCEPTION(InvalidCall, msg);
@@ -1207,7 +1207,7 @@ void Session::restore(const string &dir, bool before, const std::vector<std::str
 
 void Session::restore2(const string &dir, bool before, const std::vector<std::string> &sources)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (!m_forkExecParent || !m_helper) {
         SE_THROW("syncing cannot continue, helper died");
     }
@@ -1219,7 +1219,7 @@ void Session::restore2(const string &dir, bool before, const std::vector<std::st
 
 void Session::execute(const vector<string> &args, const map<string, string> &vars)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (m_runOperation == SessionCommon::OP_CMDLINE) {
         SE_THROW_EXCEPTION(InvalidCall, "cmdline started, cannot start again");
     } else if (m_runOperation != SessionCommon::OP_NULL) {
@@ -1238,7 +1238,7 @@ void Session::execute(const vector<string> &args, const map<string, string> &var
 
 void Session::execute2(const vector<string> &args, const map<string, string> &vars)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     if (!m_forkExecParent || !m_helper) {
         SE_THROW("syncing cannot continue, helper died");
     }
@@ -1251,7 +1251,7 @@ void Session::execute2(const vector<string> &args, const map<string, string> &va
 /*Implementation of Session.CheckPresence */
 void Session::checkPresence (string &status)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     vector<string> transport;
     m_server.checkPresence(m_configName, status, transport);
 }
@@ -1260,7 +1260,7 @@ void Session::sendViaConnection(const DBusArray<uint8_t> buffer,
                                 const std::string &type,
                                 const std::string &url)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         boost::shared_ptr<Connection> connection = m_connection.lock();
 
@@ -1279,7 +1279,7 @@ void Session::sendViaConnection(const DBusArray<uint8_t> buffer,
 
 void Session::shutdownConnection()
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     try {
         boost::shared_ptr<Connection> connection = m_connection.lock();
 
@@ -1299,7 +1299,7 @@ void Session::shutdownConnection()
 void Session::storeMessage(const DBusArray<uint8_t> &message,
                            const std::string &type)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     // ignore errors
     if (m_helper) {
         m_helper->m_storeMessage.start(message, type,
@@ -1309,7 +1309,7 @@ void Session::storeMessage(const DBusArray<uint8_t> &message,
 
 void Session::connectionState(const std::string &error)
 {
-    Session::LoggingGuard guard(this);
+    PushLogger<Logger> guard(m_me);
     // ignore errors
     if (m_helper) {
         m_helper->m_connectionState.start(error,