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.
This commit is contained in:
Patrick Ohly
parent
a5ef5b5a11
commit
989d18e5aa
|
|
@ -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",
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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();
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
Loading…
Reference in New Issue