added debug logging for signal and process handling

Added debug logging to valgrindcheck.sh, suspend flags, fork/exec
and main() functions. Helps with tracing where signal handlers
are installed and which processes run.

6 files changed, 36 insertions, 7 deletions

diff --git a/src/dbus/server/main.cpp b/src/dbus/server/main.cpp
index 6b4100c6..6f55a6ef 100644
--- a/src/dbus/server/main.cpp
+++ b/src/dbus/server/main.cpp
@@ -91,9 +91,6 @@ int main(int argc, char **argv, char **envp)
         setvbuf(stderr, NULL, _IONBF, 0);
         setvbuf(stdout, NULL, _IONBF, 0);
 
-        signal(SIGTERM, niam);
-        signal(SIGINT, niam);
-
         LogRedirect redirect(true);
 
         // make daemon less chatty - long term this should be a command line option
@@ -101,6 +98,10 @@ int main(int argc, char **argv, char **envp)
                                         LoggerBase::DEBUG :
                                         LoggerBase::INFO);
 
+        SE_LOG_DEBUG(NULL, NULL, "syncevo-dbus-server: catch SIGINT/SIGTERM in our own shutdown function");
+        signal(SIGTERM, niam);
+        signal(SIGINT, niam);
+
         DBusErrorCXX err;
         DBusConnectionPtr conn = dbus_get_bus_connection("SESSION",
                                                          "org.syncevolution",
diff --git a/src/syncevo/ForkExec.cpp b/src/syncevo/ForkExec.cpp
index 6ef6dcc5..3375d3f1 100644
--- a/src/syncevo/ForkExec.cpp
+++ b/src/syncevo/ForkExec.cpp
@@ -78,6 +78,7 @@ void ForkExecParent::start()
     // boost::shared_ptr<ForkExecParent> me = ...;
     GDBusCXX::DBusErrorCXX dbusError;
 
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: preparing for child process %s", m_helper.c_str());
     m_server = GDBusCXX::DBusServerCXX::listen("", &dbusError);
     if (!m_server) {
         dbusError.throwFailure("starting server");
@@ -123,6 +124,8 @@ void ForkExecParent::start()
     m_envStrings.push_back(ForkExecEnvVar + m_server->getAddress());
     m_env.reset(AllocStringArray(m_envStrings));
 
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: running %s with D-Bus address %s",
+                 helper.c_str(), m_server->getAddress().c_str());
     GErrorCXX gerror;
     if (!g_spawn_async_with_pipes(NULL, // working directory
                                   static_cast<gchar **>(m_argv.get()),
@@ -139,6 +142,9 @@ void ForkExecParent::start()
         gerror.throwError("spawning child");
     }
 
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: child process for %s has pid %ld",
+                 helper.c_str(), (long)m_childPid);
+
     // TODO: introduce C++ wrapper around GSource
     m_watchChild = g_child_watch_source_new(m_childPid);
     g_source_set_callback(m_watchChild, (GSourceFunc)watchChildCallback, this, NULL);
@@ -155,7 +161,7 @@ void ForkExecParent::watchChildCallback(GPid pid,
         me->m_onQuit(status);
         if (!me->m_hasConnected ||
             status != 0) {
-            SE_LOG_DEBUG(NULL, NULL, "signaled %s, signal %d, int %d, term %d, int sent %s, term sent %s",
+            SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: child was signaled %s, signal %d, int %d, term %d, int sent %s, term sent %s",
                          WIFSIGNALED(status) ? "yes" : "no",
                          WTERMSIG(status), SIGINT, SIGTERM,
                          me->m_sigIntSent ? "yes" : "no",
@@ -194,6 +200,8 @@ void ForkExecParent::watchChildCallback(GPid pid,
 void ForkExecParent::newClientConnection(GDBusCXX::DBusConnectionPtr &conn) throw()
 {
     try {
+        SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: child %s has connected",
+                     m_helper.c_str());
         m_hasConnected = true;
         m_onConnect(conn);
     } catch (...) {
@@ -210,7 +218,8 @@ void ForkExecParent::newClientConnection(GDBusCXX::DBusConnectionPtr &conn) thro
 
 void ForkExecParent::stop()
 {
-    SE_LOG_DEBUG(NULL, NULL, "killing with SIGINT/SIGTERM");
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: killing %s with SIGINT/SIGTERM",
+                 m_helper.c_str());
     ::kill(m_childPid, SIGINT);
     m_sigIntSent = true;
     ::kill(m_childPid, SIGTERM);
@@ -219,7 +228,8 @@ void ForkExecParent::stop()
 
 void ForkExecParent::kill()
 {
-    SE_LOG_DEBUG(NULL, NULL, "killing with SIGKILL");
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecParent: killing %s with SIGKILL",
+                 m_helper.c_str());
     ::kill(m_childPid, SIGKILL);
 }
 
@@ -240,6 +250,8 @@ void ForkExecChild::connect()
         SE_THROW("cannot connect to parent, was not forked");
     }
 
+    SE_LOG_DEBUG(NULL, NULL, "ForkExecChild: connecting to parent with D-Bus address %s",
+                 address);
     GDBusCXX::DBusErrorCXX dbusError;
     GDBusCXX::DBusConnectionPtr conn = dbus_get_bus_connection(address,
                                                                &dbusError);
diff --git a/src/syncevo/LocalTransportAgent.cpp b/src/syncevo/LocalTransportAgent.cpp
index a6165eda..2e309d23 100644
--- a/src/syncevo/LocalTransportAgent.cpp
+++ b/src/syncevo/LocalTransportAgent.cpp
@@ -779,6 +779,8 @@ public:
             new_action.sa_handler = abortLocalSync;
             sigaction(SIGTERM, &new_action, NULL);
 
+            SE_LOG_DEBUG(NULL, NULL, "LocalTransportChild: ignore SIGINT, die in SIGTERM");
+
             m_client->sync(&m_clientReport);
         } catch (...) {
             string explanation;
diff --git a/src/syncevo/SuspendFlags.cpp b/src/syncevo/SuspendFlags.cpp
index 63de68fe..57b79d96 100644
--- a/src/syncevo/SuspendFlags.cpp
+++ b/src/syncevo/SuspendFlags.cpp
@@ -135,6 +135,8 @@ boost::shared_ptr<SuspendFlags::StateBlocker> SuspendFlags::block(boost::weak_pt
 
 boost::shared_ptr<SuspendFlags::Guard> SuspendFlags::activate()
 {
+    SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: (re)activating, currently %s",
+                 m_senderFD > 0 ? "active" : "inactive");
     int fds[2];
     if (pipe(fds)) {
         SE_THROW(StringPrintf("allocating pipe for signals failed: %s", strerror(errno)));
@@ -144,6 +146,8 @@ boost::shared_ptr<SuspendFlags::Guard> SuspendFlags::activate()
     fcntl(fds[1], F_SETFL, fcntl(fds[1], F_GETFL) | O_NONBLOCK);
     m_senderFD = fds[1];
     m_receiverFD = fds[0];
+    SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: activating signal handler(s) with fds %d->%d",
+                 m_senderFD, m_receiverFD);
     sigaction(SIGINT, NULL, &m_oldSigInt);
     sigaction(SIGTERM, NULL, &m_oldSigTerm);
 
@@ -162,9 +166,11 @@ boost::shared_ptr<SuspendFlags::Guard> SuspendFlags::activate()
     }
     if (m_oldSigInt.sa_handler == SIG_DFL) {
         sigaction(SIGINT, &new_action, NULL);
+        SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: catch SIGINT");
     }
     if (m_oldSigTerm.sa_handler == SIG_DFL) {
         sigaction(SIGTERM, &new_action, NULL);
+        SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: catch SIGTERM");
     }
 
     return boost::shared_ptr<Guard>(new GLibGuard(m_receiverFD));
@@ -172,6 +178,8 @@ boost::shared_ptr<SuspendFlags::Guard> SuspendFlags::activate()
 
 void SuspendFlags::deactivate()
 {
+    SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: deactivating fds %d->%d",
+                 m_senderFD, m_receiverFD);
     if (m_receiverFD >= 0) {
         sigaction(SIGTERM, &m_oldSigTerm, NULL);
         sigaction(SIGINT, &m_oldSigInt, NULL);
@@ -186,6 +194,9 @@ void SuspendFlags::handleSignal(int sig)
 {
     SuspendFlags &me(getSuspendFlags());
 
+    // can't use logging infrastructure in signal handler,
+    // not reentrant
+
     unsigned char msg;
     switch (sig) {
     case SIGTERM:
@@ -237,6 +248,8 @@ void SuspendFlags::printSignals()
     if (m_receiverFD >= 0) {
         unsigned char msg;
         while (read(m_receiverFD, &msg, 1) == 1) {
+            SE_LOG_DEBUG(NULL, NULL, "SuspendFlags: read %d from fd %d",
+                         msg, m_receiverFD);
             const char *str = NULL;
             switch (msg) {
             case SUSPEND:
diff --git a/src/syncevo/SyncContext.cpp b/src/syncevo/SyncContext.cpp
index be6f8cf3..62d519eb 100644
--- a/src/syncevo/SyncContext.cpp
+++ b/src/syncevo/SyncContext.cpp
@@ -3271,6 +3271,7 @@ SyncMLStatus SyncContext::doSync()
     // install signal handlers unless this was explicitly disabled
     bool catchSignals = getenv("SYNCEVOLUTION_NO_SYNC_SIGNALS") == NULL;
     if (catchSignals) {
+        SE_LOG_DEBUG(NULL, NULL, "sync is starting, catch signals");
         signalGuard = SuspendFlags::getSuspendFlags().activate();
     }
 
diff --git a/test/valgrindcheck.sh b/test/valgrindcheck.sh
index e0119eed..80fcbfc1 100755
--- a/test/valgrindcheck.sh
+++ b/test/valgrindcheck.sh
@@ -45,7 +45,7 @@ trap "kill -INT $VALGRIND_PID" INT
 
 wait $VALGRIND_PID
 RET=$?
-echo valgrindcheck: "$@": returned $RET >&2
+echo "valgrindcheck ($$): '$@' ($VALGRIND_PID): returned $RET" >&2
 
 # give other valgrind instances some time to settle down, then kill them
 sleep 1