src/syncevo/LocalTransportAgent.cpp

   1 /*
   2  * Copyright (C) 2010 Patrick Ohly
   3  *
   4  * This library is free software; you can redistribute it and/or
   5  * modify it under the terms of the GNU Lesser General Public
   6  * License as published by the Free Software Foundation; either
   7  * version 2.1 of the License, or (at your option) version 3.
   8  *
   9  * This library is distributed in the hope that it will be useful,
  10  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  11  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  12  * Lesser General Public License for more details.
  13  *
  14  * You should have received a copy of the GNU Lesser General Public
  15  * License along with this library; if not, write to the Free Software
  16  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
  17  * 02110-1301  USA
  18  */
  19
  20 #include <syncevo/LocalTransportAgent.h>
  21 #include <syncevo/SyncContext.h>
  22 #include <syncevo/SyncML.h>
  23 #include <syncevo/LogRedirect.h>
  24 #include <syncevo/StringDataBlob.h>
  25 #include <syncevo/IniConfigNode.h>
  26 #include <syncevo/GLibSupport.h>
  27 #include <syncevo/DBusTraits.h>
  28 #include <syncevo/SuspendFlags.h>
  29 #include <syncevo/LogRedirect.h>
  30 #include <syncevo/LogDLT.h>
  31 #include <syncevo/BoostHelper.h>
  32
  33 #include <synthesis/syerror.h>
  34
  35 #include <stddef.h>
  36 #include <sys/socket.h>
  37 #include <sys/types.h>
  38 #include <sys/wait.h>
  39 #include <fcntl.h>
  40 #include <pcrecpp.h>
  41
  42 #include <algorithm>
  43
  44 #include <syncevo/declarations.h>
  45 SE_BEGIN_CXX
  46
  47 class NoopAgentDestructor
  48 {
  49 public:
  50     void operator () (TransportAgent *agent) throw() {}
  51 };
  52
  53 LocalTransportAgent::LocalTransportAgent(SyncContext *server,
  54                                          const std::string &clientContext,
  55                                          void *loop) :
  56     m_server(server),
  57     m_clientContext(SyncConfig::normalizeConfigString(clientContext)),
  58     m_status(INACTIVE),
  59     m_loop(loop ?
  60            GMainLoopCXX(static_cast<GMainLoop *>(loop), ADD_REF) :
  61            GMainLoopCXX(g_main_loop_new(NULL, false), TRANSFER_REF))
  62 {
  63 }
  64
  65 boost::shared_ptr<LocalTransportAgent> LocalTransportAgent::create(SyncContext *server,
  66                                                                    const std::string &clientContext,
  67                                                                    void *loop)
  68 {
  69     boost::shared_ptr<LocalTransportAgent> self(new LocalTransportAgent(server, clientContext, loop));
  70     self->m_self = self;
  71     return self;
  72 }
  73
  74 LocalTransportAgent::~LocalTransportAgent()
  75 {
  76 }
  77
  78 void LocalTransportAgent::start()
  79 {
  80     // compare normalized context names to detect forbidden sync
  81     // within the same context; they could be set up, but are more
  82     // likely configuration mistakes
  83     string peer, context;
  84     SyncConfig::splitConfigString(m_clientContext, peer, context);
  85     if (!peer.empty()) {
  86         SE_THROW(StringPrintf("invalid local sync URL: '%s' references a peer config, should point to a context like @%s instead",
  87                               m_clientContext.c_str(),
  88                               context.c_str()));
  89     }
  90     // TODO (?): check that there are no conflicts between the active
  91     // sources. The old "contexts must be different" check achieved that
  92     // via brute force (because by definition, databases from different
  93     // contexts are meant to be independent), but it was too coarse
  94     // and ruled out valid configurations.
  95     // if (m_clientContext == m_server->getContextName()) {
  96     //     SE_THROW(StringPrintf("invalid local sync inside context '%s', need second context with different databases", context.c_str()));
  97     // }
  98
  99     if (m_forkexec) {
 100         SE_THROW("local transport already started");
 101     }
 102     m_status = ACTIVE;
 103     m_forkexec = ForkExecParent::create("syncevo-local-sync");
 104 #ifdef USE_DLT
 105     if (getenv("SYNCEVOLUTION_USE_DLT")) {
 106         m_forkexec->addEnvVar("SYNCEVOLUTION_USE_DLT", StringPrintf("%d", LoggerDLT::getCurrentDLTLogLevel()));
 107     }
 108 #endif
 109     m_forkexec->m_onConnect.connect(boost::bind(&LocalTransportAgent::onChildConnect, this, _1));
 110     // fatal problems, including quitting child with non-zero status
 111     m_forkexec->m_onFailure.connect(boost::bind(&LocalTransportAgent::onFailure, this, _2));
 112     // watch onQuit and remember whether the child is still running,
 113     // because it might quit prematurely with a zero return code (for
 114     // example, when an unexpected slow sync is detected)
 115     m_forkexec->m_onQuit.connect(boost::bind(&LocalTransportAgent::onChildQuit, this, _1));
 116     m_forkexec->start();
 117 }
 118
 119 /**
 120  * Uses the D-Bus API provided by LocalTransportParent.
 121  */
 122 class LocalTransportParent : private GDBusCXX::DBusRemoteObject
 123 {
 124  public:
 125     static const char *path() { return "/"; }
 126     static const char *interface() { return "org.syncevolution.localtransport.parent"; }
 127     static const char *destination() { return "local.destination"; }
 128     static const char *askPasswordName() { return "AskPassword"; }
 129     static const char *storeSyncReportName() { return "StoreSyncReport"; }
 130
 131     LocalTransportParent(const GDBusCXX::DBusConnectionPtr &conn) :
 132         GDBusCXX::DBusRemoteObject(conn, path(), interface(), destination()),
 133         m_askPassword(*this, askPasswordName()),
 134         m_storeSyncReport(*this, storeSyncReportName())
 135     {}
 136
 137     /** LocalTransportAgent::askPassword() */
 138     GDBusCXX::DBusClientCall1<std::string> m_askPassword;
 139     /** LocalTransportAgent::storeSyncReport() */
 140     GDBusCXX::DBusClientCall0 m_storeSyncReport;
 141 };
 142
 143 /**
 144  * Uses the D-Bus API provided by LocalTransportAgentChild.
 145  */
 146 class LocalTransportChild : public GDBusCXX::DBusRemoteObject
 147 {
 148  public:
 149     static const char *path() { return "/"; }
 150     static const char *interface() { return "org.syncevolution.localtransport.child"; }
 151     static const char *destination() { return "local.destination"; }
 152     static const char *logOutputName() { return "LogOutput"; }
 153     static const char *startSyncName() { return "StartSync"; }
 154     static const char *sendMsgName() { return "SendMsg"; }
 155
 156     LocalTransportChild(const GDBusCXX::DBusConnectionPtr &conn) :
 157         GDBusCXX::DBusRemoteObject(conn, path(), interface(), destination()),
 158         m_logOutput(*this, logOutputName(), false),
 159         m_startSync(*this, startSyncName()),
 160         m_sendMsg(*this, sendMsgName())
 161     {}
 162
 163     /**
 164      * information from server config about active sources:
 165      * mapping is from server source names to child source name + sync mode
 166      * (again as set on the server side!)
 167      */
 168     typedef std::map<std::string, StringPair> ActiveSources_t;
 169     /** use this to send a message back from child to parent */
 170     typedef boost::shared_ptr< GDBusCXX::Result2< std::string, GDBusCXX::DBusArray<uint8_t> > > ReplyPtr;
 171
 172     /** log output with level and message; process name will be added by parent */
 173     GDBusCXX::SignalWatch2<string, string> m_logOutput;
 174
 175     /** LocalTransportAgentChild::startSync() */
 176     GDBusCXX::DBusClientCall2<std::string, GDBusCXX::DBusArray<uint8_t> > m_startSync;
 177     /** LocalTransportAgentChild::sendMsg() */
 178     GDBusCXX::DBusClientCall2<std::string, GDBusCXX::DBusArray<uint8_t> > m_sendMsg;
 179
 180 };
 181
 182 void LocalTransportAgent::logChildOutput(const std::string &level, const std::string &message)
 183 {
 184     Logger::MessageOptions options(Logger::strToLevel(level.c_str()));
 185     options.m_processName = &m_clientContext;
 186     // Child should have written this into its own log file and/or syslog/dlt already.
 187     // Only pass it on to a user of the command line interface.
 188     options.m_flags = Logger::MessageOptions::ALREADY_LOGGED;
 189     SyncEvo::Logger::instance().messageWithOptions(options, "%s", message.c_str());
 190 }
 191
 192 void LocalTransportAgent::onChildConnect(const GDBusCXX::DBusConnectionPtr &conn)
 193 {
 194     SE_LOG_DEBUG(NULL, "child is ready");
 195     m_parent.reset(new GDBusCXX::DBusObjectHelper(conn,
 196                                                   LocalTransportParent::path(),
 197                                                   LocalTransportParent::interface(),
 198                                                   GDBusCXX::DBusObjectHelper::Callback_t(),
 199                                                   true));
 200     m_parent->add(this, &LocalTransportAgent::askPassword, LocalTransportParent::askPasswordName());
 201     m_parent->add(this, &LocalTransportAgent::storeSyncReport, LocalTransportParent::storeSyncReportName());
 202     m_parent->activate();
 203     m_child.reset(new LocalTransportChild(conn));
 204     m_child->m_logOutput.activate(boost::bind(&LocalTransportAgent::logChildOutput, this, _1, _2));
 205
 206     // now tell child what to do
 207     LocalTransportChild::ActiveSources_t sources;
 208     BOOST_FOREACH(const string &sourceName, m_server->getSyncSources()) {
 209         SyncSourceNodes nodes = m_server->getSyncSourceNodesNoTracking(sourceName);
 210         SyncSourceConfig source(sourceName, nodes);
 211         std::string sync = source.getSync();
 212         if (sync != "disabled") {
 213             string targetName = source.getURINonEmpty();
 214             sources[sourceName] = std::make_pair(targetName, sync);
 215         }
 216     }
 217     m_child->m_startSync.start(m_clientContext,
 218                                StringPair(m_server->getConfigName(),
 219                                           m_server->isEphemeral() ?
 220                                           "ephemeral" :
 221                                           m_server->getRootPath()),
 222                                static_cast<std::string>(m_server->getLogDir()),
 223                                m_server->getDoLogging(),
 224                                std::make_pair(m_server->getSyncUser(),
 225                                               m_server->getSyncPassword()),
 226                                m_server->getConfigProps(),
 227                                sources,
 228                                boost::bind(&LocalTransportAgent::storeReplyMsg, m_self, _1, _2, _3));
 229 }
 230
 231 void LocalTransportAgent::onFailure(const std::string &error)
 232 {
 233     m_status = FAILED;
 234     g_main_loop_quit(m_loop.get());
 235
 236     SE_LOG_ERROR(NULL, "local transport failed: %s", error.c_str());
 237     m_parent.reset();
 238     m_child.reset();
 239 }
 240
 241 void LocalTransportAgent::onChildQuit(int status)
 242 {
 243     SE_LOG_DEBUG(NULL, "child process has quit with status %d", status);
 244     g_main_loop_quit(m_loop.get());
 245 }
 246
 247 static void GotPassword(const boost::shared_ptr< GDBusCXX::Result1<const std::string &> > &reply,
 248                         const std::string &password)
 249 {
 250     reply->done(password);
 251 }
 252
 253 static void PasswordException(const boost::shared_ptr< GDBusCXX::Result1<const std::string &> > &reply)
 254 {
 255     // TODO: refactor, this is the same as dbusErrorCallback
 256     try {
 257         // If there is no pending exception, the process will abort
 258         // with "terminate called without an active exception";
 259         // dbusErrorCallback() should only be called when there is
 260         // a pending exception.
 261         // TODO: catch this misuse in a better way
 262         throw;
 263     } catch (...) {
 264         // let D-Bus parent log the error
 265         std::string explanation;
 266         Exception::handle(explanation, HANDLE_EXCEPTION_NO_ERROR);
 267         reply->failed(GDBusCXX::dbus_error("org.syncevolution.localtransport.error", explanation));
 268     }
 269 }
 270
 271 void LocalTransportAgent::askPassword(const std::string &passwordName,
 272                                       const std::string &descr,
 273                                       const ConfigPasswordKey &key,
 274                                       const boost::shared_ptr< GDBusCXX::Result1<const std::string &> > &reply)
 275 {
 276     // pass that work to our own SyncContext and its UI - currently blocks
 277     SE_LOG_DEBUG(NULL, "local sync parent: asked for password %s, %s",
 278                  passwordName.c_str(),
 279                  descr.c_str());
 280     try {
 281         if (m_server) {
 282             m_server->getUserInterfaceNonNull().askPasswordAsync(passwordName, descr, key,
 283                                                                  // TODO refactor: use dbus-callbacks.h
 284                                                                  boost::bind(GotPassword,
 285                                                                              reply,
 286                                                                              _1),
 287                                                                  boost::bind(PasswordException,
 288                                                                              reply));
 289         } else {
 290             SE_LOG_DEBUG(NULL, "local sync parent: password request failed because no m_server");
 291             reply->failed(GDBusCXX::dbus_error("org.syncevolution.localtransport.error",
 292                                                "not connected to UI"));
 293         }
 294     } catch (...) {
 295         PasswordException(reply);
 296     }
 297 }
 298
 299 void LocalTransportAgent::storeSyncReport(const std::string &report)
 300 {
 301     SE_LOG_DEBUG(NULL, "got child sync report:\n%s",
 302                  report.c_str());
 303     m_clientReport = SyncReport(report);
 304 }
 305
 306 void LocalTransportAgent::getClientSyncReport(SyncReport &report)
 307 {
 308     report = m_clientReport;
 309 }
 310
 311 void LocalTransportAgent::setContentType(const std::string &type)
 312 {
 313     m_contentType = type;
 314 }
 315
 316 // workaround for limitations of bind+signals when used together with plain GMainLoop pointer
 317 // (pointer to undefined struct)
 318 static void gMainLoopQuit(GMainLoopCXX *loop)
 319 {
 320     g_main_loop_quit(loop->get());
 321 }
 322
 323 void LocalTransportAgent::shutdown()
 324 {
 325     SE_LOG_DEBUG(NULL, "parent is shutting down");
 326     if (m_forkexec) {
 327         // block until child is done
 328         boost::signals2::scoped_connection c(m_forkexec->m_onQuit.connect(boost::bind(gMainLoopQuit,
 329                                                                                       &m_loop)));
 330         // don't kill the child here - we expect it to complete by
 331         // itself at some point
 332         // TODO: how do we detect a child which gets stuck after its last
 333         // communication with the parent?
 334         // m_forkexec->stop();
 335         while (m_forkexec->getState() != ForkExecParent::TERMINATED) {
 336             SE_LOG_DEBUG(NULL, "waiting for child to stop");
 337             g_main_loop_run(m_loop.get());
 338         }
 339
 340         m_forkexec.reset();
 341         m_parent.reset();
 342         m_child.reset();
 343     }
 344 }
 345
 346 void LocalTransportAgent::send(const char *data, size_t len)
 347 {
 348     if (m_child) {
 349         m_status = ACTIVE;
 350         m_child->m_sendMsg.start(m_contentType, GDBusCXX::makeDBusArray(len, (uint8_t *)(data)),
 351                                  boost::bind(&LocalTransportAgent::storeReplyMsg, m_self, _1, _2, _3));
 352     } else {
 353         m_status = FAILED;
 354         SE_THROW_EXCEPTION(TransportException,
 355                            "cannot send message because child process is gone");
 356     }
 357 }
 358
 359 void LocalTransportAgent::storeReplyMsg(const std::string &contentType,
 360                                         const GDBusCXX::DBusArray<uint8_t> &reply,
 361                                         const std::string &error)
 362 {
 363     m_replyMsg.assign(reinterpret_cast<const char *>(reply.second),
 364                       reply.first);
 365     m_replyContentType = contentType;
 366     if (error.empty()) {
 367         m_status = GOT_REPLY;
 368     } else {
 369         // Only an error if the client hasn't shut down normally.
 370         if (m_clientReport.empty()) {
 371             SE_LOG_ERROR(NULL, "sending message to child failed: %s", error.c_str());
 372             m_status = FAILED;
 373         }
 374     }
 375     g_main_loop_quit(m_loop.get());
 376 }
 377
 378 void LocalTransportAgent::cancel()
 379 {
 380     if (m_forkexec) {
 381         SE_LOG_DEBUG(NULL, "killing local transport child in cancel()");
 382         m_forkexec->stop();
 383     }
 384     m_status = CANCELED;
 385 }
 386
 387 TransportAgent::Status LocalTransportAgent::wait(bool noReply)
 388 {
 389     if (m_status == ACTIVE) {
 390         // need next message; for noReply == true we are done
 391         if (noReply) {
 392             m_status = INACTIVE;
 393         } else {
 394             while (m_status == ACTIVE) {
 395                 SE_LOG_DEBUG(NULL, "waiting for child to send message");
 396                 if (m_forkexec &&
 397                     m_forkexec->getState() == ForkExecParent::TERMINATED) {
 398                     m_status = FAILED;
 399                     if (m_clientReport.getStatus() != STATUS_OK &&
 400                         m_clientReport.getStatus() != STATUS_HTTP_OK) {
 401                         // Report that status, with an error message which contains the explanation
 402                         // added to the client's error. We are a bit fuzzy about matching the status:
 403                         // 10xxx matches xxx and vice versa.
 404                         int status = m_clientReport.getStatus();
 405                         if (status >= sysync::LOCAL_STATUS_CODE && status <= sysync::LOCAL_STATUS_CODE_END) {
 406                             status -= sysync::LOCAL_STATUS_CODE;
 407                         }
 408                         std::string explanation = StringPrintf("failure on target side %s of local sync",
 409                                                                m_clientContext.c_str());
 410                         static const pcrecpp::RE re("\\((?:local|remote), status (\\d+)\\): (.*)");
 411                         int clientStatus;
 412                         std::string clientExplanation;
 413                         if (re.PartialMatch(m_clientReport.getError(), &clientStatus, &clientExplanation) &&
 414                             (status == clientStatus ||
 415                              status == clientStatus - sysync::LOCAL_STATUS_CODE)) {
 416                             explanation += ": ";
 417                             explanation += clientExplanation;
 418                         }
 419                         SE_THROW_EXCEPTION_STATUS(StatusException,
 420                                                   explanation,
 421                                                   m_clientReport.getStatus());
 422                     } else {
 423                         SE_THROW_EXCEPTION(TransportException,
 424                                            "child process quit without sending its message");
 425                     }
 426                 }
 427                 g_main_loop_run(m_loop.get());
 428             }
 429         }
 430     }
 431     return m_status;
 432 }
 433
 434 void LocalTransportAgent::getReply(const char *&data, size_t &len, std::string &contentType)
 435 {
 436     if (m_status != GOT_REPLY) {
 437         SE_THROW("internal error, no reply available");
 438     }
 439     contentType = m_replyContentType;
 440     data = m_replyMsg.c_str();
 441     len = m_replyMsg.size();
 442 }
 443
 444 void LocalTransportAgent::setTimeout(int seconds)
 445 {
 446     // setTimeout() was meant for unreliable transports like HTTP
 447     // which cannot determine whether the peer is still alive. The
 448     // LocalTransportAgent uses sockets and will notice when a peer
 449     // dies unexpectedly, so timeouts should never be necessary.
 450     //
 451     // Quite the opposite, because the "client" in a local sync
 452     // with WebDAV on the client side can be quite slow, incorrect
 453     // timeouts were seen where the client side took longer than
 454     // the default timeout of 5 minutes to process a message and
 455     // send a reply.
 456     //
 457     // Therefore we ignore the request to set a timeout here and thus
 458     // local send/receive operations are allowed to continue for as
 459     // long as they like.
 460     //
 461     // m_timeoutSeconds = seconds;
 462 }
 463
 464 class LocalTransportUI : public UserInterface
 465 {
 466     boost::shared_ptr<LocalTransportParent> m_parent;
 467
 468 public:
 469     LocalTransportUI(const boost::shared_ptr<LocalTransportParent> &parent) :
 470         m_parent(parent)
 471     {}
 472
 473     /** implements password request by asking the parent via D-Bus */
 474     virtual string askPassword(const string &passwordName,
 475                                const string &descr,
 476                                const ConfigPasswordKey &key)
 477     {
 478         SE_LOG_DEBUG(NULL, "local transport child: requesting password %s, %s via D-Bus",
 479                      passwordName.c_str(),
 480                      descr.c_str());
 481         std::string password;
 482         std::string error;
 483         bool havePassword = false;
 484         m_parent->m_askPassword.start(passwordName, descr, key,
 485                                       boost::bind(&LocalTransportUI::storePassword, this,
 486                                                   boost::ref(password), boost::ref(error),
 487                                                   boost::ref(havePassword),
 488                                                   _1, _2));
 489         SuspendFlags &s = SuspendFlags::getSuspendFlags();
 490         while (!havePassword) {
 491             if (s.getState() != SuspendFlags::NORMAL) {
 492                 SE_THROW_EXCEPTION_STATUS(StatusException,
 493                                           StringPrintf("User did not provide the '%s' password.",
 494                                                        passwordName.c_str()),
 495                                           SyncMLStatus(sysync::LOCERR_USERABORT));
 496             }
 497             g_main_context_iteration(NULL, true);
 498         }
 499         if (!error.empty()) {
 500             Exception::tryRethrowDBus(error);
 501             SE_THROW(StringPrintf("retrieving password failed: %s", error.c_str()));
 502         }
 503         return password;
 504     }
 505
 506     virtual bool savePassword(const std::string &passwordName, const std::string &password, const ConfigPasswordKey &key) { SE_THROW("not implemented"); return false; }
 507     virtual void readStdin(std::string &content) { SE_THROW("not implemented"); }
 508
 509 private:
 510     void storePassword(std::string &res, std::string &errorRes, bool &haveRes, const std::string &password, const std::string &error)
 511     {
 512         if (!error.empty()) {
 513             SE_LOG_DEBUG(NULL, "local transport child: D-Bus password request failed: %s",
 514                          error.c_str());
 515             errorRes = error;
 516         } else {
 517             SE_LOG_DEBUG(NULL, "local transport child: D-Bus password request succeeded");
 518             res = password;
 519         }
 520         haveRes = true;
 521     }
 522 };
 523
 524 static void abortLocalSync(int sigterm)
 525 {
 526     // logging anything here is not safe (our own logging system might
 527     // have been interrupted by the SIGTERM and thus be in an inconsistent
 528     // state), but let's try it anyway
 529     SE_LOG_INFO(NULL, "local sync child shutting down due to SIGTERM");
 530     // raise the signal again after disabling the handler, to ensure that
 531     // the exit status is "killed by signal xxx" - good because then
 532     // the whoever killed used gets the information that we didn't die for
 533     // some other reason
 534     signal(sigterm, SIG_DFL);
 535     raise(sigterm);
 536 }
 537
 538 /**
 539  * Provides the "LogOutput" signal.
 540  * LocalTransportAgentChild adds the method implementations
 541  * before activating it.
 542  */
 543 class LocalTransportChildImpl : public GDBusCXX::DBusObjectHelper
 544 {
 545 public:
 546     LocalTransportChildImpl(const GDBusCXX::DBusConnectionPtr &conn) :
 547         GDBusCXX::DBusObjectHelper(conn,
 548                                    LocalTransportChild::path(),
 549                                    LocalTransportChild::interface(),
 550                                    GDBusCXX::DBusObjectHelper::Callback_t(),
 551                                    true),
 552         m_logOutput(*this, LocalTransportChild::logOutputName())
 553     {
 554         add(m_logOutput);
 555     };
 556
 557     GDBusCXX::EmitSignal2<std::string,
 558                           std::string,
 559                           true /* ignore transmission failures */> m_logOutput;
 560 };
 561
 562 class ChildLogger : public Logger
 563 {
 564     std::auto_ptr<LogRedirect> m_parentLogger;
 565     boost::weak_ptr<LocalTransportChildImpl> m_child;
 566
 567 public:
 568     ChildLogger(const boost::shared_ptr<LocalTransportChildImpl> &child) :
 569         m_parentLogger(new LogRedirect(LogRedirect::STDERR_AND_STDOUT)),
 570         m_child(child)
 571     {}
 572     ~ChildLogger()
 573     {
 574         m_parentLogger.reset();
 575     }
 576
 577     /**
 578      * Write message into our own log and send to parent.
 579      */
 580     virtual void messagev(const MessageOptions &options,
 581                           const char *format,
 582                           va_list args)
 583     {
 584         if (options.m_level <= m_parentLogger->getLevel()) {
 585             m_parentLogger->process();
 586             boost::shared_ptr<LocalTransportChildImpl> child = m_child.lock();
 587             if (child) {
 588                 // prefix is used to set session path
 589                 // for general server output, the object path field is dbus server
 590                 // the object path can't be empty for object paths prevent using empty string.
 591                 string strLevel = Logger::levelToStr(options.m_level);
 592                 string log = StringPrintfV(format, args);
 593                 child->m_logOutput(strLevel, log);
 594             }
 595         }
 596     }
 597 };
 598
 599 class LocalTransportAgentChild : public TransportAgent
 600 {
 601     /** final return code of our main(): non-zero indicates that we need to shut down */
 602     int m_ret;
 603
 604     /**
 605      * sync report for client side of the local sync
 606      */
 607     SyncReport m_clientReport;
 608
 609     /** used to capture libneon output */
 610     boost::scoped_ptr<LogRedirect> m_parentLogger;
 611
 612     /**
 613      * provides connection to parent, created in constructor
 614      */
 615     boost::shared_ptr<ForkExecChild> m_forkexec;
 616
 617     /**
 618      * proxy for the parent's D-Bus API in onConnect()
 619      */
 620     boost::shared_ptr<LocalTransportParent> m_parent;
 621
 622     /**
 623      * our D-Bus interface, created in onConnect()
 624      */
 625     boost::shared_ptr<LocalTransportChildImpl> m_child;
 626
 627     /**
 628      * sync context, created in Sync() D-Bus call
 629      */
 630     boost::scoped_ptr<SyncContext> m_client;
 631
 632     /**
 633      * use this D-Bus result handle to send a message from child to parent
 634      * in response to sync() or (later) sendMsg()
 635      */
 636     LocalTransportChild::ReplyPtr m_msgToParent;
 637     void setMsgToParent(const LocalTransportChild::ReplyPtr &reply,
 638                         const std::string &reason)
 639     {
 640         if (m_msgToParent) {
 641             m_msgToParent->failed(GDBusCXX::dbus_error("org.syncevolution.localtransport.error",
 642                                                        "cancelling message: " + reason));
 643         }
 644         m_msgToParent = reply;
 645     }
 646
 647     /** content type for message to parent */
 648     std::string m_contentType;
 649
 650     /**
 651      * message from parent
 652      */
 653     std::string m_message;
 654
 655     /**
 656      * content type of message from parent
 657      */
 658     std::string m_messageType;
 659
 660     /**
 661      * true after parent has received sync report, or sending failed
 662      */
 663     bool m_reportSent;
 664
 665     /**
 666      * INACTIVE when idle,
 667      * ACTIVE after having sent and while waiting for next message,
 668      * GOT_REPLY when we have a message to be processed,
 669      * FAILED when permanently broken
 670      */
 671     Status m_status;
 672
 673     /**
 674      * one loop run + error checking
 675      */
 676     void step(const std::string &status)
 677     {
 678         SE_LOG_DEBUG(NULL, "local transport: %s", status.c_str());
 679         if (!m_forkexec ||
 680             m_forkexec->getState() == ForkExecChild::DISCONNECTED) {
 681             SE_THROW("local transport child no longer has a parent, terminating");
 682         }
 683         g_main_context_iteration(NULL, true);
 684         if (m_ret) {
 685             SE_THROW("local transport child encountered a problem, terminating");
 686         }
 687     }
 688
 689     static void onParentQuit()
 690     {
 691         // Never free this state blocker. We can only abort and
 692         // quit from now on.
 693         static boost::shared_ptr<SuspendFlags::StateBlocker> abortGuard;
 694         SE_LOG_ERROR(NULL, "sync parent quit unexpectedly");
 695         abortGuard = SuspendFlags::getSuspendFlags().abort();
 696     }
 697
 698     void onConnect(const GDBusCXX::DBusConnectionPtr &conn)
 699     {
 700         SE_LOG_DEBUG(NULL, "child connected to parent");
 701
 702         // provide our own API
 703         m_child.reset(new LocalTransportChildImpl(conn));
 704         m_child->add(this, &LocalTransportAgentChild::startSync, LocalTransportChild::startSyncName());
 705         m_child->add(this, &LocalTransportAgentChild::sendMsg, LocalTransportChild::sendMsgName());
 706         m_child->activate();
 707
 708         // set up connection to parent
 709         m_parent.reset(new LocalTransportParent(conn));
 710     }
 711
 712     void onFailure(SyncMLStatus status, const std::string &reason)
 713     {
 714         SE_LOG_DEBUG(NULL, "child fork/exec failed: %s", reason.c_str());
 715
 716         // record failure for parent
 717         if (!m_clientReport.getStatus()) {
 718             m_clientReport.setStatus(status);
 719         }
 720         if (!reason.empty() &&
 721             m_clientReport.getError().empty()) {
 722             m_clientReport.setError(reason);
 723         }
 724
 725         // return to step()
 726         m_ret = 1;
 727     }
 728
 729     // D-Bus API, see LocalTransportChild;
 730     // must keep number of parameters < 9, the maximum supported by
 731     // our D-Bus binding
 732     void startSync(const std::string &clientContext,
 733                    const StringPair &serverConfig, // config name + root path
 734                    const std::string &serverLogDir,
 735                    bool serverDoLogging,
 736                    const std::pair<UserIdentity, InitStateString> &serverSyncCredentials,
 737                    const FullProps &serverConfigProps,
 738                    const LocalTransportChild::ActiveSources_t &sources,
 739                    const LocalTransportChild::ReplyPtr &reply)
 740     {
 741         setMsgToParent(reply, "sync() was called");
 742         Logger::setProcessName(clientContext);
 743         SE_LOG_DEBUG(NULL, "Sync() called, starting the sync");
 744         const char *delay = getenv("SYNCEVOLUTION_LOCAL_CHILD_DELAY2");
 745         if (delay) {
 746             Sleep(atoi(delay));
 747         }
 748
 749         // initialize sync context
 750         m_client.reset(new SyncContext(std::string("target-config") + clientContext,
 751                                        serverConfig.first,
 752                                        serverConfig.second == "ephemeral" ?
 753                                        serverConfig.second :
 754                                        serverConfig.second + "/." + clientContext,
 755                                        boost::shared_ptr<TransportAgent>(this, NoopAgentDestructor()),
 756                                        serverDoLogging));
 757         if (serverConfig.second == "ephemeral") {
 758             m_client->makeEphemeral();
 759         }
 760         boost::shared_ptr<UserInterface> ui(new LocalTransportUI(m_parent));
 761         m_client->setUserInterface(ui);
 762
 763         // allow proceeding with sync even if no "target-config" was created,
 764         // because information about username/password (for WebDAV) or the
 765         // sources (for file backends) might be enough
 766         m_client->setConfigNeeded(false);
 767
 768         // apply temporary config filters
 769         m_client->setConfigFilter(true, "", serverConfigProps.createSyncFilter(m_client->getConfigName()));
 770         BOOST_FOREACH(const string &sourceName, m_client->getSyncSources()) {
 771             m_client->setConfigFilter(false, sourceName, serverConfigProps.createSourceFilter(m_client->getConfigName(), sourceName));
 772         }
 773
 774         // Copy non-empty credentials from main config, because
 775         // that is where the GUI knows how to store them. A better
 776         // solution would be to require that credentials are in the
 777         // "target-config" config.
 778         //
 779         // Interactive password requests later in SyncContext::sync()
 780         // will end up in our LocalTransportContext::askPassword()
 781         // implementation above, which will pass the question to
 782         // the local sync parent.
 783         if (!serverSyncCredentials.first.toString().empty()) {
 784             m_client->setSyncUsername(serverSyncCredentials.first.toString(), true);
 785         }
 786         if (!serverSyncCredentials.second.empty()) {
 787             m_client->setSyncPassword(serverSyncCredentials.second, true);
 788         }
 789
 790         // debugging mode: write logs inside sub-directory of parent,
 791         // otherwise use normal log settings
 792         if (!serverDoLogging) {
 793             m_client->setLogDir(std::string(serverLogDir) + "/child", true);
 794         }
 795
 796         // disable all sources temporarily, will be enabled by next loop
 797         BOOST_FOREACH(const string &targetName, m_client->getSyncSources()) {
 798             SyncSourceNodes targetNodes = m_client->getSyncSourceNodes(targetName);
 799             SyncSourceConfig targetSource(targetName, targetNodes);
 800             targetSource.setSync("disabled", true);
 801         }
 802
 803         // activate all sources in client targeted by main config,
 804         // with right uri
 805         BOOST_FOREACH(const LocalTransportChild::ActiveSources_t::value_type &entry, sources) {
 806             // mapping is from server (source) to child (target)
 807             const std::string &sourceName = entry.first;
 808             const std::string &targetName = entry.second.first;
 809             std::string sync = entry.second.second;
 810             SyncMode mode = StringToSyncMode(sync);
 811             if (mode != SYNC_NONE) {
 812                 SyncSourceNodes targetNodes = m_client->getSyncSourceNodes(targetName);
 813                 SyncSourceConfig targetSource(targetName, targetNodes);
 814                 string fullTargetName = clientContext + "/" + targetName;
 815
 816                 if (!targetNodes.dataConfigExists()) {
 817                     if (targetName.empty()) {
 818                         m_client->throwError("missing URI for one of the sources");
 819                     } else {
 820                         m_client->throwError(StringPrintf("%s: source not configured",
 821                                                           fullTargetName.c_str()));
 822                     }
 823                 }
 824
 825                 // All of the config setting is done as volatile,
 826                 // so none of the regular config nodes have to
 827                 // be written. If a sync mode was set, it must have been
 828                 // done before in this loop => error in original config.
 829                 if (!targetSource.isDisabled()) {
 830                     m_client->throwError(StringPrintf("%s: source targetted twice by %s",
 831                                                       fullTargetName.c_str(),
 832                                                       serverConfig.first.c_str()));
 833                 }
 834                 // invert data direction
 835                 if (mode == SYNC_REFRESH_FROM_LOCAL) {
 836                     mode = SYNC_REFRESH_FROM_REMOTE;
 837                 } else if (mode == SYNC_REFRESH_FROM_REMOTE) {
 838                     mode = SYNC_REFRESH_FROM_LOCAL;
 839                 } else if (mode == SYNC_ONE_WAY_FROM_LOCAL) {
 840                     mode = SYNC_ONE_WAY_FROM_REMOTE;
 841                 } else if (mode == SYNC_ONE_WAY_FROM_REMOTE) {
 842                     mode = SYNC_ONE_WAY_FROM_LOCAL;
 843                 } else if (mode == SYNC_LOCAL_CACHE_SLOW) {
 844                     // Remote side is running in caching mode and
 845                     // asking for refresh. Send all our data.
 846                     mode = SYNC_SLOW;
 847                 } else if (mode == SYNC_LOCAL_CACHE_INCREMENTAL) {
 848                     // Remote side is running in caching mode and
 849                     // asking for an update. Use two-way mode although
 850                     // nothing is going to come back (simpler that way
 851                     // than using one-way, which has special code
 852                     // paths in libsynthesis).
 853                     mode = SYNC_TWO_WAY;
 854                 }
 855                 targetSource.setSync(PrettyPrintSyncMode(mode, true), true);
 856                 targetSource.setURI(sourceName, true);
 857             }
 858         }
 859
 860
 861         // ready for m_client->sync()
 862         m_status = ACTIVE;
 863     }
 864
 865     void sendMsg(const std::string &contentType,
 866                  const GDBusCXX::DBusArray<uint8_t> &data,
 867                  const LocalTransportChild::ReplyPtr &reply)
 868     {
 869         SE_LOG_DEBUG(NULL, "child got message of %ld bytes", (long)data.first);
 870         setMsgToParent(LocalTransportChild::ReplyPtr(), "sendMsg() was called");
 871         if (m_status == ACTIVE) {
 872             m_msgToParent = reply;
 873             m_message.assign(reinterpret_cast<const char *>(data.second),
 874                              data.first);
 875             m_messageType = contentType;
 876             m_status = GOT_REPLY;
 877         } else {
 878             reply->failed(GDBusCXX::dbus_error("org.syncevolution.localtransport.error",
 879                                                "child not expecting any message"));
 880         }
 881     }
 882
 883 public:
 884     LocalTransportAgentChild() :
 885         m_ret(0),
 886         m_forkexec(SyncEvo::ForkExecChild::create()),
 887         m_reportSent(false),
 888         m_status(INACTIVE)
 889     {
 890         m_forkexec->m_onConnect.connect(boost::bind(&LocalTransportAgentChild::onConnect, this, _1));
 891         m_forkexec->m_onFailure.connect(boost::bind(&LocalTransportAgentChild::onFailure, this, _1, _2));
 892         // When parent quits, we need to abort whatever we do and shut
 893         // down. There's no way how we can complete our work without it.
 894         //
 895         // Note that another way how this process can detect the
 896         // death of the parent is when it currently is waiting for
 897         // completion of a method call to the parent, like a request
 898         // for a password. However, that does not cover failures
 899         // like the parent not asking us to sync in the first place
 900         // and also does not work with libdbus (https://bugs.freedesktop.org/show_bug.cgi?id=49728).
 901         m_forkexec->m_onQuit.connect(&onParentQuit);
 902
 903         m_forkexec->connect();
 904     }
 905
 906     boost::shared_ptr<ChildLogger> createLogger()
 907     {
 908         return boost::shared_ptr<ChildLogger>(new ChildLogger(m_child));
 909     }
 910
 911     void run()
 912     {
 913         SuspendFlags &s = SuspendFlags::getSuspendFlags();
 914
 915         while (!m_parent) {
 916             if (s.getState() != SuspendFlags::NORMAL) {
 917                 SE_LOG_DEBUG(NULL, "aborted, returning while waiting for parent");
 918                 return;
 919             }
 920             step("waiting for parent");
 921         }
 922         while (!m_client) {
 923             if (s.getState() != SuspendFlags::NORMAL) {
 924                 SE_LOG_DEBUG(NULL, "aborted, returning while waiting for Sync() call from parent");
 925             }
 926             step("waiting for Sync() call from parent");
 927         }
 928         try {
 929             // ignore SIGINT signal in local sync helper from now on:
 930             // the parent process will handle those and tell us when
 931             // we are expected to abort by sending a SIGTERM
 932             struct sigaction new_action;
 933             memset(&new_action, 0, sizeof(new_action));
 934             new_action.sa_handler = SIG_IGN;
 935             sigemptyset(&new_action.sa_mask);
 936             sigaction(SIGINT, &new_action, NULL);
 937
 938             // SIGTERM would be caught by SuspendFlags and set the "abort"
 939             // state. But a lot of code running in this process cannot
 940             // check that flag in a timely manner (blocking calls in
 941             // libneon, activesync client libraries, ...). Therefore
 942             // it is better to abort inside the signal handler.
 943             new_action.sa_handler = abortLocalSync;
 944             sigaction(SIGTERM, &new_action, NULL);
 945
 946             SE_LOG_DEBUG(NULL, "LocalTransportChild: ignore SIGINT, die in SIGTERM");
 947             SE_LOG_INFO(NULL, "target side of local sync ready");
 948             m_client->sync(&m_clientReport);
 949         } catch (...) {
 950             string explanation;
 951             SyncMLStatus status = Exception::handle(explanation);
 952             m_clientReport.setStatus(status);
 953             if (!explanation.empty() &&
 954                 m_clientReport.getError().empty()) {
 955                 m_clientReport.setError(explanation);
 956             }
 957             if (m_parent) {
 958                 std::string report = m_clientReport.toString();
 959                 SE_LOG_DEBUG(NULL, "child sending sync report after failure:\n%s", report.c_str());
 960                 m_parent->m_storeSyncReport.start(report,
 961                                                   boost::bind(&LocalTransportAgentChild::syncReportReceived, this, _1));
 962                 // wait for acknowledgement for report once:
 963                 // we are in some kind of error state, better
 964                 // do not wait too long
 965                 if (m_parent) {
 966                     SE_LOG_DEBUG(NULL, "waiting for parent's ACK for sync report");
 967                     g_main_context_iteration(NULL, true);
 968                 }
 969             }
 970             throw;
 971         }
 972
 973         if (m_parent) {
 974             // send final report, ignore result
 975             std::string report = m_clientReport.toString();
 976             SE_LOG_DEBUG(NULL, "child sending sync report:\n%s", report.c_str());
 977             m_parent->m_storeSyncReport.start(report,
 978                                               boost::bind(&LocalTransportAgentChild::syncReportReceived, this, _1));
 979             while (!m_reportSent && m_parent &&
 980                    s.getState() == SuspendFlags::NORMAL) {
 981                 step("waiting for parent's ACK for sync report");
 982             }
 983         }
 984     }
 985
 986     void syncReportReceived(const std::string &error)
 987     {
 988         SE_LOG_DEBUG(NULL, "sending sync report to parent: %s",
 989                      error.empty() ? "done" : error.c_str());
 990         m_reportSent = true;
 991     }
 992
 993     int getReturnCode() const { return m_ret; }
 994
 995     /**
 996      * set transport specific URL of next message
 997      */
 998     virtual void setURL(const std::string &url) {}
 999
1000     /**
1001      * define content type for post, see content type constants
1002      */
1003     virtual void setContentType(const std::string &type)
1004     {
1005         m_contentType = type;
1006     }
1007
1008     /**
1009      * Requests an normal shutdown of the transport. This can take a
1010      * while, for example if communication is still pending.
1011      * Therefore wait() has to be called to ensure that the
1012      * shutdown is complete and that no error occurred.
1013      *
1014      * Simply deleting the transport is an *unnormal* shutdown that
1015      * does not communicate with the peer.
1016      */
1017     virtual void shutdown()
1018     {
1019         SE_LOG_DEBUG(NULL, "child local transport shutting down");
1020         if (m_msgToParent) {
1021             // Must send non-zero message, empty messages cause an
1022             // error during D-Bus message decoding on the receiving
1023             // side. Content doesn't matter, ignored by parent.
1024             m_msgToParent->done("shutdown-message", GDBusCXX::makeDBusArray(1, (uint8_t *)""));
1025             m_msgToParent.reset();
1026         }
1027         if (m_status != FAILED) {
1028             m_status = CLOSED;
1029         }
1030     }
1031
1032     /**
1033      * start sending message
1034      *
1035      * Memory must remain valid until reply is received or
1036      * message transmission is canceled.
1037      *
1038      * @param data      start address of data to send
1039      * @param len       number of bytes
1040      */
1041     virtual void send(const char *data, size_t len)
1042     {
1043         SE_LOG_DEBUG(NULL, "child local transport sending %ld bytes", (long)len);
1044         if (m_msgToParent) {
1045             m_status = ACTIVE;
1046             m_msgToParent->done(m_contentType, GDBusCXX::makeDBusArray(len, (uint8_t *)(data)));
1047             m_msgToParent.reset();
1048         } else {
1049             m_status = FAILED;
1050             SE_THROW("cannot send data to parent because parent is not waiting for message");
1051         }
1052     }
1053
1054     /**
1055      * cancel an active message transmission
1056      *
1057      * Blocks until send buffer is no longer in use.
1058      * Returns immediately if nothing pending.
1059      */
1060     virtual void cancel() {}
1061
1062
1063     /**
1064      * Wait for completion of an operation initiated earlier.
1065      * The operation can be a send with optional reply or
1066      * a close request.
1067      *
1068      * Returns immediately if no operations is pending.
1069      *
1070      * @param noReply    true if no reply is required for a running send;
1071      *                   only relevant for transports used by a SyncML server
1072      */
1073     virtual Status wait(bool noReply = false)
1074     {
1075         SuspendFlags &s = SuspendFlags::getSuspendFlags();
1076         while (m_status == ACTIVE &&
1077                s.getState() == SuspendFlags::NORMAL) {
1078             step("waiting for next message");
1079         }
1080         return m_status;
1081     }
1082
1083     /**
1084      * Tells the transport agent to stop the transmission the given
1085      * amount of seconds after send() was called. The transport agent
1086      * will then stop the message transmission and return a TIME_OUT
1087      * status in wait().
1088      *
1089      * @param seconds      number of seconds to wait before timing out, zero for no timeout
1090      */
1091     virtual void setTimeout(int seconds) {}
1092
1093     /**
1094      * provides access to reply data
1095      *
1096      * Memory pointer remains valid as long as
1097      * transport agent is not deleted and no other
1098      * message is sent.
1099      */
1100     virtual void getReply(const char *&data, size_t &len, std::string &contentType)
1101     {
1102         SE_LOG_DEBUG(NULL, "processing %ld bytes in child", (long)m_message.size());
1103         if (m_status != GOT_REPLY) {
1104             SE_THROW("getReply() called in child when no reply available");
1105         }
1106         data = m_message.c_str();
1107         len = m_message.size();
1108         contentType = m_messageType;
1109     }
1110 };
1111
1112 int LocalTransportMain(int argc, char **argv)
1113 {
1114     // delay the client for debugging purposes
1115     const char *delay = getenv("SYNCEVOLUTION_LOCAL_CHILD_DELAY");
1116     if (delay) {
1117         Sleep(atoi(delay));
1118     }
1119
1120     SyncContext::initMain("syncevo-local-sync");
1121
1122     // Our stderr is either connected to the original stderr (when
1123     // SYNCEVOLUTION_DEBUG is set) or the local sync's parent
1124     // LogRedirect. However, that stderr is not normally used.
1125     // Instead we install our own LogRedirect for both stdout (for
1126     // Execute() and synccompare, which then knows that it needs to
1127     // capture the output) and stderr (to get output like the one from
1128     // libneon into the child log) in LocalTransportAgentChild and
1129     // send all logging output to the local sync parent via D-Bus, to
1130     // be forwarded to the user as part of the normal message stream
1131     // of the sync session.
1132     setvbuf(stderr, NULL, _IONBF, 0);
1133     setvbuf(stdout, NULL, _IONBF, 0);
1134
1135     // SIGPIPE must be ignored, some system libs (glib GIO?) trigger
1136     // it. SIGINT/TERM will be handled via SuspendFlags once the sync
1137     // runs.
1138     struct sigaction sa;
1139     memset(&sa, 0, sizeof(sa));
1140     sa.sa_handler = SIG_IGN;
1141     sigaction(SIGPIPE, &sa, NULL);
1142
1143     try {
1144         if (getenv("SYNCEVOLUTION_DEBUG")) {
1145             Logger::instance().setLevel(Logger::DEBUG);
1146         }
1147         // process name will be set to target config name once it is known
1148         Logger::setProcessName("syncevo-local-sync");
1149
1150         boost::shared_ptr<LocalTransportAgentChild> child(new LocalTransportAgentChild);
1151         PushLogger<Logger> logger;
1152         // Temporary handle is necessary to avoid compiler issue with
1153         // clang (ambiguous brackets).
1154         {
1155             Logger::Handle handle(child->createLogger());
1156             logger.reset(handle);
1157         }
1158
1159 #ifdef USE_DLT
1160         // Set by syncevo-dbus-server for us.
1161         bool useDLT = getenv("SYNCEVOLUTION_USE_DLT") != NULL;
1162         PushLogger<LoggerDLT> loggerdlt;
1163         if (useDLT) {
1164             loggerdlt.reset(new LoggerDLT(DLT_SYNCEVO_LOCAL_HELPER_ID, "SyncEvolution local sync helper"));
1165         }
1166 #endif
1167
1168         child->run();
1169         int ret = child->getReturnCode();
1170         logger.reset();
1171         child.reset();
1172         return ret;
1173     } catch ( const std::exception &ex ) {
1174         SE_LOG_ERROR(NULL, "%s", ex.what());
1175     } catch (...) {
1176         SE_LOG_ERROR(NULL, "unknown error");
1177     }
1178
1179     return 1;
1180 }
1181
1182 SE_END_CXX