src/syncevo/SyncContext.cpp

   1 /*
   2  * Copyright (C) 2005-2009 Patrick Ohly <patrick.ohly@gmx.de>
   3  * Copyright (C) 2009 Intel Corporation
   4  *
   5  * This library is free software; you can redistribute it and/or
   6  * modify it under the terms of the GNU Lesser General Public
   7  * License as published by the Free Software Foundation; either
   8  * version 2.1 of the License, or (at your option) version 3.
   9  *
  10  * This library is distributed in the hope that it will be useful,
  11  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  12  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  13  * Lesser General Public License for more details.
  14  *
  15  * You should have received a copy of the GNU Lesser General Public
  16  * License along with this library; if not, write to the Free Software
  17  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
  18  * 02110-1301  USA
  19  */
  20
  21 #ifndef _GNU_SOURCE
  22 # define _GNU_SOURCE 1
  23 #endif
  24 #include <dlfcn.h>
  25
  26 #include <syncevo/SyncContext.h>
  27 #include <syncevo/SyncSource.h>
  28 #include <syncevo/util.h>
  29 #include <syncevo/SuspendFlags.h>
  30 #include <syncevo/ThreadSupport.h>
  31 #include <syncevo/IdentityProvider.h>
  32
  33 #include <syncevo/SafeConfigNode.h>
  34 #include <syncevo/IniConfigNode.h>
  35
  36 #include <syncevo/LogStdout.h>
  37 #include <syncevo/TransportAgent.h>
  38 #include <syncevo/CurlTransportAgent.h>
  39 #include <syncevo/SoupTransportAgent.h>
  40 #include <syncevo/ObexTransportAgent.h>
  41 #include <syncevo/LocalTransportAgent.h>
  42
  43 #include <list>
  44 #include <memory>
  45 #include <vector>
  46 #include <sstream>
  47 #include <fstream>
  48 #include <iomanip>
  49 #include <iostream>
  50 #include <stdexcept>
  51 #include <algorithm>
  52 #include <ctime>
  53 using namespace std;
  54
  55 #include <boost/algorithm/string/predicate.hpp>
  56 #include <boost/algorithm/string/join.hpp>
  57 #include <boost/foreach.hpp>
  58 #include <boost/algorithm/string/split.hpp>
  59 #include <boost/bind.hpp>
  60 #include <boost/utility.hpp>
  61
  62 #include <sys/stat.h>
  63 #include <sys/wait.h>
  64 #include <pwd.h>
  65 #include <unistd.h>
  66 #include <signal.h>
  67 #include <dirent.h>
  68 #include <errno.h>
  69 #include <pthread.h>
  70 #include <signal.h>
  71
  72 #include <synthesis/enginemodulebridge.h>
  73 #include <synthesis/SDK_util.h>
  74 #include <synthesis/san.h>
  75
  76 #ifdef USE_DLT
  77 # include <dlt.h>
  78 #endif
  79
  80 #include "test.h"
  81
  82 #include <syncevo/declarations.h>
  83 SE_BEGIN_CXX
  84
  85 SyncContext *SyncContext::m_activeContext;
  86
  87 static const char *LogfileBasename = "syncevolution-log";
  88
  89 SyncContext::SyncContext()
  90 {
  91     init();
  92 }
  93
  94 SyncContext::SyncContext(const string &server,
  95                          bool doLogging) :
  96     SyncConfig(server),
  97     m_server(server)
  98 {
  99     init();
 100     m_doLogging = doLogging;
 101 }
 102
 103 SyncContext::SyncContext(const string &client,
 104                          const string &server,
 105                          const string &rootPath,
 106                          const boost::shared_ptr<TransportAgent> &agent,
 107                          bool doLogging) :
 108     SyncConfig(client,
 109                boost::shared_ptr<ConfigTree>(),
 110                rootPath),
 111     m_server(client),
 112     m_localClientRootPath(rootPath),
 113     m_agent(agent)
 114 {
 115     init();
 116     initLocalSync(server);
 117     m_doLogging = doLogging;
 118 }
 119
 120 void SyncContext::initLocalSync(const string &config)
 121 {
 122     m_localSync = true;
 123     string tmp;
 124     splitConfigString(config, tmp, m_localPeerContext);
 125     m_localPeerContext.insert(0, "@");
 126 }
 127
 128 void SyncContext::init()
 129 {
 130     m_doLogging = false;
 131     m_quiet = false;
 132     m_dryrun = false;
 133     m_localSync = false;
 134     m_serverMode = false;
 135     m_serverAlerted = false;
 136     m_configNeeded = true;
 137     m_firstSourceAccess = true;
 138     m_remoteInitiated = false;
 139     m_sourceListPtr = NULL;
 140 }
 141
 142 SyncContext::~SyncContext()
 143 {
 144 }
 145
 146 /**
 147  * Utility code for parsing and comparing
 148  * log dir names. Also a binary predicate for
 149  * sorting them.
 150  */
 151 class LogDirNames {
 152 public:
 153     // internal prefix for backup directory name: "SyncEvolution-"
 154     static const char* const DIR_PREFIX;
 155
 156     /**
 157      * Compare two directory by its creation time encoded
 158      * in the directory name sort them in ascending order
 159      */
 160     bool operator() (const string &str1, const string &str2) {
 161         string iDirPath1, iStr1;
 162         string iDirPath2, iStr2;
 163         parseLogDir(str1, iDirPath1, iStr1);
 164         parseLogDir(str2, iDirPath2, iStr2);
 165         string dirPrefix1, peerName1, dateTime1;
 166         parseDirName(iStr1, dirPrefix1, peerName1, dateTime1);
 167         string dirPrefix2, peerName2, dateTime2;
 168         parseDirName(iStr2, dirPrefix2, peerName2, dateTime2);
 169         return dateTime1 < dateTime2;
 170     }
 171
 172     /**
 173      * extract backup directory name from a full backup path
 174      * for example, a full path "/home/xxx/.cache/syncevolution/default/funambol-2009-12-08-14-05"
 175      * is parsed as "/home/xxx/.cache/syncevolution/default" and "funambol-2009-12-08-14-05"
 176      */
 177     static void parseLogDir(const string &fullpath, string &dirPath, string &dirName) {
 178         string iFullpath = boost::trim_right_copy_if(fullpath, boost::is_any_of("/"));
 179         size_t off = iFullpath.find_last_of('/');
 180         if(off != iFullpath.npos) {
 181             dirPath = iFullpath.substr(0, off);
 182             dirName = iFullpath.substr(off+1);
 183         } else {
 184             dirPath = "";
 185             dirName = iFullpath;
 186         }
 187     }
 188
 189     // escape '-' and '_' for peer name
 190     static string escapePeer(const string &prefix) {
 191         string escaped = prefix;
 192         boost::replace_all(escaped, "_", "__");
 193         boost::replace_all(escaped, "-", "_+");
 194         return escaped;
 195     }
 196
 197     // un-escape '_+' and '__' for peer name
 198     static string unescapePeer(const string &escaped) {
 199         string prefix = escaped;
 200         boost::replace_all(prefix, "_+", "-");
 201         boost::replace_all(prefix, "__", "_");
 202         return prefix;
 203     }
 204
 205     /**
 206      * parse a directory name into dirPrefix(empty or DIR_PREFIX), peerName, dateTime.
 207      * peerName must be unescaped by the caller to get the real string.
 208      * If directory name is in the format of '[DIR_PREFIX]-peer[@context]-year-month-day-hour-min'
 209      * then parsing is sucessful and these 3 strings are correctly set and true is returned.
 210      * Otherwise, false is returned.
 211      * Here we don't check whether the dir name is matching peer name
 212      */
 213     static bool parseDirName(const string &dir, string &dirPrefix, string &config, string &dateTime) {
 214         string iDir = dir;
 215         if (!boost::starts_with(iDir, DIR_PREFIX)) {
 216             dirPrefix = "";
 217         } else {
 218             dirPrefix = DIR_PREFIX;
 219             boost::erase_first(iDir, DIR_PREFIX);
 220         }
 221         size_t off = iDir.find('-');
 222         if (off != iDir.npos) {
 223             config = iDir.substr(0, off);
 224             dateTime = iDir.substr(off);
 225             // m_prefix doesn't contain peer name or it equals with dirPrefix plus peerName
 226             return checkDirName(dateTime);
 227         }
 228         return false;
 229     }
 230
 231     // check the dir name is conforming to what format we write
 232     static bool checkDirName(const string& value) {
 233         const char* str = value.c_str();
 234         /** need check whether string after prefix is a valid date-time we wrote, format
 235          * should be -YYYY-MM-DD-HH-MM and optional sequence number */
 236         static char table[] = {'-','9','9','9','9', //year
 237                                '-','1','9', //month
 238                                '-','3','9', //date
 239                                '-','2','9', //hour
 240                                '-','5','9'  //minute
 241         };
 242         for(size_t i = 0; i < sizeof(table)/sizeof(table[0]) && *str; i++,str++) {
 243             switch(table[i]) {
 244                 case '-':
 245                     if(*str != '-')
 246                         return false;
 247                     break;
 248                 case '1':
 249                     if(*str < '0' || *str > '1')
 250                         return false;
 251                     break;
 252                 case '2':
 253                     if(*str < '0' || *str > '2')
 254                         return false;
 255                     break;
 256                 case '3':
 257                     if(*str < '0' || *str > '3')
 258                         return false;
 259                     break;
 260                 case '5':
 261                     if(*str < '0' || *str > '5')
 262                         return false;
 263                     break;
 264                 case '9':
 265                     if(*str < '0' || *str > '9')
 266                         return false;
 267                     break;
 268                 default:
 269                     return false;
 270             };
 271         }
 272         return true;
 273     }
 274 };
 275
 276 class LogDir;
 277
 278 /**
 279  * Helper class for LogDir: acts as proxy for logging into
 280  * the LogDir's reports and log file.
 281  */
 282 class LogDirLogger : public Logger
 283 {
 284     Logger::Handle m_parentLogger;     /**< the logger which was active before we started to intercept messages */
 285     boost::weak_ptr<LogDir> m_logdir;  /**< grants access to report and Synthesis engine */
 286 #ifdef USE_DLT
 287     bool m_useDLT;                     /**< SyncEvolution and libsynthesis are logging to DLT */
 288 #endif
 289
 290 public:
 291     LogDirLogger(const boost::weak_ptr<LogDir> &logdir);
 292     virtual void remove() throw ();
 293     virtual void messagev(const MessageOptions &options,
 294                           const char *format,
 295                           va_list args);
 296 };
 297
 298 // This class owns the logging directory. It is responsible
 299 // for redirecting output at the start and end of sync (even
 300 // in case of exceptions thrown!).
 301 class LogDir : private boost::noncopyable, private LogDirNames {
 302     SyncContext &m_client;
 303     string m_logdir;         /**< configured backup root dir */
 304     int m_maxlogdirs;        /**< number of backup dirs to preserve, 0 if unlimited */
 305     string m_prefix;         /**< common prefix of backup dirs */
 306     string m_path;           /**< path to current logging and backup dir */
 307     string m_logfile;        /**< Path to log file there, empty if not writing one.
 308                                   The file is no longer written by this class, nor
 309                                   does it control the basename of it. Writing the
 310                                   log file is enabled by the XML configuration that
 311                                   we prepare for the Synthesis engine; the base name
 312                                   of the file is hard-coded in the engine. Despite
 313                                   that this class still is the central point to ask
 314                                   for the name of the log file. */
 315     boost::scoped_ptr<SafeConfigNode> m_info;  /**< key/value representation of sync information */
 316
 317     // Access to m_report and m_client must be thread-safe as soon as
 318     // LogDirLogger is active, because they are shared between main
 319     // thread and any thread which might log errors.
 320     friend class LogDirLogger;
 321     bool m_readonly;         /**< m_info is not to be written to */
 322     SyncReport *m_report;    /**< record start/end times here */
 323
 324     boost::weak_ptr<LogDir> m_self;
 325     PushLogger<LogDirLogger> m_logger; /**< active logger */
 326
 327     LogDir(SyncContext &client) : m_client(client), m_info(NULL), m_readonly(false), m_report(NULL)
 328     {
 329         // Set default log directory. This will be overwritten with a user-specified
 330         // location later on, if one was selected by the user. SyncEvolution >= 0.9 alpha
 331         // and < 0.9 beta 2 used XDG_DATA_HOME because the logs and data base dumps
 332         // were not considered "non-essential data files". Because XDG_DATA_HOME is
 333         // searched for .desktop files and creating large amounts of other files there
 334         // slows down that search, the default was changed to XDG_CACHE_DIR.
 335         //
 336         // To migrate old installations seamlessly, this code here renames the old
 337         // default directory to the new one. Errors (like not found) are silently ignored.
 338         mkdir_p(SubstEnvironment("${XDG_CACHE_HOME}").c_str());
 339         rename(SubstEnvironment("${XDG_DATA_HOME}/applications/syncevolution").c_str(),
 340                SubstEnvironment("${XDG_CACHE_HOME}/syncevolution").c_str());
 341
 342         string path = m_client.getLogDir();
 343         if (path.empty()) {
 344             path = "${XDG_CACHE_HOME}/syncevolution";
 345         }
 346         setLogdir(path);
 347     }
 348
 349 public:
 350     static boost::shared_ptr<LogDir> create(SyncContext &client)
 351     {
 352         boost::shared_ptr<LogDir> logdir(new LogDir(client));
 353         logdir->m_self = logdir;
 354         return logdir;
 355     }
 356
 357     /**
 358      * Finds previous log directories for context. Reports errors via exceptions.
 359      *
 360      * @retval dirs       vector of full path names, oldest first
 361      */
 362     void previousLogdirs(vector<string> &dirs) {
 363         dirs.clear();
 364         getLogdirs(dirs);
 365     }
 366
 367     /**
 368      * Finds previous log directory. Returns empty string if anything went wrong.
 369      *
 370      * @param path        path to configured backup directy, NULL if defaulting to /tmp, "none" if not creating log file
 371      * @return full path of previous log directory, empty string if not found
 372      */
 373     string previousLogdir() throw() {
 374         try {
 375             vector<string> dirs;
 376             previousLogdirs(dirs);
 377             return dirs.empty() ? "" : dirs.back();
 378         } catch (...) {
 379             Exception::handle();
 380             return "";
 381         }
 382     }
 383
 384     /**
 385      * Set log dir and base name used for searching and creating sessions.
 386      * Default if not called is the getLogDir() value of the context.
 387      *
 388      * @param logdir     "none" to disable sessions, "" for default, may contain ${}
 389      *                   for environment variables
 390      */
 391     void setLogdir(const string &logdir) {
 392         if (logdir.empty()) {
 393             return;
 394         }
 395         m_logdir = SubstEnvironment(logdir);
 396         m_logdir = boost::trim_right_copy_if(m_logdir, boost::is_any_of("/"));
 397         if (m_logdir == "none") {
 398             return;
 399         }
 400
 401         // the config name has been normalized
 402         string peer = m_client.getConfigName();
 403
 404         // escape "_" and "-" the peer name
 405         peer = escapePeer(peer);
 406
 407         if (boost::iends_with(m_logdir, "syncevolution")) {
 408             // use just the server name as prefix
 409             m_prefix = peer;
 410         } else {
 411             // SyncEvolution-<server>-<yyyy>-<mm>-<dd>-<hh>-<mm>
 412             m_prefix = DIR_PREFIX;
 413             m_prefix += peer;
 414         }
 415     }
 416
 417     /**
 418      * access existing log directory to extract status information
 419      */
 420     void openLogdir(const string &dir) {
 421         boost::shared_ptr<ConfigNode> filenode(new IniFileConfigNode(dir, "status.ini", true));
 422         m_info.reset(new SafeConfigNode(filenode));
 423         m_info->setMode(false);
 424         m_readonly = true;
 425     }
 426     /*
 427      * get the corresponding peer name encoded in the logging dir name.
 428      * The dir name must match the format(see startSession). Otherwise,
 429      * empty string is returned.
 430      */
 431     string getPeerNameFromLogdir(const string &dir) {
 432         // extract the dir name from the fullpath
 433         string iDirPath, iDirName;
 434         parseLogDir(dir, iDirPath, iDirName);
 435         // extract the peer name from the dir name
 436         string dirPrefix, peerName, dateTime;
 437         if(parseDirName(iDirName, dirPrefix, peerName, dateTime)) {
 438             return unescapePeer(peerName);
 439         }
 440         return "";
 441     }
 442
 443     /**
 444      * read sync report for session selected with openLogdir()
 445      */
 446     void readReport(SyncReport &report) {
 447         report.clear();
 448         if (!m_info) {
 449             return;
 450         }
 451         *m_info >> report;
 452     }
 453
 454     /**
 455      * write sync report for current session
 456      */
 457     void writeReport(SyncReport &report) {
 458         if (m_info) {
 459             *m_info << report;
 460
 461             /* write in slightly different format and flush at the end */
 462             writeTimestamp("start", report.getStart(), false);
 463             writeTimestamp("end", report.getEnd(), true);
 464         }
 465     }
 466
 467     enum SessionMode {
 468         SESSION_USE_PATH,      /**< write directly into path, don't create and manage subdirectories */
 469         SESSION_READ_ONLY,     /**< access an existing session directory identified with path */
 470         SESSION_CREATE         /**< create a new session directory inside the given path */
 471     };
 472
 473     // setup log directory and redirect logging into it
 474     // @param path        path to configured backup directy, empty for using default, "none" if not creating log file
 475     // @param mode        determines how path is interpreted and which session is accessed
 476     // @param maxlogdirs  number of backup dirs to preserve in path, 0 if unlimited
 477     // @param logLevel    0 = default, 1 = ERROR, 2 = INFO, 3 = DEBUG
 478     // @param report      record information about session here (may be NULL)
 479     void startSession(const string &path, SessionMode mode, int maxlogdirs, int logLevel, SyncReport *report) {
 480         m_maxlogdirs = maxlogdirs;
 481         m_report = report;
 482         m_logfile = "";
 483         if (boost::iequals(path, "none")) {
 484             m_path = "";
 485         } else {
 486             setLogdir(path);
 487             if (mode == SESSION_CREATE) {
 488                 // create unique directory name in the given directory
 489                 time_t ts = time(NULL);
 490                 struct tm tmbuffer;
 491                 struct tm *tm = localtime_r(&ts, &tmbuffer);
 492                 if (!tm) {
 493                     SE_THROW("localtime_r() failed");
 494                 }
 495                 stringstream base;
 496                 base << "-"
 497                      << setfill('0')
 498                      << setw(4) << tm->tm_year + 1900 << "-"
 499                      << setw(2) << tm->tm_mon + 1 << "-"
 500                      << setw(2) << tm->tm_mday << "-"
 501                      << setw(2) << tm->tm_hour << "-"
 502                      << setw(2) << tm->tm_min;
 503                 // If other sessions, regardless of which peer, have
 504                 // the same date and time, then append a sequence
 505                 // number to ensure correct sorting. Solve this by
 506                 // finding the maximum sequence number for any kind of
 507                 // date time. Backwards running clocks or changing the
 508                 // local time will still screw our ordering, though.
 509                 typedef std::map<string, int> SeqMap_t;
 510                 SeqMap_t dateTimes2Seq;
 511                 if (isDir(m_logdir)) {
 512                     ReadDir dir(m_logdir);
 513                     BOOST_FOREACH(const string &entry, dir) {
 514                         string dirPrefix, peerName, dateTime;
 515                         if (parseDirName(entry, dirPrefix, peerName, dateTime)) {
 516                             // dateTime = -2010-01-31-12-00[-rev]
 517                             size_t off = 0;
 518                             for (int i = 0; off != dateTime.npos && i < 5; i++) {
 519                                 off = dateTime.find('-', off + 1);
 520                             }
 521                             int sequence;
 522                             if (off != dateTime.npos) {
 523                                 sequence = dateTime[off + 1] - 'a';
 524                                 dateTime.resize(off);
 525                             } else {
 526                                 sequence = -1;
 527                             }
 528                             pair <SeqMap_t::iterator, bool> entry = dateTimes2Seq.insert(make_pair(dateTime, sequence));
 529                             if (sequence > entry.first->second) {
 530                                 entry.first->second = sequence;
 531                             }
 532                         }
 533                     }
 534                 }
 535                 stringstream path;
 536                 path << base.str();
 537                 SeqMap_t::iterator it = dateTimes2Seq.find(path.str());
 538                 if (it != dateTimes2Seq.end()) {
 539                     path << "-" << (char)('a' + it->second + 1);
 540                 }
 541                 m_path = m_logdir + "/";
 542                 m_path += m_prefix;
 543                 m_path += path.str();
 544                 mkdir_p(m_path);
 545             } else {
 546                 m_path = m_logdir;
 547                 if (mkdir(m_path.c_str(), S_IRWXU) &&
 548                     errno != EEXIST) {
 549                     SE_LOG_DEBUG(NULL, "%s: %s", m_path.c_str(), strerror(errno));
 550                     SyncContext::throwError(m_path, errno);
 551                 }
 552             }
 553             m_logfile = m_path + "/" + LogfileBasename + ".html";
 554         }
 555
 556         // update log level of default logger and our own replacement
 557         Logger::Level level;
 558         switch (logLevel) {
 559         case 0:
 560             // default for console output
 561             level = Logger::INFO;
 562             break;
 563         case 1:
 564             level = Logger::ERROR;
 565             break;
 566         case 2:
 567             level = Logger::INFO;
 568             break;
 569         default:
 570             if (m_logfile.empty() || getenv("SYNCEVOLUTION_DEBUG")) {
 571                 // no log file or user wants to see everything:
 572                 // print all information to the console
 573                 level = Logger::DEBUG;
 574             } else {
 575                 // have log file: avoid excessive output to the console,
 576                 // full information is in the log file
 577                 level = Logger::INFO;
 578             }
 579             break;
 580         }
 581         if (mode != SESSION_USE_PATH) {
 582             Logger::instance().setLevel(level);
 583         }
 584         boost::shared_ptr<Logger> logger(new LogDirLogger(m_self));
 585         logger->setLevel(level);
 586         m_logger.reset(logger);
 587
 588         time_t start = time(NULL);
 589         if (m_report) {
 590             m_report->setStart(start);
 591         }
 592         m_readonly = mode == SESSION_READ_ONLY;
 593         if (!m_path.empty()) {
 594             boost::shared_ptr<ConfigNode> filenode(new IniFileConfigNode(m_path, "status.ini", m_readonly));
 595             m_info.reset(new SafeConfigNode(filenode));
 596             m_info->setMode(false);
 597             if (mode != SESSION_READ_ONLY) {
 598                 // Create a status.ini which contains an error.
 599                 // Will be overwritten later on, unless we crash.
 600                 m_info->setProperty("status", STATUS_DIED_PREMATURELY);
 601                 m_info->setProperty("error", InitStateString("synchronization process died prematurely", true));
 602                 writeTimestamp("start", start);
 603             }
 604         }
 605     }
 606
 607     /** sets a fixed directory for database files without redirecting logging */
 608     void setPath(const string &path) { m_path = path; }
 609
 610     // return log directory, empty if not enabled
 611     const string &getLogdir() {
 612         return m_path;
 613     }
 614
 615     // return log file, empty if not enabled
 616     const string &getLogfile() {
 617         return m_logfile;
 618     }
 619
 620     /**
 621      * remove backup dir(s) if exceeding limit
 622      *
 623      * Assign a priority to each session dir, with lower
 624      * meaning "less important". Then sort by priority and (if
 625      * equal) creation time (aka index) in ascending
 626      * order. The sessions at the beginning of the sorted
 627      * vector are then removed first.
 628      *
 629      * DUMPS = any kind of database dump was made
 630      * ERROR = session failed
 631      * CHANGES = local data modified since previous dump (based on dumps
 632      *           of the current peer, for simplicity reasons),
 633      *           dump created for the first time,
 634      *           changes made during sync (detected with dumps and statistics)
 635      *
 636      * The goal is to preserve as many database dumps as possible
 637      * and ideally those where something happened.
 638      *
 639      * Some criteria veto the removal of a session:
 640      * - it is the only one holding a dump of a specific source
 641      * - it is the last session
 642      */
 643     void expire() {
 644         if (m_logdir.size() && m_maxlogdirs > 0 ) {
 645             vector<string> dirs;
 646             getLogdirs(dirs);
 647
 648             /** stores priority and index in "dirs"; after sorting, delete from the start */
 649             vector< pair<Priority, size_t> > victims;
 650             /** maps from source name to list of information about dump, oldest first */
 651             typedef map< string, list<DumpInfo> > Dumps_t;
 652             Dumps_t dumps;
 653             for (size_t i = 0;
 654                  i < dirs.size();
 655                  i++) {
 656                 bool changes = false;
 657                 bool havedumps = false;
 658                 bool errors = false;
 659
 660                 LogDir logdir(m_client);
 661                 logdir.openLogdir(dirs[i]);
 662                 SyncReport report;
 663                 logdir.readReport(report);
 664                 SyncMLStatus status = report.getStatus();
 665                 if (status != STATUS_OK && status != STATUS_HTTP_OK) {
 666                     errors = true;
 667                 }
 668                 BOOST_FOREACH(SyncReport::SourceReport_t source, report) {
 669                     string &sourcename = source.first;
 670                     SyncSourceReport &sourcereport = source.second;
 671                     list<DumpInfo> &dumplist = dumps[sourcename];
 672                     if (sourcereport.m_backupBefore.isAvailable() ||
 673                         sourcereport.m_backupAfter.isAvailable()) {
 674                         // yes, we have backup dumps
 675                         havedumps = true;
 676
 677                         DumpInfo info(i,
 678                                       sourcereport.m_backupBefore.getNumItems(),
 679                                       sourcereport.m_backupAfter.getNumItems());
 680
 681                         // now check for changes, if none found yet
 682                         if (!changes) {
 683                             if (dumplist.empty()) {
 684                                 // new backup dump
 685                                 changes = true;
 686                             } else {
 687                                 DumpInfo &previous = dumplist.back();
 688                                 changes =
 689                                     // item count changed -> items changed
 690                                     previous.m_itemsDumpedAfter != info.m_itemsDumpedBefore ||
 691                                     sourcereport.wasChanged(SyncSourceReport::ITEM_LOCAL) ||
 692                                     sourcereport.wasChanged(SyncSourceReport::ITEM_REMOTE) ||
 693                                     haveDifferentContent(sourcename,
 694                                                          dirs[previous.m_dirIndex], "after",
 695                                                          dirs[i], "before");
 696                             }
 697                         }
 698
 699                         dumplist.push_back(info);
 700                     }
 701                 }
 702                 Priority pri =
 703                     havedumps ?
 704                     (changes ?
 705                      HAS_DUMPS_WITH_CHANGES :
 706                      errors ?
 707                      HAS_DUMPS_NO_CHANGES_WITH_ERRORS :
 708                      HAS_DUMPS_NO_CHANGES) :
 709                     (changes ?
 710                      NO_DUMPS_WITH_CHANGES :
 711                      errors ?
 712                      NO_DUMPS_WITH_ERRORS :
 713                      NO_DUMPS_NO_ERRORS);
 714                 victims.push_back(make_pair(pri, i));
 715             }
 716             sort(victims.begin(), victims.end());
 717
 718             int deleted = 0;
 719             for (size_t e = 0;
 720                  e < victims.size() && (int)dirs.size() - deleted > m_maxlogdirs;
 721                  ++e) {
 722                 size_t index = victims[e].second;
 723                 string &path = dirs[index];
 724                 // preserve latest session
 725                 if (index != dirs.size() - 1) {
 726                     bool mustkeep = false;
 727                     // also check whether it holds the only backup of a source
 728                     BOOST_FOREACH(Dumps_t::value_type dump, dumps) {
 729                         if (dump.second.size() == 1 &&
 730                             dump.second.front().m_dirIndex == index) {
 731                             mustkeep = true;
 732                             break;
 733                         }
 734                     }
 735                     if (!mustkeep) {
 736                         SE_LOG_DEBUG(NULL, "removing %s", path.c_str());
 737                         rm_r(path);
 738                         ++deleted;
 739                     }
 740                 }
 741             }
 742         }
 743     }
 744
 745     // finalize session
 746     void endSession()
 747     {
 748         time_t end = time(NULL);
 749         if (m_report) {
 750             m_report->setEnd(end);
 751         }
 752         if (m_info) {
 753             if (!m_readonly) {
 754                 writeTimestamp("end", end);
 755                 if (m_report) {
 756                     RecMutex::Guard guard = Logger::lock();
 757                     writeReport(*m_report);
 758                 }
 759                 m_info->flush();
 760             }
 761             m_info.reset();
 762         }
 763     }
 764
 765     // Remove redirection of logging.
 766     void restore() {
 767         m_logger.reset();
 768     }
 769
 770     ~LogDir() {
 771         restore();
 772     }
 773
 774
 775 #if 0
 776     /**
 777      * A quick check for level = SHOW text dumps whether the text dump
 778      * starts with the [ERROR] prefix; used to detect error messages
 779      * from forked process which go through this instance but are not
 780      * already tagged as error messages and thus would not show up as
 781      * "first error" in sync reports.
 782      *
 783      * Example for the problem:
 784      * [ERROR] onConnect not implemented                [from child process]
 785      * [ERROR] child process quit with return code 1    [from parent]
 786      * ...
 787      * Changes applied during synchronization:
 788      * ...
 789      * First ERROR encountered: child process quit with return code 1
 790      */
 791     static bool isErrorString(const char *format,
 792                               va_list args)
 793     {
 794         const char *text;
 795         if (!strcmp(format, "%s")) {
 796             va_list argscopy;
 797             va_copy(argscopy, args);
 798             text = va_arg(argscopy, const char *);
 799             va_end(argscopy);
 800         } else {
 801             text = format;
 802         }
 803         return boost::starts_with(text, "[ERROR");
 804     }
 805 #endif
 806
 807     /**
 808      * Compare two database dumps just based on their inodes.
 809      * @return true    if inodes differ
 810      */
 811     static bool haveDifferentContent(const string &sourceName,
 812                                      const string &firstDir,
 813                                      const string &firstSuffix,
 814                                      const string &secondDir,
 815                                      const string &secondSuffix)
 816     {
 817         string first = firstDir + "/" + sourceName + "." + firstSuffix;
 818         string second = secondDir + "/" + sourceName + "." + secondSuffix;
 819         ReadDir firstContent(first);
 820         ReadDir secondContent(second);
 821         set<ino_t> firstInodes;
 822         BOOST_FOREACH(const string &name, firstContent) {
 823             struct stat buf;
 824             string fullpath = first + "/" + name;
 825             if (stat(fullpath.c_str(), &buf)) {
 826                 SyncContext::throwError(fullpath, errno);
 827             }
 828             firstInodes.insert(buf.st_ino);
 829         }
 830         BOOST_FOREACH(const string &name, secondContent) {
 831             struct stat buf;
 832             string fullpath = second + "/" + name;
 833             if (stat(fullpath.c_str(), &buf)) {
 834                 SyncContext::throwError(fullpath, errno);
 835             }
 836             set<ino_t>::iterator it = firstInodes.find(buf.st_ino);
 837             if (it == firstInodes.end()) {
 838                 // second dir has different file
 839                 return true;
 840             } else {
 841                 firstInodes.erase(it);
 842             }
 843         }
 844         if (!firstInodes.empty()) {
 845             // first dir has different file
 846             return true;
 847         }
 848         // exact match of inodes
 849         return false;
 850     }
 851
 852 private:
 853     enum Priority {
 854         NO_DUMPS_NO_ERRORS,
 855         NO_DUMPS_WITH_ERRORS,
 856         NO_DUMPS_WITH_CHANGES,
 857         HAS_DUMPS_NO_CHANGES,
 858         HAS_DUMPS_NO_CHANGES_WITH_ERRORS,
 859         HAS_DUMPS_WITH_CHANGES
 860     };
 861
 862     struct DumpInfo {
 863         size_t m_dirIndex;
 864         int m_itemsDumpedBefore;
 865         int m_itemsDumpedAfter;
 866         DumpInfo(size_t dirIndex,
 867                  int itemsDumpedBefore,
 868                  int itemsDumpedAfter) :
 869             m_dirIndex(dirIndex),
 870             m_itemsDumpedBefore(itemsDumpedBefore),
 871             m_itemsDumpedAfter(itemsDumpedAfter)
 872         {}
 873     };
 874
 875     /**
 876      * Find all entries in a given directory, return as sorted array of full paths in ascending order.
 877      * If m_prefix doesn't contain peer name information, then all log dirs for different peers in the
 878      * logdir are returned.
 879      */
 880     void getLogdirs(vector<string> &dirs) {
 881         if (m_logdir != "none" && !isDir(m_logdir)) {
 882             return;
 883         }
 884         string peer = m_client.getConfigName();
 885         string peerName, context;
 886         SyncConfig::splitConfigString(peer, peerName, context);
 887
 888         ReadDir dir(m_logdir);
 889         BOOST_FOREACH(const string &entry, dir) {
 890             string tmpDirPrefix, tmpPeer, tmpDateTime;
 891             // if directory name could not be parsed, ignore it
 892             if(parseDirName(entry, tmpDirPrefix, tmpPeer, tmpDateTime)) {
 893                 if(!peerName.empty() && (m_prefix == (tmpDirPrefix + tmpPeer))) {
 894                     // if peer name exists, match the logs for the given peer
 895                     dirs.push_back(m_logdir + "/" + entry);
 896                 } else if(peerName.empty()) {
 897                     // if no peer name and only context, match for all logs under the given context
 898                     string tmpName, tmpContext;
 899                     SyncConfig::splitConfigString(unescapePeer(tmpPeer), tmpName, tmpContext);
 900                     if( context == tmpContext && boost::starts_with(m_prefix, tmpDirPrefix)) {
 901                         dirs.push_back(m_logdir + "/" + entry);
 902                     }
 903                 }
 904             }
 905         }
 906         // sort vector in ascending order
 907         // if no peer name
 908         if(peerName.empty()){
 909             sort(dirs.begin(), dirs.end(), LogDirNames());
 910         } else {
 911             sort(dirs.begin(), dirs.end());
 912         }
 913     }
 914
 915     // store time stamp in session info
 916     void writeTimestamp(const string &key, time_t val, bool flush = true) {
 917         if (m_info) {
 918             char buffer[160];
 919             struct tm tmbuffer, *tm;
 920             // be nice and store a human-readable date in addition the seconds since the epoch
 921             tm = localtime_r(&val, &tmbuffer);
 922             if (tm) {
 923                 strftime(buffer, sizeof(buffer), "%s, %Y-%m-%d %H:%M:%S %z", tm);
 924             } else {
 925                 // Less suitable fallback. Won't work correctly for 32
 926                 // bit long beyond 2038.
 927                 sprintf(buffer, "%lu", (long unsigned)val);
 928             }
 929             m_info->setProperty(key, buffer);
 930             if (flush) {
 931                 m_info->flush();
 932             }
 933         }
 934     }
 935 };
 936
 937 LogDirLogger::LogDirLogger(const boost::weak_ptr<LogDir> &logdir) :
 938     m_parentLogger(Logger::instance()),
 939     m_logdir(logdir)
 940 #ifdef USE_DLT
 941     , m_useDLT(getenv("SYNCEVOLUTION_USE_DLT") != NULL)
 942 #endif
 943 {
 944 }
 945
 946 void LogDirLogger::remove() throw ()
 947 {
 948     // Forget reference to LogDir. This prevents accessing it in
 949     // future messagev() calls.
 950     RecMutex::Guard guard = Logger::lock();
 951     m_logdir.reset();
 952 }
 953
 954 void LogDirLogger::messagev(const MessageOptions &options,
 955                             const char *format,
 956                             va_list args)
 957 {
 958     // Protects ordering of log messages and access to shared
 959     // variables like m_report and m_engine.
 960     RecMutex::Guard guard = Logger::lock();
 961
 962     // always to parent first (usually stdout):
 963     // if the parent is a LogRedirect instance, then
 964     // it'll flush its own output first, which ensures
 965     // that the new output comes later (as desired)
 966     va_list argscopy;
 967     va_copy(argscopy, args);
 968     m_parentLogger.messagev(options, format, argscopy);
 969     va_end(argscopy);
 970
 971     // Special handling of our own messages: include in sync report
 972     // (always, because that is how we did it traditionally) and write
 973     // to our own syncevolution-log.html (if not already logged).
 974     //
 975     // The TestLocalSync.testServerFailure and some others check that
 976     // we record the child's error message in our sync report. If we
 977     // don't then it shows up later marked as an "error on the target
 978     // side", which is probably not what we want.
 979     boost::shared_ptr<LogDir> logdir;
 980     if ((bool)(logdir = m_logdir.lock())) {
 981         if (logdir->m_report &&
 982             options.m_level <= ERROR &&
 983             logdir->m_report->getError().empty()) {
 984             va_list argscopy;
 985             va_copy(argscopy, args);
 986             string error = StringPrintfV(format, argscopy);
 987             va_end(argscopy);
 988
 989             logdir->m_report->setError(error);
 990         }
 991
 992         if (!(options.m_flags & MessageOptions::ALREADY_LOGGED) &&
 993 #ifdef USE_DLT
 994             // Don't send to  libsynthesis if using DLT,
 995             // because then it would end up getting logged
 996             // in DLT twice.
 997             !m_useDLT &&
 998 #endif
 999             logdir->m_client.getEngine().get()) {
1000             va_list argscopy;
1001             va_copy(argscopy, args);
1002             // Once to Synthesis log, with full debugging.
1003             // The API does not support a process name, so
1004             // put it into the prefix as "<procname> <prefix>".
1005             std::string prefix;
1006             if (options.m_processName) {
1007                 prefix += *options.m_processName;
1008             }
1009             if (options.m_prefix) {
1010                 if (!prefix.empty()) {
1011                     prefix += " ";
1012                 }
1013                 prefix += *options.m_prefix;
1014             }
1015             logdir->m_client.getEngine().doDebug(options.m_level,
1016                                                  prefix.empty() ? NULL : prefix.c_str(),
1017                                                  options.m_file,
1018                                                  options.m_line,
1019                                                  options.m_function,
1020                                                  format,
1021                                                  argscopy);
1022             va_end(argscopy);
1023         }
1024     }
1025 }
1026
1027
1028 const char* const LogDirNames::DIR_PREFIX = "SyncEvolution-";
1029
1030 /**
1031  * This class owns the sync sources. For historic reasons (required
1032  * by Funambol) SyncSource instances are stored as plain pointers
1033  * deleted by this class. Virtual sync sources were added later
1034  * and are stored as shared pointers which are freed automatically.
1035  * It is possible to iterate over the two classes of sources
1036  * separately.
1037  *
1038  * The SourceList ensures that all sources (normal and virtual) have
1039  * a valid and unique integer ID as needed for Synthesis. Traditionally
1040  * this used to be a simple hash of the source name (which is unique
1041  * by design), without checking for hash collisions. Now the ID is assigned
1042  * the first time a source is added here and doesn't have one yet.
1043  * For backward compatibility (the ID is stored in the .synthesis dir),
1044  * the same Hash() value is tested first. Assuming that there were no
1045  * hash conflicts, the same IDs will be generated as before.
1046  *
1047  * Together with a logdir, the SourceList
1048  * handles writing of per-sync files as well as the final report.
1049  * It is not stateless. The expectation is that it is instantiated
1050  * together with a SyncContext for one particular operation (sync
1051  * session, status check, restore). In contrast to a SyncContext,
1052  * this class has to be recreated for another operation.
1053  *
1054  * When running as client, only the active sources get added. They can
1055  * be dumped one after the other before running a sync.
1056  *
1057  * As a server, all sources get added, regardless whether they are
1058  * active. This implies that at least their "type" must be valid. Then
1059  * later when a client really starts using them, they are opened() and
1060  * database dumps are made.
1061  *
1062  * Virtual datastores are stored here when they get initialized
1063  * together with the normal sources by the user of SourceList.
1064  *
1065  *
1066  */
1067 class SourceList : private vector<SyncSource *> {
1068     typedef vector<SyncSource *> inherited;
1069
1070 public:
1071     enum LogLevel {
1072         LOGGING_QUIET,    /**< avoid all extra output */
1073         LOGGING_SUMMARY,  /**< sync report, but no database comparison */
1074         LOGGING_FULL      /**< everything */
1075     };
1076
1077     typedef std::vector< boost::shared_ptr<VirtualSyncSource> > VirtualSyncSources_t;
1078
1079     /** reading our set of virtual sources is okay, modifying it is not */
1080     const VirtualSyncSources_t &getVirtualSources() { return m_virtualSources; }
1081     void addSource(const boost::shared_ptr<VirtualSyncSource> &source) { checkSource(source.get()); m_virtualSources.push_back(source); }
1082
1083     using inherited::iterator;
1084     using inherited::const_iterator;
1085     using inherited::empty;
1086     using inherited::begin;
1087     using inherited::end;
1088     using inherited::rbegin;
1089     using inherited::rend;
1090     using inherited::size;
1091
1092     /** transfers ownership (historic reasons for storing plain pointer...) */
1093     void addSource(cxxptr<SyncSource> &source) { checkSource(source); push_back(source.release()); }
1094
1095 private:
1096     VirtualSyncSources_t m_virtualSources; /**< all configured virtual data sources (aka Synthesis <superdatastore>) */
1097     boost::shared_ptr<LogDir> m_logdir;     /**< our logging directory */
1098     SyncContext &m_client; /**< the context in which we were instantiated */
1099     set<string> m_prepared;   /**< remember for which source we dumped databases successfully */
1100     string m_intro;      /**< remembers the dumpLocalChanges() intro and only prints it again
1101                             when different from last dumpLocalChanges() call */
1102     bool m_doLogging;    /**< true iff the normal logdir handling is enabled
1103                             (creating and expiring directoties, before/after comparison) */
1104     bool m_reportTodo;   /**< true if syncDone() shall print a final report */
1105     LogLevel m_logLevel; /**< chooses how much information is printed */
1106     string m_previousLogdir; /**< remember previous log dir before creating the new one */
1107
1108     /** create name in current (if set) or previous logdir */
1109     string databaseName(SyncSource &source, const string suffix, string logdir = "") {
1110         if (!logdir.size()) {
1111             logdir = m_logdir->getLogdir();
1112         }
1113         return logdir + "/" +
1114             source.getName() + "." + suffix;
1115     }
1116
1117     /** ensure that Synthesis ID is set and unique */
1118     void checkSource(SyncSource *source) {
1119         if (source->getSynthesisID()) {
1120             return;
1121         }
1122         int id = Hash(source->getName()) % INT_MAX;
1123         while (true) {
1124             // avoid negative values
1125             if (id < 0) {
1126                 id = -id;
1127             }
1128             // avoid zero, it means unset
1129             if (!id) {
1130                 id = 1;
1131             }
1132             // check for collisions
1133             bool collision = false;
1134             BOOST_FOREACH(const string &other, m_client.getSyncSources()) {
1135                 boost::shared_ptr<PersistentSyncSourceConfig> sc(m_client.getSyncSourceConfig(other));
1136                 int other_id = sc->getSynthesisID();
1137                 if (other_id == id) {
1138                     ++id;
1139                     collision = true;
1140                     break;
1141                 }
1142             }
1143             if (!collision) {
1144                 source->setSynthesisID(id);
1145                 return;
1146             }
1147         }
1148     }
1149
1150 public:
1151     /** allow iterating over sources */
1152     const inherited *getSourceSet() const { return this; }
1153
1154     LogLevel getLogLevel() const { return m_logLevel; }
1155     void setLogLevel(LogLevel logLevel) { m_logLevel = logLevel; }
1156
1157     /**
1158      * Dump into files with a certain suffix, optionally store report
1159      * in member of SyncSourceReport. Remembers which sources were
1160      * dumped before a sync and only dumps those again afterward.
1161      *
1162      * @param suffix        "before/after/current" - before sync, after sync, during status check
1163      * @param excludeSource when not empty, only dump that source
1164      */
1165     void dumpDatabases(const string &suffix,
1166                        BackupReport SyncSourceReport::*report,
1167                        const string &excludeSource = "") {
1168         // Identify all logdirs of current context, of any peer.  Used
1169         // to search for previous backups of each source, if
1170         // necessary.
1171         SyncContext context(m_client.getContextName());
1172         boost::shared_ptr<LogDir> logdir(LogDir::create(context));
1173         vector<string> dirs;
1174         logdir->previousLogdirs(dirs);
1175
1176         BOOST_FOREACH(SyncSource *source, *this) {
1177             if ((!excludeSource.empty() && excludeSource != source->getName()) ||
1178                 (suffix == "after" && m_prepared.find(source->getName()) == m_prepared.end())) {
1179                 continue;
1180             }
1181
1182             string dir = databaseName(*source, suffix);
1183             boost::shared_ptr<ConfigNode> node = ConfigNode::createFileNode(dir + ".ini");
1184             SE_LOG_DEBUG(NULL, "creating %s", dir.c_str());
1185             rm_r(dir);
1186             BackupReport dummy;
1187             if (source->getOperations().m_backupData) {
1188                 SyncSource::Operations::ConstBackupInfo oldBackup;
1189                 // Now look for a backup of the current source,
1190                 // starting with the most recent one.
1191                 for (vector<string>::const_reverse_iterator it = dirs.rbegin();
1192                      it != dirs.rend();
1193                      ++it) {
1194                     const string &sessiondir = *it;
1195                     string oldBackupDir;
1196                     SyncSource::Operations::BackupInfo::Mode mode =
1197                         SyncSource::Operations::BackupInfo::BACKUP_AFTER;
1198                     oldBackupDir = databaseName(*source, "after", sessiondir);
1199                     if (!isDir(oldBackupDir)) {
1200                         mode = SyncSource::Operations::BackupInfo::BACKUP_BEFORE;
1201                         oldBackupDir = databaseName(*source, "before", sessiondir);
1202                         if (!isDir(oldBackupDir)) {
1203                             // try next session
1204                             continue;
1205                         }
1206                     }
1207
1208                     oldBackup.m_mode = mode;
1209                     oldBackup.m_dirname = oldBackupDir;
1210                     oldBackup.m_node = ConfigNode::createFileNode(oldBackupDir + ".ini");
1211                     break;
1212                 }
1213                 mkdir_p(dir);
1214                 SyncSource::Operations::BackupInfo newBackup(suffix == "before" ?
1215                                                              SyncSource::Operations::BackupInfo::BACKUP_BEFORE :
1216                                                              suffix == "after" ?
1217                                                              SyncSource::Operations::BackupInfo::BACKUP_AFTER :
1218                                                              SyncSource::Operations::BackupInfo::BACKUP_OTHER,
1219                                                              dir, node);
1220                 source->getOperations().m_backupData(oldBackup, newBackup,
1221                                                      report ? source->*report : dummy);
1222                 SE_LOG_DEBUG(NULL, "%s created", dir.c_str());
1223
1224                 // remember that we have dumped at the beginning of a sync
1225                 if (suffix == "before") {
1226                     m_prepared.insert(source->getName());
1227                 }
1228             }
1229         }
1230     }
1231
1232     void restoreDatabase(SyncSource &source, const string &suffix, bool dryrun, SyncSourceReport &report)
1233     {
1234         string dir = databaseName(source, suffix);
1235         boost::shared_ptr<ConfigNode> node = ConfigNode::createFileNode(dir + ".ini");
1236         if (!node->exists()) {
1237             SyncContext::throwError(dir + ": no such database backup found");
1238         }
1239         if (source.getOperations().m_restoreData) {
1240             source.getOperations().m_restoreData(SyncSource::Operations::ConstBackupInfo(SyncSource::Operations::BackupInfo::BACKUP_OTHER, dir, node),
1241                                                  dryrun, report);
1242         }
1243     }
1244
1245     SourceList(SyncContext &client, bool doLogging) :
1246         m_logdir(LogDir::create(client)),
1247         m_client(client),
1248         m_doLogging(doLogging),
1249         m_reportTodo(true),
1250         m_logLevel(LOGGING_FULL)
1251     {
1252     }
1253
1254     // call as soon as logdir settings are known
1255     void startSession(const string &logDirPath, int maxlogdirs, int logLevel, SyncReport *report) {
1256         m_logdir->setLogdir(logDirPath);
1257         m_previousLogdir = m_logdir->previousLogdir();
1258         if (m_doLogging) {
1259             m_logdir->startSession(logDirPath, LogDir::SESSION_CREATE, maxlogdirs, logLevel, report);
1260         } else {
1261             // Run debug session without paying attention to
1262             // the normal logdir handling. The log level here
1263             // refers to stdout. The log file will be as complete
1264             // as possible.
1265             m_logdir->startSession(logDirPath, LogDir::SESSION_USE_PATH, 0, 1, report);
1266         }
1267     }
1268
1269     /** read-only access to existing session, identified in logDirPath */
1270     void accessSession(const string &logDirPath) {
1271         m_logdir->setLogdir(logDirPath);
1272         m_previousLogdir = m_logdir->previousLogdir();
1273         m_logdir->startSession(logDirPath, LogDir::SESSION_READ_ONLY, 0, 0, NULL);
1274     }
1275
1276
1277     /** return log directory, empty if not enabled */
1278     const string &getLogdir() {
1279         return m_logdir->getLogdir();
1280     }
1281
1282     /** return previous log dir found in startSession() */
1283     const string &getPrevLogdir() const { return m_previousLogdir; }
1284
1285     /** set directory for database files without actually redirecting the logging */
1286     void setPath(const string &path) { m_logdir->setPath(path); }
1287
1288     /**
1289      * If possible (directory to compare against available) and enabled,
1290      * then dump changes applied locally.
1291      *
1292      * @param oldSession     directory to compare against; "" searches in sessions of current peer
1293      *                       as selected by context for the lastest one involving each source
1294      * @param oldSuffix      suffix of old database dump: usually "after"
1295      * @param currentSuffix  the current database dump suffix: "current"
1296      *                       when not doing a sync, otherwise "before"
1297      * @param excludeSource  when not empty, only dump that source
1298      */
1299     bool dumpLocalChanges(const string &oldSession,
1300                           const string &oldSuffix, const string &newSuffix,
1301                           const string &excludeSource,
1302                           const string &intro = "Local data changes to be applied remotely during synchronization:\n",
1303                           const string &config = "CLIENT_TEST_LEFT_NAME='after last sync' CLIENT_TEST_RIGHT_NAME='current data' CLIENT_TEST_REMOVED='removed since last sync' CLIENT_TEST_ADDED='added since last sync'") {
1304         if (m_logLevel <= LOGGING_SUMMARY) {
1305             return false;
1306         }
1307
1308         vector<string> dirs;
1309         if (oldSession.empty()) {
1310             m_logdir->previousLogdirs(dirs);
1311         }
1312
1313         BOOST_FOREACH(SyncSource *source, *this) {
1314             if ((!excludeSource.empty() && excludeSource != source->getName()) ||
1315                 (newSuffix == "after" && m_prepared.find(source->getName()) == m_prepared.end())) {
1316                 continue;
1317             }
1318
1319             // dump only if not done before or changed
1320             if (m_intro != intro) {
1321                 SE_LOG_SHOW(NULL, "%s", intro.c_str());
1322                 m_intro = intro;
1323             }
1324
1325             string oldDir;
1326             if (oldSession.empty()) {
1327                 // Now look for the latest session involving the current source,
1328                 // starting with the most recent one.
1329                 for (vector<string>::const_reverse_iterator it = dirs.rbegin();
1330                      it != dirs.rend();
1331                      ++it) {
1332                     const string &sessiondir = *it;
1333                     boost::shared_ptr<LogDir> oldsession(LogDir::create(m_client));
1334                     oldsession->openLogdir(sessiondir);
1335                     SyncReport report;
1336                     oldsession->readReport(report);
1337                     if (report.find(source->getName()) != report.end())  {
1338                         // source was active in that session, use dump
1339                         // made there
1340                         oldDir = databaseName(*source, oldSuffix, sessiondir);
1341                         break;
1342                     }
1343                 }
1344             } else {
1345                 oldDir = databaseName(*source, oldSuffix, oldSession);
1346             }
1347             string newDir = databaseName(*source, newSuffix);
1348             SE_LOG_SHOW(NULL, "*** %s ***", source->getDisplayName().c_str());
1349             string cmd = string("env CLIENT_TEST_COMPARISON_FAILED=10 " + config + " synccompare '" ) +
1350                 oldDir + "' '" + newDir + "'";
1351             int ret = Execute(cmd, EXECUTE_NO_STDERR);
1352             switch (ret == -1 ? ret :
1353                     WIFEXITED(ret) ? WEXITSTATUS(ret) :
1354                     -1) {
1355             case 0:
1356                 SE_LOG_SHOW(NULL, "no changes");
1357                 break;
1358             case 10:
1359                 break;
1360             default:
1361                 SE_LOG_SHOW(NULL, "Comparison was impossible.");
1362                 break;
1363             }
1364         }
1365         SE_LOG_SHOW(NULL, "\n");
1366         return true;
1367     }
1368
1369     // call when all sync sources are ready to dump
1370     // pre-sync databases
1371     // @param sourceName   limit preparation to that source
1372     void syncPrepare(const string &sourceName) {
1373         if (m_prepared.find(sourceName) != m_prepared.end()) {
1374             // data dump was already done (can happen when running multiple
1375             // SyncML sessions)
1376             return;
1377         }
1378
1379         if (m_logdir->getLogfile().size() &&
1380             m_doLogging &&
1381             (m_client.getDumpData() || m_client.getPrintChanges())) {
1382             // dump initial databases
1383             SE_LOG_INFO(NULL, "creating complete data backup of source %s before sync (%s)",
1384                         sourceName.c_str(),
1385                         (m_client.getDumpData() && m_client.getPrintChanges()) ? "enabled with dumpData and needed for printChanges" :
1386                         m_client.getDumpData() ? "because it was enabled with dumpData" :
1387                         m_client.getPrintChanges() ? "needed for printChanges" :
1388                         "???");
1389             dumpDatabases("before", &SyncSourceReport::m_backupBefore, sourceName);
1390             if (m_client.getPrintChanges()) {
1391                 // compare against the old "after" database dump
1392                 dumpLocalChanges("", "after", "before", sourceName,
1393                                  StringPrintf("%s data changes to be applied during synchronization:\n",
1394                                               m_client.isLocalSync() ? m_client.getContextName().c_str() : "Local"));
1395             }
1396         }
1397     }
1398
1399     // call at the end of a sync with success == true
1400     // if all went well to print report
1401     void syncDone(SyncMLStatus status, SyncReport *report) {
1402         // record status - failures from now only affect post-processing
1403         // and thus do no longer change that result
1404         if (report) {
1405             report->setStatus(status == 0 ? STATUS_HTTP_OK : status);
1406         }
1407
1408         // dump database after sync if explicitly enabled or
1409         // needed for comparison;
1410         // in the latter case only if dumping it at the beginning completed
1411         if (m_doLogging &&
1412             (m_client.getDumpData() ||
1413              (m_client.getPrintChanges() && m_reportTodo && !m_prepared.empty()))) {
1414             try {
1415                 SE_LOG_INFO(NULL, "creating complete data backup after sync (%s)",
1416                             (m_client.getDumpData() && m_client.getPrintChanges()) ? "enabled with dumpData and needed for printChanges" :
1417                             m_client.getDumpData() ? "because it was enabled with dumpData" :
1418                             m_client.getPrintChanges() ? "needed for printChanges" :
1419                             "???");
1420                 dumpDatabases("after", &SyncSourceReport::m_backupAfter);
1421             } catch (...) {
1422                 Exception::handle();
1423                 // not exactly sure what the problem was, but don't
1424                 // try it again
1425                 m_prepared.clear();
1426             }
1427         }
1428
1429         if (m_doLogging) {
1430             if (m_reportTodo && !m_prepared.empty() && report) {
1431                 // update report with more recent information about m_backupAfter
1432                 updateSyncReport(*report);
1433             }
1434
1435             // ensure that stderr is seen again
1436             m_logdir->restore();
1437
1438             // write out session status
1439             m_logdir->endSession();
1440
1441             if (m_reportTodo) {
1442                 // haven't looked at result of sync yet;
1443                 // don't do it again
1444                 m_reportTodo = false;
1445
1446                 string logfile = m_logdir->getLogfile();
1447                 if (status == STATUS_OK) {
1448                     SE_LOG_SHOW(NULL, "\nSynchronization successful.");
1449                 } else if (logfile.size()) {
1450                     SE_LOG_SHOW(NULL, "\nSynchronization failed, see %s for details.",
1451                                 logfile.c_str());
1452                 } else {
1453                     SE_LOG_SHOW(NULL, "\nSynchronization failed.");
1454                 }
1455
1456                 // pretty-print report
1457                 if (m_logLevel > LOGGING_QUIET) {
1458                     std::string procname = Logger::getProcessName();
1459                     SE_LOG_SHOW(NULL, "\nChanges applied during synchronization%s%s%s:",
1460                                 procname.empty() ? "" : " (",
1461                                 procname.c_str(),
1462                                 procname.empty() ? "" : ")");
1463                 }
1464                 if (m_logLevel > LOGGING_QUIET && report) {
1465                     ostringstream out;
1466                     out << *report;
1467                     std::string slowSync = report->slowSyncExplanation(m_client.getPeer());
1468                     if (!slowSync.empty()) {
1469                         out << endl << slowSync;
1470                     }
1471                     SE_LOG_SHOW(NULL, "%s", out.str().c_str());
1472                 }
1473
1474                 // compare databases?
1475                 if (m_client.getPrintChanges()) {
1476                     dumpLocalChanges(m_logdir->getLogdir(),
1477                                      "before", "after", "",
1478                                      StringPrintf("\nData modified %s during synchronization:\n",
1479                                                   m_client.isLocalSync() ? m_client.getContextName().c_str() : "locally"),
1480                                      "CLIENT_TEST_LEFT_NAME='before sync' CLIENT_TEST_RIGHT_NAME='after sync' CLIENT_TEST_REMOVED='removed during sync' CLIENT_TEST_ADDED='added during sync'");
1481                 }
1482
1483                 // now remove some old logdirs
1484                 m_logdir->expire();
1485             }
1486         } else {
1487             // finish debug session
1488             m_logdir->restore();
1489             m_logdir->endSession();
1490         }
1491     }
1492
1493     /** copies information about sources into sync report */
1494     void updateSyncReport(SyncReport &report) {
1495         BOOST_FOREACH(SyncSource *source, *this) {
1496             report.addSyncSourceReport(source->getName(), *source);
1497         }
1498     }
1499
1500     /** returns names of active sources */
1501     set<string> getSources() {
1502         set<string> res;
1503
1504         BOOST_FOREACH(SyncSource *source, *this) {
1505             res.insert(source->getName());
1506         }
1507         return res;
1508     }
1509
1510     ~SourceList() {
1511         // free sync sources
1512         BOOST_FOREACH(SyncSource *source, *this) {
1513             delete source;
1514         }
1515     }
1516
1517     /** find sync source by name (both normal and virtual sources) */
1518     SyncSource *operator [] (const string &name) {
1519         BOOST_FOREACH(SyncSource *source, *this) {
1520             if (name == source->getName()) {
1521                 return source;
1522             }
1523         }
1524         BOOST_FOREACH(boost::shared_ptr<VirtualSyncSource> &source, m_virtualSources) {
1525             if (name == source->getName()) {
1526                 return source.get();
1527             }
1528         }
1529         return NULL;
1530     }
1531
1532     /** find by XML <dbtypeid> (the ID used by Synthesis to identify sources in progress events) */
1533     SyncSource *lookupBySynthesisID(int synthesisid) {
1534         BOOST_FOREACH(SyncSource *source, *this) {
1535             if (source->getSynthesisID() == synthesisid) {
1536                 return source;
1537             }
1538         }
1539         BOOST_FOREACH(boost::shared_ptr<VirtualSyncSource> &source, m_virtualSources) {
1540             if (source->getSynthesisID() == synthesisid) {
1541                 return source.get();
1542             }
1543         }
1544         return NULL;
1545     }
1546
1547     std::list<std::string> getSourceNames() const;
1548 };
1549
1550 std::list<std::string> SourceList::getSourceNames() const
1551 {
1552     std::list<std::string> sourceNames;
1553     BOOST_FOREACH (SyncSource *source, *this) {
1554         sourceNames.push_back(source->getName());
1555     }
1556     return sourceNames;
1557 }
1558
1559 void unref(SourceList *sourceList)
1560 {
1561     delete sourceList;
1562 }
1563
1564 UserInterface &SyncContext::getUserInterfaceNonNull()
1565 {
1566     if (m_userInterface) {
1567         return *m_userInterface;
1568     } else {
1569         // Doesn't use keyring.
1570         static SimpleUserInterface dummy("0");
1571         return dummy;
1572     }
1573 }
1574
1575 void SyncContext::requestAnotherSync()
1576 {
1577     if (m_activeContext &&
1578         m_activeContext->m_engine.get() &&
1579         m_activeContext->m_session) {
1580         SharedKey sessionKey =
1581             m_activeContext->m_engine.OpenSessionKey(m_activeContext->m_session);
1582         m_activeContext->m_engine.SetInt32Value(sessionKey,
1583                                                 "restartsync",
1584                                                 true);
1585     }
1586 }
1587
1588 const std::vector<SyncSource *> *SyncContext::getSources() const
1589 {
1590     return m_sourceListPtr ?
1591         m_sourceListPtr->getSourceSet() :
1592         NULL;
1593 }
1594
1595 string SyncContext::getUsedSyncURL() {
1596     vector<string> urls = getSyncURL();
1597     BOOST_FOREACH (string url, urls) {
1598         if (boost::starts_with(url, "http://") ||
1599                 boost::starts_with(url, "https://")) {
1600 #ifdef ENABLE_LIBSOUP
1601             return url;
1602 #elif defined(ENABLE_LIBCURL)
1603             return url;
1604 #endif
1605         } else if (url.find("obex-bt://") ==0) {
1606 #ifdef ENABLE_BLUETOOTH
1607             return url;
1608 #endif
1609         } else if (boost::starts_with(url, "local://")) {
1610             return url;
1611         }
1612     }
1613     return "";
1614 }
1615
1616 static void CancelTransport(TransportAgent *agent, SuspendFlags &flags)
1617 {
1618     if (flags.getState() == SuspendFlags::ABORT) {
1619         SE_LOG_DEBUG(NULL, "CancelTransport: cancelling because of SuspendFlags::ABORT");
1620         agent->cancel();
1621     }
1622 }
1623
1624 /**
1625  * common initialization for all kinds of transports, to be called
1626  * before using them
1627  */
1628 static void InitializeTransport(const boost::shared_ptr<TransportAgent> &agent,
1629                                 int timeout)
1630 {
1631     agent->setTimeout(timeout);
1632
1633     // Automatically call cancel() when we an abort request
1634     // is detected. Relies of automatic connection management
1635     // to disconnect when agent is deconstructed.
1636     SuspendFlags &flags(SuspendFlags::getSuspendFlags());
1637     flags.m_stateChanged.connect(SuspendFlags::StateChanged_t::slot_type(CancelTransport, agent.get(), _1).track(agent));
1638 }
1639
1640 boost::shared_ptr<TransportAgent> SyncContext::createTransportAgent(void *gmainloop)
1641 {
1642     string url = getUsedSyncURL();
1643     m_retryInterval = getRetryInterval();
1644     m_retryDuration = getRetryDuration();
1645     int timeout = m_serverMode ? m_retryDuration : min(m_retryInterval, m_retryDuration);
1646
1647     if (m_localSync) {
1648         string peer = url.substr(strlen("local://"));
1649         boost::shared_ptr<LocalTransportAgent> agent(LocalTransportAgent::create(this, peer, gmainloop));
1650         InitializeTransport(agent, timeout);
1651         agent->start();
1652         return agent;
1653     } else if (boost::starts_with(url, "http://") ||
1654         boost::starts_with(url, "https://")) {
1655 #ifdef ENABLE_LIBSOUP
1656         boost::shared_ptr<SoupTransportAgent> agent(new SoupTransportAgent(static_cast<GMainLoop *>(gmainloop)));
1657         agent->setConfig(*this);
1658         InitializeTransport(agent, timeout);
1659         return agent;
1660 #elif defined(ENABLE_LIBCURL)
1661         boost::shared_ptr<CurlTransportAgent> agent(new CurlTransportAgent());
1662         agent->setConfig(*this);
1663         InitializeTransport(agent, timeout);
1664         return agent;
1665 #endif
1666     } else if (url.find("obex-bt://") ==0) {
1667 #ifdef ENABLE_BLUETOOTH
1668         std::string btUrl = url.substr (strlen ("obex-bt://"), std::string::npos);
1669         boost::shared_ptr<ObexTransportAgent> agent(new ObexTransportAgent(ObexTransportAgent::OBEX_BLUETOOTH,
1670                                                                            static_cast<GMainLoop *>(gmainloop)));
1671         agent->setURL (btUrl);
1672         InitializeTransport(agent, timeout);
1673         // this will block already
1674         agent->connect();
1675         return agent;
1676 #endif
1677     }
1678
1679     SE_THROW("unsupported transport type is specified in the configuration");
1680 }
1681
1682 void SyncContext::displayServerMessage(const string &message)
1683 {
1684     SE_LOG_INFO(NULL, "message from server: %s", message.c_str());
1685 }
1686
1687 void SyncContext::displaySyncProgress(sysync::TProgressEventEnum type,
1688                                               int32_t extra1, int32_t extra2, int32_t extra3)
1689 {
1690
1691 }
1692
1693 bool SyncContext::displaySourceProgress(SyncSource &source,
1694                                         const SyncSourceEvent &event,
1695                                         bool flush)
1696 {
1697     if (!flush) {
1698         // Certain events do not need to be printed immediately.
1699         // For example, instead of multiple PEV_ITEMRECEIVED events
1700         //   foo: received 1/100
1701         //   foo: received 2/100
1702         //   foo: ...
1703         //   foo: received 100/100
1704         // it is better to just print one:
1705         //   foo: received 100/100
1706         switch (event.m_type) {
1707         case sysync::PEV_ITEMPROCESSED:
1708             // Ignore this one completely. There is one such event
1709             // after each PEV_ITEMRECEIVED, so processing
1710             // PEV_ITEMPROCESSED would break the merging of
1711             // PEV_ITEMRECEIVED, at least the way it is implemented
1712             // now. PEV_ITEMPROCESSED also doesn't add much
1713             // information.
1714             return true;
1715         case sysync::PEV_DELETING:
1716         case sysync::PEV_ITEMRECEIVED:
1717         case sysync::PEV_ITEMSENT:
1718             // Flush when switching to a different event type or source.
1719             if (m_sourceEvent.m_type != sysync::PEV_NOP &&
1720                 (m_sourceEvent.m_type != event.m_type ||
1721                  m_sourceProgress != &source)) {
1722                 displaySourceProgress(*m_sourceProgress, m_sourceEvent, true);
1723             }
1724             m_sourceEvent.m_type = event.m_type;
1725             m_sourceEvent.m_extra1 = event.m_extra1;
1726             m_sourceEvent.m_extra2 = event.m_extra2;
1727             m_sourceEvent.m_extra3 = event.m_extra3;
1728             m_sourceProgress = &source;
1729             return true;
1730             break;
1731         default:
1732             if (m_sourceEvent.m_type != sysync::PEV_NOP) {
1733                 displaySourceProgress(*m_sourceProgress, m_sourceEvent, true);
1734                 m_sourceEvent.m_type = sysync::PEV_NOP;
1735             }
1736             break;
1737         }
1738     }
1739
1740     switch(event.m_type) {
1741     case sysync::PEV_PREPARING:
1742         /* preparing (e.g. preflight in some clients), extra1=progress, extra2=total */
1743         /* extra2 might be zero */
1744         /*
1745          * At the moment, preparing items doesn't do any real work.
1746          * Printing this progress just increases the output and slows
1747          * us down. Disabled.
1748          */
1749         if (true || source.getFinalSyncMode() == SYNC_NONE) {
1750             // not active, suppress output
1751         } else if (event.m_extra2) {
1752             SE_LOG_INFO(NULL, "%s: preparing %d/%d",
1753                         source.getDisplayName().c_str(), event.m_extra1, event.m_extra2);
1754         } else {
1755             SE_LOG_INFO(NULL, "%s: preparing %d",
1756                         source.getDisplayName().c_str(), event.m_extra1);
1757         }
1758         break;
1759     case sysync::PEV_DELETING:
1760         /* deleting (zapping datastore), extra1=progress, extra2=total */
1761         if (event.m_extra2) {
1762             SE_LOG_INFO(NULL, "%s: deleting %d/%d",
1763                         source.getDisplayName().c_str(), event.m_extra1, event.m_extra2);
1764         } else {
1765             SE_LOG_INFO(NULL, "%s: deleting %d",
1766                         source.getDisplayName().c_str(), event.m_extra1);
1767         }
1768         break;
1769     case sysync::PEV_ALERTED: {
1770         /* datastore alerted (extra1=0 for normal, 1 for slow, 2 for first time slow,
1771            extra2=1 for resumed session,
1772            extra3 0=twoway, 1=fromserver, 2=fromclient */
1773         // -1 is used for alerting a restore from backup. Synthesis won't use this
1774         bool peerIsClient = getPeerIsClient();
1775         if (event.m_extra1 != -1) {
1776             SE_LOG_INFO(NULL, "%s: %s %s sync%s (%s)",
1777                         source.getDisplayName().c_str(),
1778                         event.m_extra2 ? "resuming" : "starting",
1779                         event.m_extra1 == 0 ? "normal" :
1780                         event.m_extra1 == 1 ? "slow" :
1781                         event.m_extra1 == 2 ? "first time" :
1782                         "unknown",
1783                         event.m_extra3 == 0 ? ", two-way" :
1784                         event.m_extra3 == 1 ? " from server" :
1785                         event.m_extra3 == 2 ? " from client" :
1786                         ", unknown direction",
1787                         peerIsClient ? "peer is client" : "peer is server");
1788
1789             SimpleSyncMode mode = SIMPLE_SYNC_NONE;
1790             SyncMode sync = StringToSyncMode(source.getSync());
1791             switch (event.m_extra1) {
1792             case 0:
1793                 switch (event.m_extra3) {
1794                 case 0:
1795                     mode = SIMPLE_SYNC_TWO_WAY;
1796                     if (m_serverMode &&
1797                         m_serverAlerted) {
1798                         if (sync == SYNC_ONE_WAY_FROM_SERVER ||
1799                             sync == SYNC_ONE_WAY_FROM_LOCAL) {
1800                             // As in the slow/refresh-from-server case below,
1801                             // pretending to do a two-way incremental sync
1802                             // is a correct way of executing the requested
1803                             // one-way sync, as long as the client doesn't
1804                             // send any of its own changes. The Synthesis
1805                             // engine does that.
1806                             mode = SIMPLE_SYNC_ONE_WAY_FROM_LOCAL;
1807                         } else if (sync == SYNC_LOCAL_CACHE_SLOW ||
1808                                    sync == SYNC_LOCAL_CACHE_INCREMENTAL) {
1809                             mode = SIMPLE_SYNC_LOCAL_CACHE_INCREMENTAL;
1810                         }
1811                     }
1812                     break;
1813                 case 1:
1814                     mode = peerIsClient ? SIMPLE_SYNC_ONE_WAY_FROM_LOCAL : SIMPLE_SYNC_ONE_WAY_FROM_REMOTE;
1815                     break;
1816                 case 2:
1817                     mode = peerIsClient ? SIMPLE_SYNC_ONE_WAY_FROM_REMOTE : SIMPLE_SYNC_ONE_WAY_FROM_LOCAL;
1818                     break;
1819                 }
1820                 break;
1821             case 1:
1822             case 2:
1823                 switch (event.m_extra3) {
1824                 case 0:
1825                     mode = SIMPLE_SYNC_SLOW;
1826                     if (m_serverMode &&
1827                         m_serverAlerted) {
1828                         if (sync == SYNC_REFRESH_FROM_SERVER ||
1829                             sync == SYNC_REFRESH_FROM_LOCAL) {
1830                             // We run as server and told the client to refresh
1831                             // its data. A slow sync is how some clients (the
1832                             // Synthesis engine included) execute that sync mode;
1833                             // let's be optimistic and assume that the client
1834                             // did as it was told and deleted its data.
1835                             mode = SIMPLE_SYNC_REFRESH_FROM_LOCAL;
1836                         } else if (sync == SYNC_LOCAL_CACHE_SLOW ||
1837                                    sync == SYNC_LOCAL_CACHE_INCREMENTAL) {
1838                             mode = SIMPLE_SYNC_LOCAL_CACHE_SLOW;
1839                         }
1840                     }
1841                     break;
1842                 case 1:
1843                     mode = peerIsClient ? SIMPLE_SYNC_REFRESH_FROM_LOCAL : SIMPLE_SYNC_REFRESH_FROM_REMOTE;
1844                     break;
1845                 case 2:
1846                     mode = peerIsClient ? SIMPLE_SYNC_REFRESH_FROM_REMOTE : SIMPLE_SYNC_REFRESH_FROM_LOCAL;
1847                     break;
1848                 }
1849                 break;
1850             }
1851
1852             if (SyncMode(mode) != SYNC_NONE) {
1853                 SE_LOG_DEBUG(NULL, "reading: set read-ahead based on sync mode %s",
1854                              PrettyPrintSyncMode(SyncMode(mode)).c_str());
1855                 switch (mode) {
1856                 case SIMPLE_SYNC_NONE:
1857                 case SIMPLE_SYNC_INVALID:
1858                 case SIMPLE_SYNC_RESTORE_FROM_BACKUP:
1859                 case SIMPLE_SYNC_ONE_WAY_FROM_REMOTE:
1860                 case SIMPLE_SYNC_REFRESH_FROM_REMOTE:
1861                 case SIMPLE_SYNC_LOCAL_CACHE_INCREMENTAL:
1862                     source.setReadAheadOrder(SyncSourceBase::READ_NONE);
1863                     break;
1864                 case SIMPLE_SYNC_TWO_WAY:
1865                 case SIMPLE_SYNC_ONE_WAY_FROM_LOCAL:
1866                     source.setReadAheadOrder(SyncSourceBase::READ_CHANGED_ITEMS);
1867                     break;
1868                 case SIMPLE_SYNC_SLOW:
1869                 case SIMPLE_SYNC_REFRESH_FROM_LOCAL:
1870                 case SIMPLE_SYNC_LOCAL_CACHE_SLOW:
1871                     source.setReadAheadOrder(SyncSourceBase::READ_ALL_ITEMS);
1872                     break;
1873                 }
1874             }
1875             if (source.getFinalSyncMode() == SYNC_NONE) {
1876                 source.recordFinalSyncMode(SyncMode(mode));
1877                 source.recordFirstSync(event.m_extra1 == 2);
1878                 source.recordResumeSync(event.m_extra2 == 1);
1879             } else if (SyncMode(mode) != SYNC_NONE) {
1880                 // Broadcast statistics before moving into next cycle.
1881                 m_sourceSyncedSignal(source.getName(), source);
1882                 // may happen when the source is used in multiple
1883                 // SyncML sessions; only remember the initial sync
1884                 // mode in that case and count all following syncs
1885                 // (they should only finish the work of the initial
1886                 // one)
1887                 source.recordRestart();
1888                 if (m_serverMode) {
1889                     // Done with first cycle, revert to normal photo
1890                     // handling if it was disabled.
1891                     SharedKey sessionKey = m_engine.OpenSessionKey(m_session);
1892                     SharedKey contextKey = m_engine.OpenKeyByPath(sessionKey, "/sessionvars");
1893                     m_engine.SetInt32Value(contextKey, "keepPhotoData", false);
1894                 }
1895             }
1896         } else {
1897             SE_LOG_INFO(NULL, "%s: restore from backup", source.getDisplayName().c_str());
1898             source.recordFinalSyncMode(SYNC_RESTORE_FROM_BACKUP);
1899         }
1900         break;
1901     }
1902     case sysync::PEV_SYNCSTART:
1903         /* sync started */
1904         SE_LOG_INFO(NULL, "%s: started",
1905                     source.getDisplayName().c_str());
1906         break;
1907     case sysync::PEV_ITEMRECEIVED:
1908         /* item received, extra1=current item count,
1909            extra2=number of expected changes (if >= 0) */
1910         if (source.getFinalSyncMode() == SYNC_NONE) {
1911         } else if (event.m_extra2 > 0) {
1912             SE_LOG_INFO(NULL, "%s: received %d/%d",
1913                         source.getDisplayName().c_str(), event.m_extra1, event.m_extra2);
1914         } else {
1915             SE_LOG_INFO(NULL, "%s: received %d",
1916                         source.getDisplayName().c_str(), event.m_extra1);
1917         }
1918         source.recordTotalNumItemsReceived(event.m_extra1);
1919         break;
1920     case sysync::PEV_ITEMSENT:
1921         /* item sent,     extra1=current item count,
1922            extra2=number of expected items to be sent (if >=0) */
1923         if (source.getFinalSyncMode() == SYNC_NONE) {
1924         } else if (event.m_extra2 > 0) {
1925             SE_LOG_INFO(NULL, "%s: sent %d/%d",
1926                         source.getDisplayName().c_str(), event.m_extra1, event.m_extra2);
1927         } else {
1928             SE_LOG_INFO(NULL, "%s: sent %d",
1929                         source.getDisplayName().c_str(), event.m_extra1);
1930         }
1931         break;
1932     // Not reached, see above.
1933     case sysync::PEV_ITEMPROCESSED:
1934         /* item locally processed,               extra1=# added,
1935            extra2=# updated,
1936            extra3=# deleted */
1937         if (source.getFinalSyncMode() == SYNC_NONE) {
1938         } else if (source.getFinalSyncMode() != SYNC_NONE) {
1939             SE_LOG_INFO(NULL, "%s: added %d, updated %d, removed %d",
1940                         source.getDisplayName().c_str(), event.m_extra1, event.m_extra2, event.m_extra3);
1941         }
1942         break;
1943     case sysync::PEV_SYNCEND: {
1944         /* sync finished, probably with error in extra1 (0=ok),
1945            syncmode in extra2 (0=normal, 1=slow, 2=first time),
1946            extra3=1 for resumed session) */
1947         if (source.getFinalSyncMode() == SYNC_NONE) {
1948             SE_LOG_INFO(NULL, "%s: inactive", source.getDisplayName().c_str());
1949         } else if(source.getFinalSyncMode() == SYNC_RESTORE_FROM_BACKUP) {
1950             SE_LOG_INFO(NULL, "%s: restore done %s",
1951                         source.getDisplayName().c_str(),
1952                         event.m_extra1 ? "unsuccessfully" : "successfully" );
1953         } else {
1954             SE_LOG_INFO(NULL, "%s: %s%s sync done %s",
1955                         source.getDisplayName().c_str(),
1956                         event.m_extra3 ? "resumed " : "",
1957                         event.m_extra2 == 0 ? "normal" :
1958                         event.m_extra2 == 1 ? "slow" :
1959                         event.m_extra2 == 2 ? "first time" :
1960                         "unknown",
1961                         event.m_extra1 ? "unsuccessfully" : "successfully");
1962         }
1963         int32_t extra1 = event.m_extra1;
1964         switch (extra1) {
1965         case 401:
1966             // TODO: reset cached password
1967             SE_LOG_INFO(NULL, "authorization failed, check username '%s' and password", getSyncUser().toString().c_str());
1968             break;
1969         case 403:
1970             SE_LOG_INFO(source.getDisplayName(), "log in succeeded, but server refuses access - contact server operator");
1971             break;
1972         case 407:
1973             SE_LOG_INFO(NULL, "proxy authorization failed, check proxy username and password");
1974             break;
1975         case 404:
1976             SE_LOG_INFO(source.getDisplayName(), "server database not found, check URI '%s'", source.getURINonEmpty().c_str());
1977             break;
1978         case 0:
1979             break;
1980         case sysync::LOCERR_DATASTORE_ABORT:
1981             // this can mean only one thing in SyncEvolution: unexpected slow sync
1982             extra1 = STATUS_UNEXPECTED_SLOW_SYNC;
1983             // no break!
1984         default:
1985             // Printing unknown status codes here is of somewhat questionable value,
1986             // because even "good" sources will get a bad status when the overall
1987             // session turns bad. We also don't have good explanations for the
1988             // status here.
1989             SE_LOG_ERROR(source.getDisplayName(), "%s", Status2String(SyncMLStatus(event.m_extra1)).c_str());
1990             break;
1991         }
1992         source.recordStatus(SyncMLStatus(extra1));
1993         break;
1994     }
1995     case sysync::PEV_DSSTATS_L:
1996         /* datastore statistics for local       (extra1=# added,
1997            extra2=# updated,
1998            extra3=# deleted) */
1999         source.setItemStat(SyncSource::ITEM_LOCAL,
2000                            SyncSource::ITEM_ADDED,
2001                            SyncSource::ITEM_TOTAL,
2002                            event.m_extra1);
2003         source.setItemStat(SyncSource::ITEM_LOCAL,
2004                            SyncSource::ITEM_UPDATED,
2005                            SyncSource::ITEM_TOTAL,
2006                            event.m_extra2);
2007         source.setItemStat(SyncSource::ITEM_LOCAL,
2008                            SyncSource::ITEM_REMOVED,
2009                            SyncSource::ITEM_TOTAL,
2010                            // Synthesis engine doesn't count locally
2011                            // deleted items during
2012                            // refresh-from-server/client. That's a matter of
2013                            // taste. In SyncEvolution we'd like these
2014                            // items to show up, so add it here.
2015                            (source.getFinalSyncMode() == (m_serverMode ? SYNC_REFRESH_FROM_CLIENT : SYNC_REFRESH_FROM_SERVER) ||
2016                             source.getFinalSyncMode() == SYNC_REFRESH_FROM_REMOTE) ?
2017                            source.getNumDeleted() :
2018                            event.m_extra3);
2019         break;
2020     case sysync::PEV_DSSTATS_R:
2021         /* datastore statistics for remote      (extra1=# added,
2022            extra2=# updated,
2023            extra3=# deleted) */
2024         source.setItemStat(SyncSource::ITEM_REMOTE,
2025                            SyncSource::ITEM_ADDED,
2026                            SyncSource::ITEM_TOTAL,
2027                            event.m_extra1);
2028         source.setItemStat(SyncSource::ITEM_REMOTE,
2029                            SyncSource::ITEM_UPDATED,
2030                            SyncSource::ITEM_TOTAL,
2031                            event.m_extra2);
2032         source.setItemStat(SyncSource::ITEM_REMOTE,
2033                            SyncSource::ITEM_REMOVED,
2034                            SyncSource::ITEM_TOTAL,
2035                            event.m_extra3);
2036         break;
2037     case sysync::PEV_DSSTATS_E:
2038         /* datastore statistics for local/remote rejects (extra1=# locally rejected,
2039            extra2=# remotely rejected) */
2040         source.setItemStat(SyncSource::ITEM_LOCAL,
2041                            SyncSource::ITEM_ANY,
2042                            SyncSource::ITEM_REJECT,
2043                            event.m_extra1);
2044         source.setItemStat(SyncSource::ITEM_REMOTE,
2045                            SyncSource::ITEM_ANY,
2046                            SyncSource::ITEM_REJECT,
2047                            event.m_extra2);
2048         break;
2049     case sysync::PEV_DSSTATS_S:
2050         /* datastore statistics for server slowsync  (extra1=# slowsync matches) */
2051         source.setItemStat(SyncSource::ITEM_REMOTE,
2052                            SyncSource::ITEM_ANY,
2053                            SyncSource::ITEM_MATCH,
2054                            event.m_extra1);
2055         break;
2056     case sysync::PEV_DSSTATS_C:
2057         /* datastore statistics for server conflicts (extra1=# server won,
2058            extra2=# client won,
2059            extra3=# duplicated) */
2060         source.setItemStat(SyncSource::ITEM_REMOTE,
2061                            SyncSource::ITEM_ANY,
2062                            SyncSource::ITEM_CONFLICT_SERVER_WON,
2063                            event.m_extra1);
2064         source.setItemStat(SyncSource::ITEM_REMOTE,
2065                            SyncSource::ITEM_ANY,
2066                            SyncSource::ITEM_CONFLICT_CLIENT_WON,
2067                            event.m_extra2);
2068         source.setItemStat(SyncSource::ITEM_REMOTE,
2069                            SyncSource::ITEM_ANY,
2070                            SyncSource::ITEM_CONFLICT_DUPLICATED,
2071                            event.m_extra3);
2072         break;
2073     case sysync::PEV_DSSTATS_D:
2074         /* datastore statistics for data   volume    (extra1=outgoing bytes,
2075            extra2=incoming bytes) */
2076         source.setItemStat(SyncSource::ITEM_LOCAL,
2077                            SyncSource::ITEM_ANY,
2078                            SyncSource::ITEM_SENT_BYTES,
2079                            event.m_extra1);
2080         source.setItemStat(SyncSource::ITEM_LOCAL,
2081                            SyncSource::ITEM_ANY,
2082                            SyncSource::ITEM_RECEIVED_BYTES,
2083                            event.m_extra2);
2084         break;
2085     case sysync::PEV_NOP:
2086         // Handled, do not process further.
2087         return true;
2088         break;
2089     default:
2090         SE_LOG_DEBUG(NULL, "%s: progress event %d, extra %d/%d/%d",
2091                      source.getDisplayName().c_str(),
2092                      event.m_type, event.m_extra1, event.m_extra2, event.m_extra3);
2093     }
2094     return false;
2095 }
2096
2097 void SyncContext::throwError(const string &error)
2098 {
2099     throwError(SyncMLStatus(STATUS_FATAL + sysync::LOCAL_STATUS_CODE), error);
2100 }
2101
2102 void SyncContext::throwError(SyncMLStatus status, const string &error)
2103 {
2104 #ifdef IPHONE
2105     /*
2106      * Catching the runtime_exception fails due to a toolchain problem,
2107      * so do the error handling now and abort: because there is just
2108      * one sync source this is probably the only thing that can be done.
2109      * Still, it's not nice on the server...
2110      */
2111     fatalError(NULL, error.c_str());
2112 #else
2113     SE_THROW_EXCEPTION_STATUS(StatusException, error, status);
2114 #endif
2115 }
2116
2117 void SyncContext::throwError(const string &action, int error)
2118 {
2119     std::string what = action + ": " + strerror(error);
2120     // be as specific if we can be: relevant for the file backend,
2121     // which is expected to return STATUS_NOT_FOUND == 404 for "file
2122     // not found"
2123     if (error == ENOENT) {
2124         throwError(STATUS_NOT_FOUND, what);
2125     } else {
2126         throwError(what);
2127     }
2128 }
2129
2130 void SyncContext::fatalError(void *object, const char *error)
2131 {
2132     SE_LOG_ERROR(NULL, "%s", error);
2133     if (m_activeContext && m_activeContext->m_sourceListPtr) {
2134         m_activeContext->m_sourceListPtr->syncDone(STATUS_FATAL, NULL);
2135     }
2136     exit(1);
2137 }
2138
2139 /*
2140  * There have been segfaults inside glib in the background
2141  * thread which ran the second event loop. Disabled it again,
2142  * even though the synchronous EDS API calls will block then
2143  * when EDS dies.
2144  */
2145 #if 0 && defined(HAVE_GLIB) && defined(HAVE_EDS)
2146 # define RUN_GLIB_LOOP
2147 #endif
2148
2149 #ifdef RUN_GLIB_LOOP
2150 static void *mainLoopThread(void *)
2151 {
2152     // The test framework uses SIGALRM for timeouts.
2153     // Block the signal here because a) the signal handler
2154     // prints a stack back trace when called and we are not
2155     // interessted in the background thread's stack and b)
2156     // it seems to have confused glib/libebook enough to
2157     // access invalid memory and segfault when it gets the SIGALRM.
2158     sigset_t blocked;
2159     sigemptyset(&blocked);
2160     sigaddset(&blocked, SIGALRM);
2161     pthread_sigmask(SIG_BLOCK, &blocked, NULL);
2162
2163     GMainLoop *mainloop = g_main_loop_new(NULL, TRUE);
2164     if (mainloop) {
2165         g_main_loop_run(mainloop);
2166         g_main_loop_unref(mainloop);
2167     }
2168     return NULL;
2169 }
2170 #endif
2171
2172 void SyncContext::startLoopThread()
2173 {
2174 #ifdef RUN_GLIB_LOOP
2175     // when using Evolution we must have a running main loop,
2176     // otherwise loss of connection won't be reported to us
2177     static pthread_t loopthread;
2178     static bool loopthreadrunning;
2179     if (!loopthreadrunning) {
2180         loopthreadrunning = !pthread_create(&loopthread, NULL, mainLoopThread, NULL);
2181     }
2182 #endif
2183 }
2184
2185 SyncSource *SyncContext::findSource(const std::string &name)
2186 {
2187     if (!m_activeContext || !m_activeContext->m_sourceListPtr) {
2188         return NULL;
2189     }
2190     const char *realname = strrchr(name.c_str(), m_findSourceSeparator);
2191     if (realname) {
2192         realname++;
2193     } else {
2194         realname = name.c_str();
2195     }
2196     return (*m_activeContext->m_sourceListPtr)[realname];
2197 }
2198
2199 SyncContext *SyncContext::findContext(const char *sessionName)
2200 {
2201     return m_activeContext;
2202 }
2203
2204 void SyncContext::initSources(SourceList &sourceList)
2205 {
2206     list<string> configuredSources = getSyncSources();
2207     map<string, string> subSources;
2208
2209     // Disambiguate source names because we have multiple with the same
2210     // name active?
2211     string contextName;
2212     if (m_localSync) {
2213         contextName = getContextName();
2214     }
2215
2216     // Phase 1, check all virtual sync soruces
2217     BOOST_FOREACH(const string &name, configuredSources) {
2218         boost::shared_ptr<PersistentSyncSourceConfig> sc(getSyncSourceConfig(name));
2219         SyncSourceNodes source = getSyncSourceNodes (name);
2220         std::string sync = sc->getSync();
2221         SyncMode mode = StringToSyncMode(sync);
2222         if (mode != SYNC_NONE) {
2223             SourceType sourceType = SyncSource::getSourceType(source);
2224             if (sourceType.m_backend == "virtual") {
2225                 //This is a virtual sync source, check and enable the referenced
2226                 //sub syncsources here
2227                 SyncSourceParams params(name, source, boost::shared_ptr<SyncConfig>(this, SyncConfigNOP()), contextName);
2228                 boost::shared_ptr<VirtualSyncSource> vSource = boost::shared_ptr<VirtualSyncSource> (new VirtualSyncSource (params));
2229                 std::vector<std::string> mappedSources = vSource->getMappedSources();
2230                 BOOST_FOREACH (std::string source, mappedSources) {
2231                     //check whether the mapped source is really available
2232                     boost::shared_ptr<PersistentSyncSourceConfig> source_config
2233                         = getSyncSourceConfig(source);
2234                     if (!source_config || !source_config->exists()) {
2235                         throwError(StringPrintf("Virtual data source \"%s\" references a nonexistent datasource \"%s\".", name.c_str(), source.c_str()));
2236                     }
2237                     pair< map<string, string>::iterator, bool > res = subSources.insert(make_pair(source, name));
2238                     if (!res.second) {
2239                         throwError(StringPrintf("Data source \"%s\" included in the virtual sources \"%s\" and \"%s\". It can only be included in one virtual source at a time.",
2240                                                 source.c_str(), res.first->second.c_str(), name.c_str()));
2241                     }
2242
2243                 }
2244                 FilterConfigNode::ConfigFilter vFilter;
2245                 vFilter["sync"] = sync;
2246                 if (!m_serverMode) {
2247                     // must set special URI for clients so that
2248                     // engine knows about superdatastore and its
2249                     // URI
2250                     vFilter["uri"] = string("<") + vSource->getName() + ">" + vSource->getURINonEmpty();
2251                 }
2252                 BOOST_FOREACH (std::string source, mappedSources) {
2253                     setConfigFilter (false, source, vFilter);
2254                 }
2255                 sourceList.addSource(vSource);
2256             }
2257         }
2258     }
2259
2260     BOOST_FOREACH(const string &name, configuredSources) {
2261         boost::shared_ptr<PersistentSyncSourceConfig> sc(getSyncSourceConfig(name));
2262
2263         SyncSourceNodes source = getSyncSourceNodes (name);
2264         if (!sc->isDisabled()) {
2265             SourceType sourceType = SyncSource::getSourceType(source);
2266             if (sourceType.m_backend != "virtual") {
2267                 SyncSourceParams params(name,
2268                                         source,
2269                                         boost::shared_ptr<SyncConfig>(this, SyncConfigNOP()),
2270                                         contextName);
2271                 cxxptr<SyncSource> syncSource(SyncSource::createSource(params));
2272                 if (!syncSource) {
2273                     throwError(name + ": type unknown" );
2274                 }
2275                 if (subSources.find(name) != subSources.end()) {
2276                     syncSource->recordVirtualSource(subSources[name]);
2277                 }
2278                 sourceList.addSource(syncSource);
2279             }
2280         } else {
2281             // the Synthesis engine is never going to see this source,
2282             // therefore we have to mark it as 100% complete and
2283             // "done"
2284             class DummySyncSource source(name, contextName);
2285             source.recordFinalSyncMode(SYNC_NONE);
2286             displaySourceProgress(source,
2287                                   SyncSourceEvent(sysync::PEV_PREPARING, 0, 0, 0),
2288                                   true);
2289             displaySourceProgress(source,
2290                                   SyncSourceEvent(sysync::PEV_ITEMPROCESSED, 0, 0, 0),
2291                                   true);
2292             displaySourceProgress(source,
2293                                   SyncSourceEvent(sysync::PEV_ITEMRECEIVED, 0, 0, 0),
2294                                   true);
2295             displaySourceProgress(source,
2296                                   SyncSourceEvent(sysync::PEV_ITEMSENT, 0, 0, 0),
2297                                   true);
2298             displaySourceProgress(source,
2299                                   SyncSourceEvent(sysync::PEV_SYNCEND, 0, 0, 0),
2300                                   true);
2301         }
2302     }
2303 }
2304
2305 void SyncContext::startSourceAccess(SyncSource *source)
2306 {
2307     if(m_firstSourceAccess) {
2308         syncSuccessStart();
2309         m_firstSourceAccess = false;
2310     }
2311     if (m_serverMode) {
2312         // When using the source as cache, change tracking
2313         // is not required. Disabling it can make item
2314         // changes faster.
2315         SyncMode mode = StringToSyncMode(source->getSync());
2316         if (mode == SYNC_LOCAL_CACHE_SLOW ||
2317             mode == SYNC_LOCAL_CACHE_INCREMENTAL) {
2318             source->setNeedChanges(false);
2319         }
2320         // source is active in sync, now open it
2321         source->open();
2322     }
2323     // database dumping is delayed in both client and server
2324     m_sourceListPtr->syncPrepare(source->getName());
2325 }
2326
2327 // XML configuration converted to C string constants
2328 extern "C" {
2329     // including all known fragments for a client
2330     extern const char *SyncEvolutionXMLClient;
2331     // the remote rules for a client
2332     extern const char *SyncEvolutionXMLClientRules;
2333 }
2334
2335 /**
2336  * helper class which scans directories for
2337  * XML config files
2338  */
2339 class XMLFiles
2340 {
2341 public:
2342     enum Category {
2343         MAIN,           /**< files directly under searched directories */
2344         DATATYPES,      /**< inside datatypes and datatypes/<mode> */
2345         SCRIPTING,      /**< inside scripting and scripting/<mode> */
2346         REMOTERULES,    /**< inside remoterules and remoterules/<mode> */
2347         MAX_CATEGORY
2348     };
2349
2350     /** search file system for XML config fragments */
2351     void scan(const string &mode);
2352     /** datatypes, scripts and rules concatenated, empty if none found */
2353     string get(Category category);
2354     /** main file, typically "syncevolution.xml", empty if not found */
2355     string get(const string &file);
2356
2357     static const string m_syncevolutionXML;
2358
2359 private:
2360     /* base name as sort key + full file path, iterating is done in lexical order */
2361     StringMap m_files[MAX_CATEGORY];
2362
2363     /**
2364      * scan a specific directory for main files directly inside it
2365      * and inside datatypes, scripting, remoterules;
2366      * it is not an error when it does not exist or is not a directory
2367      */
2368     void scanRoot(const string &mode, const string &dir);
2369
2370     /**
2371      * scan a datatypes/scripting/remoterules sub directory,
2372      * including the <mode> sub-directory
2373      */
2374     void scanFragments(const string &mode, const string &dir, Category category);
2375
2376     /**
2377      * add all .xml files to the right hash, overwriting old entries
2378      */
2379     void addFragments(const string &dir, Category category);
2380 };
2381
2382 const string XMLFiles::m_syncevolutionXML("syncevolution.xml");
2383
2384 void XMLFiles::scan(const string &mode)
2385 {
2386     const char *dir = getenv("SYNCEVOLUTION_XML_CONFIG_DIR");
2387     /*
2388      * read either one or the other, so that testing can run without
2389      * accidentally reading installed files
2390      */
2391     if (dir) {
2392         scanRoot(mode, dir);
2393     } else {
2394         scanRoot(mode, XML_CONFIG_DIR);
2395         scanRoot(mode, SubstEnvironment("${XDG_CONFIG_HOME}/syncevolution-xml"));
2396     }
2397 }
2398
2399 void XMLFiles::scanRoot(const string &mode, const string &dir)
2400 {
2401     addFragments(dir, MAIN);
2402     scanFragments(mode, dir + "/scripting", SCRIPTING);
2403     scanFragments(mode, dir + "/datatypes", DATATYPES);
2404     scanFragments(mode, dir + "/remoterules", REMOTERULES);
2405 }
2406
2407 void XMLFiles::scanFragments(const string &mode, const string &dir, Category category)
2408 {
2409     addFragments(dir, category);
2410     addFragments(dir + "/" + mode, category);
2411 }
2412
2413 void XMLFiles::addFragments(const string &dir, Category category)
2414 {
2415     if (!isDir(dir)) {
2416         return;
2417     }
2418     ReadDir content(dir);
2419     BOOST_FOREACH(const string &file, content) {
2420         if (boost::ends_with(file, ".xml")) {
2421             m_files[category][file] = dir + "/" + file;
2422         }
2423     }
2424 }
2425
2426 string XMLFiles::get(Category category)
2427 {
2428     string res;
2429
2430     BOOST_FOREACH(const StringPair &entry, m_files[category]) {
2431         string content;
2432         ReadFile(entry.second, content);
2433         res += content;
2434     }
2435     return res;
2436 }
2437
2438 string XMLFiles::get(const string &file)
2439 {
2440     string res;
2441     StringMap::const_iterator entry = m_files[MAIN].find(file);
2442     if (entry != m_files[MAIN].end()) {
2443         ReadFile(entry->second, res);
2444     }
2445     return res;
2446 }
2447
2448 static void substTag(string &xml, const string &tagname, const string &replacement, bool replaceElement = false)
2449 {
2450     string tag;
2451     size_t index;
2452
2453     tag.reserve(tagname.size() + 3);
2454     tag += "<";
2455     tag += tagname;
2456     tag += "/>";
2457
2458     index = xml.find(tag);
2459     if (index != xml.npos) {
2460         string tmp;
2461         tmp.reserve(tagname.size() * 2 + 2 + 3 + replacement.size());
2462         if (!replaceElement) {
2463             tmp += "<";
2464             tmp += tagname;
2465             tmp += ">";
2466         }
2467         tmp += replacement;
2468         if (!replaceElement) {
2469             tmp += "</";
2470             tmp += tagname;
2471             tmp += ">";
2472         }
2473         xml.replace(index, tag.size(), tmp);
2474     }
2475 }
2476
2477 static void substTag(string &xml, const string &tagname, const char *replacement, bool replaceElement = false)
2478 {
2479     substTag(xml, tagname, std::string(replacement), replaceElement);
2480 }
2481
2482 template <class T> void substTag(string &xml, const string &tagname, const T replacement, bool replaceElement = false)
2483 {
2484     stringstream str;
2485     str << replacement;
2486     substTag(xml, tagname, str.str(), replaceElement);
2487 }
2488
2489 void SyncContext::getConfigTemplateXML(const string &mode,
2490                                        string &xml,
2491                                        string &rules,
2492                                        string &configname)
2493 {
2494     XMLFiles files;
2495
2496     files.scan(mode);
2497     xml = files.get(files.m_syncevolutionXML);
2498     if (xml.empty()) {
2499         if (mode != "client") {
2500             SE_THROW(files.m_syncevolutionXML + " not found");
2501         }
2502         configname = "builtin XML configuration";
2503         xml = SyncEvolutionXMLClient;
2504         rules = SyncEvolutionXMLClientRules;
2505     } else {
2506         configname = "XML configuration files";
2507         rules = files.get(XMLFiles::REMOTERULES);
2508         substTag(xml, "datatypes",
2509                  files.get(XMLFiles::DATATYPES) +
2510                  "    <fieldlists/>\n    <profiles/>\n    <datatypedefs/>\n");
2511         substTag(xml, "scripting", files.get(XMLFiles::SCRIPTING));
2512     }
2513 }
2514
2515 void SyncContext::getConfigXML(string &xml, string &configname)
2516 {
2517     string rules;
2518     getConfigTemplateXML(m_serverMode ? "server" : "client",
2519                          xml,
2520                          rules,
2521                          configname);
2522
2523     string tag;
2524     size_t index;
2525     unsigned long hash = 0;
2526
2527
2528     std::set<std::string> flags = getSyncMLFlags();
2529     bool noctcap = flags.find("noctcap") != flags.end();
2530     bool norestart = flags.find("norestart") != flags.end();
2531     const char *PBAPSyncMode = getenv("SYNCEVOLUTION_PBAP_SYNC");
2532     bool keepPhotoData = PBAPSyncMode &&
2533         (boost::iequals(PBAPSyncMode, "incremental") ||
2534          boost::iequals(PBAPSyncMode, "text"));
2535     std::string sessioninitscript =
2536         "    <sessioninitscript><![CDATA[\n"
2537         "      // these variables are possibly modified by rule scripts\n"
2538         "      TIMESTAMP mindate; // earliest date remote party can handle\n"
2539         "      INTEGER retransfer_body; // if set to true, body is re-sent to client when message is moved from outbox to sent\n"
2540         "      mindate=EMPTY; // no limit by default\n"
2541         "      retransfer_body=FALSE; // normally, do not retransfer email body (and attachments) when moving items to sent box\n"
2542         "      INTEGER delayedabort;\n"
2543         "      delayedabort = FALSE;\n"
2544         "      INTEGER alarmTimeToUTC;\n"
2545         "      alarmTimeToUTC = FALSE;\n"
2546         "      INTEGER addInternetEmail;\n"
2547         "      addInternetEmail = FALSE;\n"
2548         "      INTEGER stripUID;\n"
2549         "      stripUID = FALSE;\n"
2550         "      INTEGER keepPhotoData;\n"
2551         "      keepPhotoData = "
2552         // Keep local photos in first cycle when using special sync
2553         // mode for PBAP. PBAP source will request second cycle if it
2554         // has contacts whose photo data was not donwloaded. Then we
2555         // will disable this special handling for that cycle and photo
2556         // can be updated and removed normally.
2557         + std::string(keepPhotoData ? "TRUE" : "FALSE") + ";\n"
2558         "    ]]></sessioninitscript>\n";
2559
2560     ostringstream clientorserver;
2561     if (m_serverMode) {
2562         clientorserver <<
2563             "  <server type='plugin'>\n"
2564             "    <plugin_module>SyncEvolution</plugin_module>\n"
2565             "    <plugin_sessionauth>yes</plugin_sessionauth>\n"
2566             "    <plugin_deviceadmin>yes</plugin_deviceadmin>\n";
2567
2568         InitState<unsigned int> configrequestmaxtime = getRequestMaxTime();
2569         unsigned int requestmaxtime;
2570         if (configrequestmaxtime.wasSet()) {
2571             // Explicitly set, use it regardless of the kind of sync.
2572             // We allow this even if thread support was not available,
2573             // because if a user enables it explicitly, it's probably
2574             // for a good reason (= failing client), in which case
2575             // risking multithreading issues is preferable.
2576             requestmaxtime = configrequestmaxtime.get();
2577         } else if (m_remoteInitiated || m_localSync) {
2578             // We initiated the sync (local sync, Bluetooth). The client
2579             // should not time out, so there is no need for intermediate
2580             // message sending.
2581             //
2582             // To avoid potential problems and get a single log file,
2583             // avoid it and multithreading by default.
2584             requestmaxtime = 0;
2585         } else {
2586             // We were contacted by an HTTP client. Reply to client
2587             // not later than 120 seconds while storage initializes
2588             // in a background thread.
2589 #ifdef HAVE_THREAD_SUPPORT
2590             requestmaxtime = 120; // default in seconds
2591 #else
2592             requestmaxtime = 0;
2593 #endif
2594         }
2595         if (requestmaxtime) {
2596             clientorserver <<
2597                 "    <multithread>yes</multithread>\n"
2598                 "    <requestmaxtime>" << requestmaxtime << "</requestmaxtime>\n";
2599         } else {
2600             clientorserver <<
2601                 "    <multithread>no</multithread>\n";
2602         }
2603
2604         clientorserver <<
2605             "\n" <<
2606             sessioninitscript <<
2607             "    <sessiontimeout>300</sessiontimeout>\n"
2608             "\n";
2609         //do not send respuri if over bluetooth
2610         if (boost::starts_with (getUsedSyncURL(), "obex-bt://")) {
2611             clientorserver << "    <sendrespuri>no</sendrespuri>\n"
2612             "\n";
2613         }
2614         clientorserver << "    <syncmodeextensions>" << (norestart ? "no" : "yes" ) << "</syncmodeextensions>\n";
2615         if (noctcap) {
2616             clientorserver << "    <showctcapproperties>no</showctcapproperties>\n"
2617             "\n";
2618         }
2619         clientorserver<<"    <defaultauth/>\n"
2620             "\n"
2621             "    <datastore/>\n"
2622             "\n"
2623             "    <remoterules/>\n"
2624             "  </server>\n";
2625     } else {
2626         clientorserver <<
2627             "  <client type='plugin'>\n"
2628             "    <binfilespath>$(binfilepath)</binfilespath>\n"
2629             "    <multithread>no</multithread>\n"
2630             "    <defaultauth/>\n";
2631         if (getRefreshSync()) {
2632             clientorserver <<
2633                 "    <preferslowsync>no</preferslowsync>\n";
2634         }
2635         clientorserver <<
2636             "\n" ;
2637
2638          string syncMLVersion (getSyncMLVersion());
2639          if (!syncMLVersion.empty()) {
2640              clientorserver << "<defaultsyncmlversion>"
2641                  <<syncMLVersion.c_str()<<"</defaultsyncmlversion>\n";
2642          }
2643
2644          clientorserver << "    <syncmodeextensions>" << (norestart ? "no" : "yes" ) << "</syncmodeextensions>\n";
2645          if (noctcap) {
2646              clientorserver << "    <showctcapproperties>no</showctcapproperties>\n"
2647                  "\n";
2648          }
2649
2650          clientorserver << sessioninitscript <<
2651             // SyncEvolution has traditionally not folded long lines in
2652             // vCard.  Testing showed that servers still have problems with
2653             // it, so avoid it by default
2654             "    <donotfoldcontent>yes</donotfoldcontent>\n"
2655             "\n"
2656             "    <fakedeviceid/>\n"
2657             "\n"
2658             "    <datastore/>\n"
2659             "\n"
2660             "    <remoterules/>\n"
2661             "  </client>\n";
2662     }
2663     substTag(xml,
2664              "clientorserver",
2665              clientorserver.str(),
2666              true);
2667
2668     tag = "<debug/>";
2669     index = xml.find(tag);
2670     if (index != xml.npos) {
2671         stringstream debug;
2672         bool logging = !m_sourceListPtr->getLogdir().empty();
2673         int loglevel = getLogLevel();
2674 #ifdef USE_DLT
2675         const char *useDLT = getenv("SYNCEVOLUTION_USE_DLT");
2676 #else
2677         static const char *useDLT = NULL;
2678 #endif
2679
2680         debug <<
2681             "  <debug>\n"
2682             // logpath is a config variable set by SyncContext::doSync()
2683             "    <logpath>$(logpath)</logpath>\n"
2684             "    <filename>" << (useDLT ? "" : LogfileBasename) << "</filename>" <<
2685             "    <logflushmode>flush</logflushmode>\n"
2686             "    <logformat>" << (useDLT ? "dlt" : "html") << "</logformat>\n"
2687             "    <folding>auto</folding>\n" <<
2688             (useDLT ?
2689              "    <timestamp>no</timestamp>\n"
2690              "    <timestampall>no</timestampall>\n" :
2691              "    <timestamp>yes</timestamp>\n"
2692              "    <timestampall>yes</timestampall>\n") <<
2693             "    <timedsessionlognames>no</timedsessionlognames>\n"
2694             "    <subthreadmode>separate</subthreadmode>\n"
2695             "    <logsessionstoglobal>yes</logsessionstoglobal>\n"
2696             "    <singlegloballog>yes</singlegloballog>\n";
2697 #ifdef USE_DLT
2698         if (useDLT) {
2699             const char *contexts[] = {
2700                 "PROT",
2701                 "SESS",
2702                 "ADMN",
2703                 "DATA",
2704                 "REMI",
2705                 "PARS",
2706                 "GEN",
2707                 "TRNS",
2708                 "SMLT",
2709                 "SYS"
2710             };
2711             BOOST_FOREACH (const char *context, contexts) {
2712                 // Help libsynthesis debuglogger.cpp set default log levels,
2713                 // based on our own one.
2714                 SE_LOG_DEBUG(NULL, "default libsynthesis DLT logging of %s = %s",
2715                              context, useDLT);
2716                 setenv((std::string("LIBSYNTHESIS_") + context).c_str(),
2717                        useDLT,
2718                        false);
2719             }
2720
2721             debug <<
2722                 // We have to enable all logging inside libsynthesis.
2723                 // The actual filtering then takes place inside DLT.
2724                 // Message logging is not supported.
2725                 "    <enable option=\"all\"/>\n"
2726                 // Allow logging outside of sessions.
2727                 "    <globallogs>yes</globallogs>\n"
2728                 // Don't try per-session logging, it all goes to DLT anyway.
2729                 "    <sessionlogs>yes</sessionlogs>\n"
2730                 ;
2731
2732             // Be extra verbose if currently enabled. Cannot be changed later on.
2733             if (atoi(useDLT) > DLT_LOG_DEBUG) {
2734                 debug <<
2735                     "    <enable option=\"userdata\"/>\n"
2736                     "    <enable option=\"scripts\"/>\n";
2737             }
2738             if (atoi(useDLT) > DLT_LOG_DEBUG) {
2739                 debug <<
2740                     "    <enable option=\"exotic\"/>\n";
2741             }
2742         } else
2743 #endif // USE_DLT
2744             if (logging) {
2745             debug <<
2746                 "    <sessionlogs>yes</sessionlogs>\n"
2747                 "    <globallogs>yes</globallogs>\n";
2748             debug << "<msgdump>" << (loglevel >= 5 ? "yes" : "no") << "</msgdump>\n";
2749             debug << "<xmltranslate>" << (loglevel >= 4 ? "yes" : "no") << "</xmltranslate>\n";
2750             if (loglevel >= 3) {
2751                 debug <<
2752                     "    <sourcelink>doxygen</sourcelink>\n"
2753                     "    <enable option=\"all\"/>\n"
2754                     "    <enable option=\"userdata\"/>\n"
2755                     "    <enable option=\"scripts\"/>\n"
2756                     "    <enable option=\"exotic\"/>\n";
2757             }
2758         } else {
2759             debug <<
2760                 "    <sessionlogs>no</sessionlogs>\n"
2761                 "    <globallogs>no</globallogs>\n"
2762                 "    <msgdump>no</msgdump>\n"
2763                 "    <xmltranslate>no</xmltranslate>\n"
2764                 "    <disable option=\"all\"/>";
2765         }
2766         debug <<
2767             "  </debug>\n";
2768
2769         xml.replace(index, tag.size(), debug.str());
2770     }
2771
2772     XMLConfigFragments fragments;
2773     tag = "<datastore/>";
2774     index = xml.find(tag);
2775     if (index != xml.npos) {
2776         stringstream datastores;
2777
2778         BOOST_FOREACH(SyncSource *source, *m_sourceListPtr) {
2779             string fragment;
2780             source->getDatastoreXML(fragment, fragments);
2781             string name;
2782
2783             // Make sure that sub-datastores do not interfere with the global URI namespace
2784             // by adding a <superdatastore>/ prefix. That way we can have a "calendar"
2785             // alias for "calendar+todo" without conflicting with the underlying
2786             // "calendar", which will be called "calendar+todo/calendar" in the XML config.
2787             name = source->getVirtualSource();
2788             if (!name.empty()) {
2789                 name += m_findSourceSeparator;
2790             }
2791             name += source->getName();
2792
2793             datastores << "    <datastore name='" << name << "' type='plugin'>\n" <<
2794                 "      <dbtypeid>" << source->getSynthesisID() << "</dbtypeid>\n" <<
2795                 fragment;
2796
2797             datastores << "      <resumesupport>on</resumesupport>\n";
2798             if (source->getOperations().m_writeBlob) {
2799                 // BLOB support is essential for caching partially received items.
2800                 datastores << "      <resumeitemsupport>on</resumeitemsupport>\n";
2801             }
2802
2803             SyncMode mode = StringToSyncMode(source->getSync());
2804             if (source->getForceSlowSync()) {
2805                 // we *want* a slow sync, but couldn't tell the client -> force it server-side
2806                 datastores << "      <alertscript> FORCESLOWSYNC(); </alertscript>\n";
2807             } else if (mode == SYNC_LOCAL_CACHE_SLOW ||
2808                        mode == SYNC_LOCAL_CACHE_INCREMENTAL) {
2809                 if (!m_serverMode) {
2810                     SE_THROW("sync modes 'local-cache-*' are only supported on the server side");
2811                 }
2812                 datastores << "      <alertscript>SETREFRESHONLY(1); SETCACHEDATA(1);</alertscript>\n";
2813                 // datastores << "      <datastoreinitscript>REFRESHONLY(); CACHEDATA(); SLOWSYNC(); ALERTCODE();</datastoreinitscript>\n";
2814             } else if (mode != SYNC_SLOW &&
2815                        // slow-sync detection not implemented when running as server,
2816                        // not even when initiating the sync (direct sync with phone)
2817                        !m_serverMode &&
2818                        // is implemented as "delete local data" + "slow sync",
2819                        // so a slow sync is acceptable in this case
2820                        mode != SYNC_REFRESH_FROM_SERVER &&
2821                        mode != SYNC_REFRESH_FROM_REMOTE &&
2822                        // The forceSlow should be disabled if the sync session is
2823                        // initiated by a remote peer (eg. Server Alerted Sync)
2824                        !m_remoteInitiated &&
2825                        getPreventSlowSync() &&
2826                        (!source->getOperations().m_isEmpty ||    // check is only relevant if we have local data;
2827                         !source->getOperations().m_isEmpty())) { // if we cannot check, assume we have data
2828                 // We are not expecting a slow sync => refuse to execute one.
2829                 // This is the client check for this, server must be handled
2830                 // differently (TODO, MB #2416).
2831                 datastores <<
2832                     "      <datastoreinitscript><![CDATA[\n"
2833                     "           if (SLOWSYNC() && ALERTCODE() != 203) {\n" // SLOWSYNC() is true for acceptable refresh-from-client, check for that
2834                     "              DEBUGMESSAGE(\"slow sync not expected by SyncEvolution, disabling datastore\");\n"
2835                     "              ABORTDATASTORE(" << sysync::LOCERR_DATASTORE_ABORT << ");\n"
2836                     "              // tell UI to abort instead of sending the next message\n"
2837                     "              SETSESSIONVAR(\"delayedabort\", 1);\n"
2838                     "           }\n"
2839                     "      ]]></datastoreinitscript>\n";
2840             }
2841
2842             if (m_serverMode && !m_localSync) {
2843                 string uri = source->getURI();
2844                 if (!uri.empty()) {
2845                     datastores << " <alias name='" << uri << "'/>";
2846                 }
2847             }
2848
2849             datastores << "    </datastore>\n\n";
2850         }
2851
2852         /*If there is super datastore, add it here*/
2853         //TODO generate specific superdatastore contents (MB #8753)
2854         //Now only works for synthesis built-in events+tasks
2855         BOOST_FOREACH (boost::shared_ptr<VirtualSyncSource> vSource, m_sourceListPtr->getVirtualSources()) {
2856             std::string superType = vSource->getSourceType().m_format;
2857             std::string evoSyncSource = vSource->getDatabaseID();
2858             std::vector<std::string> mappedSources = unescapeJoinedString (evoSyncSource, ',');
2859
2860             // always check for a consistent config
2861             SourceType sourceType = vSource->getSourceType();
2862             BOOST_FOREACH (std::string source, mappedSources) {
2863                 //check the data type
2864                 SyncSource *subSource = (*m_sourceListPtr)[source];
2865                 SourceType subType = subSource->getSourceType();
2866
2867                 //If there is no format explictly selected in sub SyncSource, we
2868                 //have no way to determine whether it works with the format
2869                 //specific in the virtual SyncSource, thus no warning in this
2870                 //case.
2871                 if (!subType.m_format.empty() && (
2872                     sourceType.m_format != subType.m_format ||
2873                     sourceType.m_forceFormat != subType.m_forceFormat)) {
2874                     SE_LOG_WARNING(NULL,
2875                                    "Virtual data source \"%s\" and sub data source \"%s\" have different data format. Will use the format in virtual data source.",
2876                                    vSource->getDisplayName().c_str(), source.c_str());
2877                 }
2878             }
2879
2880             if (mappedSources.size() !=2) {
2881                 vSource->throwError ("virtual data source currently only supports events+tasks combinations");
2882             }
2883
2884             string name = vSource->getName();
2885             datastores << "    <superdatastore name= '" << name << "'> \n";
2886             datastores << "      <contains datastore = '" << name << m_findSourceSeparator << mappedSources[0] <<"'>\n"
2887                 << "        <dispatchfilter>F.ISEVENT:=1</dispatchfilter>\n"
2888                 << "        <guidprefix>e</guidprefix>\n"
2889                 << "      </contains>\n"
2890                 << "\n      <contains datastore = '" << name << m_findSourceSeparator << mappedSources[1] <<"'>\n"
2891                 << "        <dispatchfilter>F.ISEVENT:=0</dispatchfilter>\n"
2892                 << "        <guidprefix>t</guidprefix>\n"
2893                 <<"      </contains>\n" ;
2894
2895             if (m_serverMode && !m_localSync) {
2896                 string uri = vSource->getURI();
2897                 if (!uri.empty()) {
2898                     datastores << " <alias name='" << uri << "'/>";
2899                 }
2900             }
2901
2902             if (vSource->getForceSlowSync()) {
2903                 // we *want* a slow sync, but couldn't tell the client -> force it server-side
2904                 datastores << "      <alertscript> FORCESLOWSYNC(); </alertscript>\n";
2905             }
2906
2907             std::string typesupport;
2908             typesupport = vSource->getDataTypeSupport();
2909             datastores << "      <typesupport>\n"
2910                 << typesupport
2911                 << "      </typesupport>\n";
2912             datastores <<"\n    </superdatastore>";
2913         }
2914
2915         if (datastores.str().empty()) {
2916             // Add dummy datastore, the engine needs it. sync()
2917             // checks that we have a valid configuration if it is
2918             // really needed.
2919 #if 0
2920             datastores << "<datastore name=\"____dummy____\" type=\"plugin\">"
2921                 "<plugin_module>SyncEvolution</plugin_module>"
2922                 "<fieldmap fieldlist=\"contacts\"/>"
2923                 "<typesupport>"
2924                 "<use datatype=\"vCard30\"/>"
2925                 "</typesupport>"
2926                 "</datastore>";
2927 #endif
2928         }
2929         xml.replace(index, tag.size(), datastores.str());
2930     }
2931
2932     substTag(xml, "fieldlists", fragments.m_fieldlists.join(), true);
2933     substTag(xml, "profiles", fragments.m_profiles.join(), true);
2934     substTag(xml, "datatypedefs", fragments.m_datatypes.join(), true);
2935     substTag(xml, "remoterules",
2936              rules +
2937              fragments.m_remoterules.join(),
2938              true);
2939
2940     if (m_serverMode) {
2941         // TODO: set the device ID for an OBEX server
2942     } else {
2943         substTag(xml, "fakedeviceid", getDevID());
2944     }
2945     substTag(xml, "model", getMod());
2946     substTag(xml, "manufacturer", getMan());
2947     substTag(xml, "hardwareversion", getHwv());
2948     // abuse (?) the firmware version to store the SyncEvolution version number
2949     substTag(xml, "firmwareversion", getSwv());
2950     substTag(xml, "devicetype", getDevType());
2951     substTag(xml, "maxmsgsize", std::max(getMaxMsgSize().get(), 10000ul));
2952     substTag(xml, "maxobjsize", std::max(getMaxObjSize().get(), 1024u));
2953     if (m_serverMode) {
2954         UserIdentity id = getSyncUser();
2955         Credentials cred = IdentityProviderCredentials(id, getSyncPassword());
2956         const string &user = cred.m_username;
2957         const string &password = cred.m_password;
2958
2959         /*
2960          * Do not check username/pwd if this local sync or over
2961          * bluetooth transport. Need credentials for checking.
2962          */
2963         if (!m_localSync &&
2964             !boost::starts_with(getUsedSyncURL(), "obex-bt") &&
2965             (!user.empty() || !password.empty())) {
2966             // require authentication with the configured password
2967             substTag(xml, "defaultauth",
2968                      "<requestedauth>md5</requestedauth>\n"
2969                      "<requiredauth>basic</requiredauth>\n"
2970                      "<autononce>yes</autononce>\n",
2971                      true);
2972         } else {
2973             // no authentication required
2974             substTag(xml, "defaultauth",
2975                      "<logininitscript>return TRUE</logininitscript>\n"
2976                      "<requestedauth>none</requestedauth>\n"
2977                      "<requiredauth>none</requiredauth>\n"
2978                      "<autononce>yes</autononce>\n",
2979                      true);
2980         }
2981     } else {
2982         substTag(xml, "defaultauth", getClientAuthType());
2983     }
2984
2985     // if the hash code is changed, that means the content of the
2986     // config has changed, save the new hash and regen the configdate
2987     hash = Hash(xml.c_str());
2988     if (getHashCode() != hash) {
2989         setConfigDate();
2990         setHashCode(hash);
2991         flush();
2992     }
2993     substTag(xml, "configdate", getConfigDate().c_str());
2994 }
2995
2996 SharedEngine SyncContext::createEngine()
2997 {
2998     SharedEngine engine(new sysync::TEngineModuleBridge);
2999
3000     // This instance of the engine is used outside of the sync session
3001     // itself for logging. doSync() then reinitializes it with a full
3002     // datastore configuration.
3003     engine.Connect(m_serverMode ?
3004 #ifdef ENABLE_SYNCML_LINKED
3005                    // use Synthesis client or server engine that we were linked against
3006                    "[server:]" : "[]",
3007 #else
3008                    // load engine dynamically
3009                    "server:libsynthesis.so.0" : "libsynthesis.so.0",
3010 #endif
3011                    0,
3012                    sysync::DBG_PLUGIN_NONE|
3013                    sysync::DBG_PLUGIN_INT|
3014                    sysync::DBG_PLUGIN_DB|
3015                    sysync::DBG_PLUGIN_EXOT);
3016
3017     SharedKey configvars = engine.OpenKeyByPath(SharedKey(), "/configvars");
3018     string logdir;
3019     if (m_sourceListPtr) {
3020         logdir = m_sourceListPtr->getLogdir();
3021     }
3022     engine.SetStrValue(configvars, "defout_path",
3023                        logdir.size() ? logdir : "/dev/null");
3024     engine.SetStrValue(configvars, "conferrpath", "console");
3025     engine.SetStrValue(configvars, "binfilepath", getSynthesisDatadir().c_str());
3026     configvars.reset();
3027
3028     return engine;
3029 }
3030
3031 namespace {
3032     void GnutlsLogFunction(int level, const char *str)
3033     {
3034         SE_LOG_DEBUG("GNUTLS", "level %d: %s", level, str);
3035     }
3036 }
3037
3038 void SyncContext::initServer(const std::string &sessionID,
3039                              SharedBuffer data,
3040                              const std::string &messageType)
3041 {
3042     m_serverMode = true;
3043     m_sessionID = sessionID;
3044     m_initialMessage = data;
3045     m_initialMessageType = messageType;
3046
3047 }
3048
3049 struct SyncContext::SyncMLMessageInfo
3050 SyncContext::analyzeSyncMLMessage(const char *data, size_t len,
3051                                   const std::string &messageType)
3052 {
3053     SyncContext sync;
3054     SourceList sourceList(sync, false);
3055     sourceList.setLogLevel(SourceList::LOGGING_SUMMARY);
3056     sync.m_sourceListPtr = &sourceList;
3057     SwapContext syncSentinel(&sync);
3058     sync.initServer("", SharedBuffer(), "");
3059     SwapEngine swapengine(sync);
3060     sync.initEngine(false);
3061
3062     sysync::TEngineProgressInfo progressInfo;
3063     sysync::uInt16 stepCmd = sysync::STEPCMD_GOTDATA;
3064     SharedSession session = sync.m_engine.OpenSession(sync.m_sessionID);
3065     SessionSentinel sessionSentinel(sync, session);
3066
3067     sync.m_engine.WriteSyncMLBuffer(session, data, len);
3068     SharedKey sessionKey = sync.m_engine.OpenSessionKey(session);
3069     sync.m_engine.SetStrValue(sessionKey,
3070                               "contenttype",
3071                               messageType);
3072
3073     // analyze main loop: runs until SessionStep() signals reply or error.
3074     // Will call our SynthesisDBPlugin callbacks, most importantly
3075     // SyncEvolution_Session_CheckDevice(), which records the device ID
3076     // for us.
3077     do {
3078         sync.m_engine.SessionStep(session, stepCmd, &progressInfo);
3079         switch (stepCmd) {
3080         case sysync::STEPCMD_OK:
3081         case sysync::STEPCMD_PROGRESS:
3082             stepCmd = sysync::STEPCMD_STEP;
3083             break;
3084         default:
3085             // whatever it is, cannot proceed
3086             break;
3087         }
3088     } while (stepCmd == sysync::STEPCMD_STEP);
3089
3090     SyncMLMessageInfo info;
3091     info.m_deviceID = sync.getSyncDeviceID();
3092     return info;
3093 }
3094
3095 void SyncContext::initEngine(bool logXML)
3096 {
3097     string xml, configname;
3098     getConfigXML(xml, configname);
3099     try {
3100         m_engine.InitEngineXML(xml.c_str());
3101     } catch (const BadSynthesisResult &ex) {
3102         SE_LOG_ERROR(NULL,
3103                      "internal error, invalid XML configuration (%s):\n%s",
3104                      m_sourceListPtr && !m_sourceListPtr->empty() ?
3105                      "with datastores" :
3106                      "without datastores",
3107                      xml.c_str());
3108         throw;
3109     }
3110     if (logXML &&
3111         getLogLevel() >= 5) {
3112         SE_LOG_DEV(NULL, "Full XML configuration:\n%s", xml.c_str());
3113     }
3114 }
3115
3116 // This is just the declaration. The actual function pointer instance
3117 // is inside libsynthesis, which, for historic purposes, doesn't define
3118 // it in its header files (yet).
3119 extern "C" int (*SySync_ConsolePrintf)(FILE *stream, const char *format, ...);
3120
3121 static int nopPrintf(FILE *stream, const char *format, ...) { return 0; }
3122
3123 extern "C"
3124 {
3125     extern int (*SySync_CondTimedWait)(pthread_cond_t *cond, pthread_mutex_t *mutex, bool &aTerminated, long aMilliSecondsToWait);
3126 }
3127
3128 #ifdef HAVE_GLIB
3129 static gboolean timeout(gpointer data)
3130 {
3131     // Call me again...
3132     return true;
3133 }
3134
3135 static bool CondTimedWaitContinue(pthread_mutex_t *mutex,
3136                                   bool &terminated,
3137                                   long milliSecondsToWait,
3138                                   Timespec &deadline,
3139                                   SuspendFlags &flags,
3140                                   int &result)
3141 {
3142     // Thread has terminated?
3143     pthread_mutex_lock(mutex);
3144     if (terminated) {
3145         pthread_mutex_unlock(mutex);
3146         SE_LOG_DEBUG(NULL, "background thread completed");
3147         return false;
3148     }
3149     pthread_mutex_unlock(mutex);
3150
3151     // Abort? Ignore when waiting for final thread shutdown, because
3152     // in that case we just get called again.
3153     if (milliSecondsToWait > 0 && flags.isAborted()) {
3154         SE_LOG_DEBUG(NULL, "give up waiting for background thread, aborted");
3155         // Signal error. libsynthesis then assumes that the thread still
3156         // runs and enters its parallel message sending, which eventually
3157         // returns control to us.
3158         result = 1;
3159         return false;
3160     }
3161
3162     // Timeout?
3163     if (!milliSecondsToWait ||
3164         (milliSecondsToWait > 0 && deadline <= Timespec::system())) {
3165         SE_LOG_DEBUG(NULL, "give up waiting for background thread, timeout");
3166         result = 1;
3167         return false;
3168     }
3169
3170     return true;
3171 }
3172
3173 static int CondTimedWaitGLib(pthread_cond_t * /* cond */, pthread_mutex_t *mutex,
3174                              bool &terminated, long milliSecondsToWait)
3175 {
3176     int result = 0;
3177
3178     // return abstime ? pthread_cond_timedwait(cond, mutex, abstime) : pthread_cond_wait(cond, mutex);
3179     try {
3180         pthread_mutex_unlock(mutex);
3181
3182         SE_LOG_DEBUG(NULL, "wait for background thread: %lds", milliSecondsToWait);
3183         SuspendFlags &flags = SuspendFlags::getSuspendFlags();
3184
3185         Timespec now = Timespec::system();
3186         Timespec wait(milliSecondsToWait / 1000, milliSecondsToWait % 1000);
3187         Timespec deadline = now + wait;
3188
3189         // We don't need to react to thread shutdown immediately (only
3190         // called once per sync), so a relatively long check interval of
3191         // one second is okay.
3192         GLibEvent id(g_timeout_add_seconds(1, timeout, NULL), "timeout");
3193
3194         GRunWhile(boost::bind(CondTimedWaitContinue,
3195                               mutex,
3196                               boost::ref(terminated),
3197                               milliSecondsToWait,
3198                               boost::ref(deadline),
3199                               boost::ref(flags),
3200                               boost::ref(result)));
3201     } catch (...) {
3202         Exception::handle(HANDLE_EXCEPTION_FATAL);
3203     }
3204
3205     pthread_mutex_lock(mutex);
3206     return result;
3207 }
3208
3209 #endif
3210
3211 void SyncContext::initMain(const char *appname)
3212 {
3213 #if defined(HAVE_GLIB)
3214     // this is required when using glib directly or indirectly
3215     g_type_init();
3216     g_thread_init(NULL);
3217     g_set_prgname(appname);
3218
3219     // redirect glib logging into our own logging
3220     g_log_set_default_handler(Logger::glogFunc, NULL);
3221
3222     // Only the main thread may use the default GMainContext.
3223     // Anything else is unsafe, see https://mail.gnome.org/archives/gtk-list/2013-April/msg00040.html
3224     // util.cpp:Sleep() checks this and uses the default context
3225     // when called by the main thread, otherwise falls back to
3226     // select(). GRunWhile() is always safe to use.
3227     g_main_context_acquire(NULL);
3228
3229     SySync_CondTimedWait = CondTimedWaitGLib;
3230 #endif
3231     if (atoi(getEnv("SYNCEVOLUTION_DEBUG", "0")) > 3) {
3232         SySync_ConsolePrintf = Logger::sysyncPrintf;
3233     } else {
3234         SySync_ConsolePrintf = nopPrintf;
3235     }
3236
3237     // invoke optional init parts, for example KDE KApplication init
3238     // in KDE backend
3239     GetInitMainSignal()(appname);
3240
3241     struct sigaction sa;
3242     memset(&sa, 0, sizeof(sa));
3243     sa.sa_handler = SIG_IGN;
3244     sigaction(SIGPIPE, &sa, NULL);
3245
3246     // Initializing a potential use of EDS early is necessary for
3247     // libsynthesis when compiled with
3248     // --enable-evolution-compatibility: in that mode libical will
3249     // only be found by libsynthesis after EDSAbiWrapperInit()
3250     // pulls it into the process by loading libecal.
3251     EDSAbiWrapperInit();
3252
3253     if (const char *gnutlsdbg = getenv("SYNCEVOLUTION_GNUTLS_DEBUG")) {
3254         // Enable libgnutls debugging without creating a hard dependency on it,
3255         // because we don't call it directly and might not even be linked against
3256         // it. Therefore check for the relevant symbols via dlsym().
3257         void (*set_log_level)(int);
3258         typedef void (*LogFunc_t)(int level, const char *str);
3259         void (*set_log_function)(LogFunc_t func);
3260
3261         set_log_level = (typeof(set_log_level))dlsym(RTLD_DEFAULT, "gnutls_global_set_log_level");
3262         set_log_function = (typeof(set_log_function))dlsym(RTLD_DEFAULT, "gnutls_global_set_log_function");
3263
3264         if (set_log_level && set_log_function) {
3265             set_log_level(atoi(gnutlsdbg));
3266             set_log_function(GnutlsLogFunction);
3267         } else {
3268             SE_LOG_ERROR(NULL, "SYNCEVOLUTION_GNUTLS_DEBUG debugging not possible, log functions not found");
3269         }
3270     }
3271 }
3272
3273 SyncContext::InitMainSignal &SyncContext::GetInitMainSignal()
3274 {
3275     static InitMainSignal initMainSignal;
3276     return initMainSignal;
3277 }
3278
3279 static bool IsStableRelease =
3280 #ifdef SYNCEVOLUTION_STABLE_RELEASE
3281                    true
3282 #else
3283                    false
3284 #endif
3285                    ;
3286 bool SyncContext::isStableRelease()
3287 {
3288     return IsStableRelease;
3289 }
3290 void SyncContext::setStableRelease(bool isStableRelease)
3291 {
3292     IsStableRelease = isStableRelease;
3293 }
3294
3295 void SyncContext::checkConfig(const std::string &operation) const
3296 {
3297     std::string peer, context;
3298     splitConfigString(m_server, peer, context);
3299     if (isConfigNeeded() &&
3300         (!exists() || peer.empty())) {
3301         if (peer.empty()) {
3302             SE_LOG_INFO(NULL, "Configuration \"%s\" does not refer to a sync peer.", m_server.c_str());
3303         } else {
3304             SE_LOG_INFO(NULL, "Configuration \"%s\" does not exist.", m_server.c_str());
3305         }
3306         throwError(StringPrintf("Cannot proceed with %s without a configuration.", operation.c_str()));
3307     }
3308 }
3309
3310 SyncMLStatus SyncContext::sync(SyncReport *report)
3311 {
3312     SyncMLStatus status = STATUS_OK;
3313
3314     checkConfig("sync");
3315
3316     // redirect logging as soon as possible
3317     SourceList sourceList(*this, m_doLogging);
3318     sourceList.setLogLevel(m_quiet ? SourceList::LOGGING_QUIET :
3319                            getPrintChanges() ? SourceList::LOGGING_FULL :
3320                            SourceList::LOGGING_SUMMARY);
3321
3322     // careful about scope, this is needed for writing the
3323     // report below
3324     SyncReport buffer;
3325
3326     SwapContext syncSentinel(this);
3327     try {
3328         m_sourceListPtr = &sourceList;
3329         string url = getUsedSyncURL();
3330         if (boost::starts_with(url, "local://")) {
3331             initLocalSync(url.substr(strlen("local://")));
3332         }
3333
3334         if (!report) {
3335             report = &buffer;
3336         }
3337         report->clear();
3338         if (m_localSync) {
3339             report->setRemoteName(m_localPeerContext);
3340             report->setLocalName(getContextName());
3341         }
3342
3343         // let derived classes override settings, like the log dir
3344         prepare();
3345
3346         // choose log directory
3347         sourceList.startSession(getLogDir(),
3348                                 getMaxLogDirs(),
3349                                 getLogLevel(),
3350                                 report);
3351
3352         /* Must detect server or client session before creating the
3353          * underlying SynthesisEngine
3354          * */
3355         if ( getPeerIsClient()) {
3356             m_serverMode = true;
3357         } else if (m_localSync && !m_agent) {
3358             throwError("configuration error, syncURL = local can only be used in combination with peerIsClient = 1");
3359         }
3360
3361         // create a Synthesis engine, used purely for logging purposes
3362         // at this time
3363         SwapEngine swapengine(*this);
3364         initEngine(false);
3365
3366         try {
3367             // dump some summary information at the beginning of the log
3368             SE_LOG_DEV(NULL, "SyncML server account: %s", getSyncUser().toString().c_str());
3369             SE_LOG_DEV(NULL, "client: SyncEvolution %s for %s", getSwv().c_str(), getDevType().c_str());
3370             SE_LOG_DEV(NULL, "device ID: %s", getDevID().c_str());
3371             SE_LOG_DEV(NULL, "%s", EDSAbiWrapperDebug());
3372             SE_LOG_DEV(NULL, "%s", SyncSource::backendsDebug().c_str());
3373
3374             // ensure that config can be modified (might have to be migrated first)
3375             prepareConfigForWrite();
3376
3377             // instantiate backends, but do not open them yet
3378             initSources(sourceList);
3379             if (sourceList.empty()) {
3380                 throwError("no sources active, check configuration");
3381             }
3382
3383             // request all config properties once: throwing exceptions
3384             // now is okay, whereas later it would lead to leaks in the
3385             // not exception safe client library
3386             SyncConfig dummy;
3387             set<string> activeSources = sourceList.getSources();
3388             dummy.copy(*this, &activeSources);
3389
3390             // start background thread if not running yet:
3391             // necessary to catch problems with Evolution backend
3392             startLoopThread();
3393
3394             // ask for passwords now
3395             PasswordConfigProperty::checkPasswords(getUserInterfaceNonNull(), *this,
3396                                                    PasswordConfigProperty::CHECK_PASSWORD_ALL,
3397                                                    sourceList.getSourceNames());
3398
3399             // open each source - failing now is still safe
3400             // in clients; in servers we wait until the source
3401             // is really needed
3402             BOOST_FOREACH(SyncSource *source, sourceList) {
3403                 if (m_serverMode) {
3404                     source->enableServerMode();
3405                 } else {
3406                     source->open();
3407                 }
3408
3409                 // request callback when starting to use source
3410                 source->getOperations().m_startDataRead.getPreSignal().connect(boost::bind(&SyncContext::startSourceAccess, this, source));
3411             }
3412
3413             // ready to go
3414             status = doSync();
3415         } catch (...) {
3416             // handle the exception here while the engine (and logging!) is still alive
3417             Exception::handle(&status);
3418             goto report;
3419         }
3420     } catch (...) {
3421         Exception::handle(&status);
3422     }
3423
3424  report:
3425     if (status == SyncMLStatus(sysync::LOCERR_DATASTORE_ABORT)) {
3426         // this can mean only one thing in SyncEvolution: unexpected slow sync
3427         status = STATUS_UNEXPECTED_SLOW_SYNC;
3428     }
3429
3430
3431     try {
3432         // Print final report before cleaning up.
3433         // Status was okay only if all sources succeeded.
3434         // When a source or the overall sync was successful,
3435         // but some items failed, we report a "partial failure"
3436         // status.
3437         BOOST_FOREACH(SyncSource *source, sourceList) {
3438             m_sourceSyncedSignal(source->getName(), *source);
3439             if (source->getStatus() == STATUS_OK &&
3440                 (source->getItemStat(SyncSource::ITEM_LOCAL,
3441                                      SyncSource::ITEM_ANY,
3442                                      SyncSource::ITEM_REJECT) ||
3443                  source->getItemStat(SyncSource::ITEM_REMOTE,
3444                                      SyncSource::ITEM_ANY,
3445                                      SyncSource::ITEM_REJECT))) {
3446                 source->recordStatus(STATUS_PARTIAL_FAILURE);
3447             }
3448             if (source->getStatus() != STATUS_OK &&
3449                 status == STATUS_OK) {
3450                 status = source->getStatus();
3451                 break;
3452             }
3453         }
3454
3455         // Also take into account result of client side in local sync,
3456         // if any existed. A non-success status code in the client's report
3457         // was already propagated to the parent via a TransportStatusException
3458         // in LocalTransportAgent::checkChildReport(). What we can do here
3459         // is updating the individual's sources status.
3460         if (m_localSync && m_agent && getPeerIsClient()) {
3461             boost::shared_ptr<LocalTransportAgent> agent = boost::static_pointer_cast<LocalTransportAgent>(m_agent);
3462             SyncReport childReport;
3463             agent->getClientSyncReport(childReport);
3464             BOOST_FOREACH(SyncSource *source, sourceList) {
3465                 const SyncSourceReport *childSourceReport = childReport.findSyncSourceReport(source->getURINonEmpty());
3466                 if (childSourceReport) {
3467                     SyncMLStatus parentSourceStatus = source->getStatus();
3468                     SyncMLStatus childSourceStatus = childSourceReport->getStatus();
3469                     // child source had an error *and*
3470                     // parent error is either unspecific (USERABORT) or
3471                     // is a remote error (HTTP error range)
3472                     if (childSourceStatus != STATUS_OK && childSourceStatus != STATUS_HTTP_OK &&
3473                         (parentSourceStatus == SyncMLStatus(sysync::LOCERR_USERABORT) ||
3474                          parentSourceStatus < SyncMLStatus(sysync::LOCAL_STATUS_CODE))) {
3475                         source->recordStatus(childSourceStatus);
3476                     }
3477                 }
3478             }
3479         }
3480
3481         sourceList.updateSyncReport(*report);
3482         sourceList.syncDone(status, report);
3483     } catch(...) {
3484         Exception::handle(&status);
3485     }
3486
3487     m_agent.reset();
3488     m_sourceListPtr = NULL;
3489     return status;
3490 }
3491
3492 bool SyncContext::sendSAN(uint16_t version)
3493 {
3494     sysync::SanPackage san;
3495     bool legacy = version < 12;
3496     /* Should be nonce sent by the server in the preceeding sync session */
3497     string nonce = "SyncEvolution";
3498     UserIdentity id = getSyncUser();
3499     Credentials cred = IdentityProviderCredentials(id, getSyncPassword());
3500     const std::string &user = cred.m_username;
3501     const std::string &password = cred.m_password;
3502     string uauthb64 = san.B64_H(user, password);
3503     /* Client is expected to conduct the sync in the backgroud */
3504     sysync::UI_Mode mode = sysync::UI_not_specified;
3505
3506     uint16_t sessionId = 1;
3507     string serverId = getRemoteIdentifier();
3508     if(serverId.empty()) {
3509         serverId = getDevID();
3510     }
3511     SE_LOG_DEBUG(NULL, "starting SAN %u auth %s nonce %s session %u server %s",
3512                  version,
3513                  uauthb64.c_str(),
3514                  nonce.c_str(),
3515                  sessionId,
3516                  serverId.c_str());
3517     san.PreparePackage( uauthb64, nonce, version, mode,
3518             sysync::Initiator_Server, sessionId, serverId);
3519
3520     san.CreateEmptyNotificationBody();
3521     bool hasSource = false;
3522
3523     std::set<std::string> dataSources = m_sourceListPtr->getSources();
3524
3525     /* For each virtual datasoruce, generate the SAN accoring to it and ignoring
3526      * sub datasource in the later phase*/
3527     BOOST_FOREACH (boost::shared_ptr<VirtualSyncSource> vSource, m_sourceListPtr->getVirtualSources()) {
3528             std::string evoSyncSource = vSource->getDatabaseID();
3529             std::string sync = vSource->getSync();
3530             SANSyncMode mode = AlertSyncMode(StringToSyncMode(sync, true), getPeerIsClient());
3531             std::vector<std::string> mappedSources = unescapeJoinedString (evoSyncSource, ',');
3532             BOOST_FOREACH (std::string source, mappedSources) {
3533                 dataSources.erase (source);
3534                 if (mode == SA_SLOW) {
3535                     // We force a source which the client is not expected to use into slow mode.
3536                     // Shouldn't we rather reject attempts to synchronize it?
3537                     (*m_sourceListPtr)[source]->setForceSlowSync(true);
3538                 }
3539             }
3540             dataSources.insert (vSource->getName());
3541     }
3542
3543     SANSyncMode syncMode = SA_INVALID;
3544     vector<pair <string, string> > alertedSources;
3545
3546     /* For each source to be notified do the following: */
3547     BOOST_FOREACH (string name, dataSources) {
3548         boost::shared_ptr<PersistentSyncSourceConfig> sc(getSyncSourceConfig(name));
3549         string sync = sc->getSync();
3550         SANSyncMode mode = AlertSyncMode(StringToSyncMode(sync, true), getPeerIsClient());
3551         if (mode == SA_SLOW) {
3552             (*m_sourceListPtr)[name]->setForceSlowSync(true);
3553             mode = SA_TWO_WAY;
3554         }
3555         if (mode < SA_FIRST || mode > SA_LAST) {
3556             SE_LOG_DEV(NULL, "Ignoring data source %s with an invalid sync mode", name.c_str());
3557             continue;
3558         }
3559         syncMode = mode;
3560         hasSource = true;
3561         string uri = sc->getURINonEmpty();
3562
3563         SourceType sourceType = sc->getSourceType();
3564         /*If the type is not set by user explictly, let's use backend default
3565          * value*/
3566         if(sourceType.m_format.empty()) {
3567             sourceType.m_format = (*m_sourceListPtr)[name]->getPeerMimeType();
3568         }
3569         if (!legacy) {
3570             /*If user did not use force type, we will always use the older type as
3571              * this is what most phones support*/
3572             int contentTypeB = StringToContentType (sourceType.m_format, sourceType.m_forceFormat);
3573             if (contentTypeB == WSPCTC_UNKNOWN) {
3574                 contentTypeB = 0;
3575                 SE_LOG_DEBUG(NULL, "Unknown datasource mimetype, use 0 as default");
3576             }
3577             SE_LOG_DEBUG(NULL, "SAN source %s uri %s type %u mode %d",
3578                          name.c_str(),
3579                          uri.c_str(),
3580                          contentTypeB,
3581                          mode);
3582             if ( san.AddSync(mode, (uInt32) contentTypeB, uri.c_str())) {
3583                 SE_LOG_ERROR(NULL, "SAN: adding server alerted sync element failed");
3584             };
3585         } else {
3586             string mimetype = GetLegacyMIMEType(sourceType.m_format, sourceType.m_forceFormat);
3587             SE_LOG_DEBUG(NULL, "SAN source %s uri %s type %s",
3588                          name.c_str(),
3589                          uri.c_str(),
3590                          mimetype.c_str());
3591             alertedSources.push_back(std::make_pair(mimetype, uri));
3592         }
3593     }
3594
3595     if (!hasSource) {
3596         SE_THROW ("No source enabled for server alerted sync!");
3597     }
3598
3599     /* Generate the SAN Package */
3600     void *buffer;
3601     size_t sanSize;
3602     if (!legacy) {
3603         if (san.GetPackage(buffer, sanSize)){
3604             SE_LOG_ERROR(NULL, "SAN package generating failed");
3605             return false;
3606         }
3607         //TODO log the binary SAN content
3608     } else {
3609         SE_LOG_DEBUG(NULL, "SAN with overall sync mode %d", syncMode);
3610         if (san.GetPackageLegacy(buffer, sanSize, alertedSources, syncMode, getWBXML())){
3611             SE_LOG_ERROR(NULL, "SAN package generating failed");
3612             return false;
3613         }
3614         //SE_LOG_DEBUG(NULL, "SAN package content: %s", (char*)buffer);
3615     }
3616
3617     m_agent = createTransportAgent();
3618     SE_LOG_INFO(NULL, "Server sending SAN");
3619     m_serverAlerted = true;
3620     m_agent->setContentType(!legacy ?
3621                            TransportAgent::m_contentTypeServerAlertedNotificationDS
3622                            : (getWBXML() ? TransportAgent::m_contentTypeSyncWBXML :
3623                             TransportAgent::m_contentTypeSyncML));
3624     m_agent->send(reinterpret_cast <char *> (buffer), sanSize);
3625     //change content type
3626     m_agent->setContentType(getWBXML() ? TransportAgent::m_contentTypeSyncWBXML :
3627                             TransportAgent::m_contentTypeSyncML);
3628
3629     TransportAgent::Status status;
3630     do {
3631         status = m_agent->wait();
3632     } while(status == TransportAgent::ACTIVE);
3633     if (status == TransportAgent::GOT_REPLY) {
3634         const char *reply;
3635         size_t replyLen;
3636         string contentType;
3637         m_agent->getReply (reply, replyLen, contentType);
3638
3639         //sanity check for the reply
3640         if (contentType.empty() ||
3641             contentType.find(TransportAgent::m_contentTypeSyncML) != contentType.npos ||
3642             contentType.find(TransportAgent::m_contentTypeSyncWBXML) != contentType.npos) {
3643             SharedBuffer request (reply, replyLen);
3644             //TODO should generate more reasonable sessionId here
3645             string sessionId ="";
3646             initServer (sessionId, request, contentType);
3647             return true;
3648         }
3649     }
3650     return false;
3651 }
3652
3653 static string Step2String(sysync::uInt16 stepcmd)
3654 {
3655     switch (stepcmd) {
3656     case sysync::STEPCMD_CLIENTSTART: return "STEPCMD_CLIENTSTART";
3657     case sysync::STEPCMD_CLIENTAUTOSTART: return "STEPCMD_CLIENTAUTOSTART";
3658     case sysync::STEPCMD_STEP: return "STEPCMD_STEP";
3659     case sysync::STEPCMD_GOTDATA: return "STEPCMD_GOTDATA";
3660     case sysync::STEPCMD_SENTDATA: return "STEPCMD_SENTDATA";
3661     case sysync::STEPCMD_SUSPEND: return "STEPCMD_SUSPEND";
3662     case sysync::STEPCMD_ABORT: return "STEPCMD_ABORT";
3663     case sysync::STEPCMD_TRANSPFAIL: return "STEPCMD_TRANSPFAIL";
3664     case sysync::STEPCMD_TIMEOUT: return "STEPCMD_TIMEOUT";
3665     case sysync::STEPCMD_SAN_CHECK: return "STEPCMD_SAN_CHECK";
3666     case sysync::STEPCMD_AUTOSYNC_CHECK: return "STEPCMD_AUTOSYNC_CHECK";
3667     case sysync::STEPCMD_OK: return "STEPCMD_OK";
3668     case sysync::STEPCMD_PROGRESS: return "STEPCMD_PROGRESS";
3669     case sysync::STEPCMD_ERROR: return "STEPCMD_ERROR";
3670     case sysync::STEPCMD_SENDDATA: return "STEPCMD_SENDDATA";
3671     case sysync::STEPCMD_NEEDDATA: return "STEPCMD_NEEDDATA";
3672     case sysync::STEPCMD_RESENDDATA: return "STEPCMD_RESENDDATA";
3673     case sysync::STEPCMD_DONE: return "STEPCMD_DONE";
3674     case sysync::STEPCMD_RESTART: return "STEPCMD_RESTART";
3675     case sysync::STEPCMD_NEEDSYNC: return "STEPCMD_NEEDSYNC";
3676     default: return StringPrintf("STEPCMD %d", stepcmd);
3677     }
3678 }
3679
3680 SyncMLStatus SyncContext::doSync()
3681 {
3682     boost::shared_ptr<SuspendFlags::Guard> signalGuard;
3683     // install signal handlers unless this was explicitly disabled
3684     bool catchSignals = getenv("SYNCEVOLUTION_NO_SYNC_SIGNALS") == NULL;
3685     if (catchSignals) {
3686         SE_LOG_DEBUG(NULL, "sync is starting, catch signals");
3687         signalGuard = SuspendFlags::getSuspendFlags().activate();
3688     }
3689
3690     // delay the sync for debugging purposes
3691     SE_LOG_DEBUG(NULL, "ready to sync");
3692     const char *delay = getenv("SYNCEVOLUTION_SYNC_DELAY");
3693     if (delay) {
3694         Sleep(atoi(delay));
3695     }
3696
3697     SuspendFlags &flags = SuspendFlags::getSuspendFlags();
3698     if (!flags.isNormal()) {
3699         return (SyncMLStatus)sysync::LOCERR_USERABORT;
3700     }
3701
3702     SyncMLStatus status = STATUS_OK;
3703     std::string s;
3704
3705     if (m_serverMode &&
3706         !m_initialMessage.size() &&
3707         !m_localSync) {
3708         //This is a server alerted sync !
3709         string sanFormat (getSyncMLVersion());
3710         uint16_t version = 12;
3711         if (boost::iequals (sanFormat, "1.2") ||
3712             sanFormat == "") {
3713             version = 12;
3714         } else if (boost::iequals (sanFormat, "1.1")) {
3715             version = 11;
3716         } else {
3717             version = 10;
3718         }
3719
3720         bool status = true;
3721         try {
3722             status = sendSAN (version);
3723         } catch (TransportException e) {
3724             if (!sanFormat.empty()){
3725                 throw;
3726             }
3727             status = false;
3728             //by pass the exception if we will try again with legacy SANFormat
3729         }
3730
3731         if (!flags.isNormal()) {
3732             return (SyncMLStatus)sysync::LOCERR_USERABORT;
3733         }
3734
3735         if (! status) {
3736             if (sanFormat.empty()) {
3737                 SE_LOG_DEBUG(NULL, "Server Alerted Sync init with SANFormat %d failed, trying with legacy format", version);
3738                 version = 11;
3739                 if (!sendSAN (version)) {
3740                     // return a proper error code
3741                     throwError ("Server Alerted Sync init failed");
3742                 }
3743             } else {
3744                 // return a proper error code
3745                 throwError ("Server Alerted Sync init failed");
3746             }
3747         }
3748     }
3749
3750     if (!flags.isNormal()) {
3751         return (SyncMLStatus)sysync::LOCERR_USERABORT;
3752     }
3753
3754     // re-init engine with all sources configured
3755     string xml, configname;
3756     initEngine(true);
3757
3758     SharedKey targets;
3759     SharedKey target;
3760     if (m_serverMode) {
3761         // Server engine has no profiles. All settings have be done
3762         // via the XML configuration or function parameters (session ID
3763         // in OpenSession()).
3764     } else {
3765         // check the settings status (MUST BE DONE TO MAKE SETTINGS READY)
3766         SharedKey profiles = m_engine.OpenKeyByPath(SharedKey(), "/profiles");
3767         m_engine.GetStrValue(profiles, "settingsstatus");
3768         // allow creating new settings when existing settings are not up/downgradeable
3769         m_engine.SetStrValue(profiles, "overwrite",  "1");
3770         // check status again
3771         m_engine.GetStrValue(profiles, "settingsstatus");
3772
3773         // open first profile
3774         SharedKey profile;
3775         profile = m_engine.OpenSubkey(profiles, sysync::KEYVAL_ID_FIRST, true);
3776         if (!profile) {
3777             // no profile exists  yet, create default profile
3778             profile = m_engine.OpenSubkey(profiles, sysync::KEYVAL_ID_NEW_DEFAULT);
3779         }
3780         if (!m_localSync) {
3781             // Not needed for local sync and might even be
3782             // impossible/wrong because username could refer to an
3783             // identity provider which cannot return a plain string.
3784             SE_LOG_DEBUG(NULL, "copying syncURL, username, password to Synthesis engine");
3785             m_engine.SetStrValue(profile, "serverURI", getUsedSyncURL());
3786             UserIdentity syncUser = getSyncUser();
3787             InitStateString syncPassword = getSyncPassword();
3788             boost::shared_ptr<AuthProvider> provider = AuthProvider::create(syncUser, syncPassword);
3789             Credentials cred = provider->getCredentials();
3790             const std::string &user = cred.m_username;
3791             const std::string &password = cred.m_password;
3792             m_engine.SetStrValue(profile, "serverUser", user);
3793             m_engine.SetStrValue(profile, "serverPassword", password);
3794         }
3795         m_engine.SetInt32Value(profile, "encoding",
3796                                getWBXML() ? 1 /* WBXML */ : 2 /* XML */);
3797
3798         // Iterate over all data stores in the XML config
3799         // and match them with sync sources.
3800         // TODO: let sync sources provide their own
3801         // XML snippets (inside <client> and inside <datatypes>).
3802         targets = m_engine.OpenKeyByPath(profile, "targets");
3803
3804         for(target = m_engine.OpenSubkey(targets, sysync::KEYVAL_ID_FIRST, true);
3805             target;
3806             target = m_engine.OpenSubkey(targets, sysync::KEYVAL_ID_NEXT, true)) {
3807             s = m_engine.GetStrValue(target, "dbname");
3808             SyncSource *source = findSource(s);
3809             if (source) {
3810                 m_engine.SetInt32Value(target, "enabled", 1);
3811                 int slow = 0;
3812                 int direction = 0;
3813                 string sync = source->getSync();
3814                 // this code only runs when we are the client,
3815                 // take that into account for the "from-local/remote" modes
3816                 SimpleSyncMode mode = SimplifySyncMode(StringToSyncMode(sync), false);
3817                 if (mode == SIMPLE_SYNC_SLOW) {
3818                     slow = 1;
3819                     direction = 0;
3820                 } else if (mode == SIMPLE_SYNC_TWO_WAY) {
3821                     slow = 0;
3822                     direction = 0;
3823                 } else if (mode == SIMPLE_SYNC_REFRESH_FROM_REMOTE) {
3824                     slow = 1;
3825                     direction = 1;
3826                 } else if (mode == SIMPLE_SYNC_REFRESH_FROM_LOCAL) {
3827                     slow = 1;
3828                     direction = 2;
3829                 } else if (mode == SIMPLE_SYNC_ONE_WAY_FROM_REMOTE) {
3830                     slow = 0;
3831                     direction = 1;
3832                 } else if (mode == SIMPLE_SYNC_ONE_WAY_FROM_LOCAL) {
3833                     slow = 0;
3834                     direction = 2;
3835                 } else {
3836                     source->throwError(string("invalid sync mode: ") + sync);
3837                 }
3838                 m_engine.SetInt32Value(target, "forceslow", slow);
3839                 m_engine.SetInt32Value(target, "syncmode", direction);
3840
3841                 string uri = source->getURINonEmpty();
3842                 m_engine.SetStrValue(target, "remotepath", uri);
3843             } else {
3844                 m_engine.SetInt32Value(target, "enabled", 0);
3845             }
3846         }
3847
3848         // Close all keys so that engine can flush the modified config.
3849         // Otherwise the session reads the unmodified values from the
3850         // created files while the updated values are still in memory.
3851         target.reset();
3852         targets.reset();
3853         profile.reset();
3854         profiles.reset();
3855
3856         // reopen profile keys
3857         profiles = m_engine.OpenKeyByPath(SharedKey(), "/profiles");
3858         m_engine.GetStrValue(profiles, "settingsstatus");
3859         profile = m_engine.OpenSubkey(profiles, sysync::KEYVAL_ID_FIRST);
3860         targets = m_engine.OpenKeyByPath(profile, "targets");
3861     }
3862
3863     m_retries = 0;
3864
3865     //Create the transport agent if not already created
3866     if(!m_agent) {
3867         m_agent = createTransportAgent();
3868     }
3869
3870     // server in local sync initiates sync by passing data to forked process
3871     if (m_serverMode && m_localSync) {
3872         m_serverAlerted = true;
3873     }
3874
3875     sysync::TEngineProgressInfo progressInfo;
3876     sysync::uInt16 stepCmd =
3877         (m_localSync && m_serverMode) ? sysync::STEPCMD_NEEDDATA :
3878         m_serverMode ?
3879         sysync::STEPCMD_GOTDATA :
3880         sysync::STEPCMD_CLIENTSTART;
3881     SharedSession session = m_engine.OpenSession(m_sessionID);
3882     SharedBuffer sendBuffer;
3883     std::auto_ptr<SessionSentinel> sessionSentinel(new SessionSentinel(*this, session));
3884
3885     if (m_serverMode && !m_localSync) {
3886         m_engine.WriteSyncMLBuffer(session,
3887                                    m_initialMessage.get(),
3888                                    m_initialMessage.size());
3889         SharedKey sessionKey = m_engine.OpenSessionKey(session);
3890         m_engine.SetStrValue(sessionKey,
3891                              "contenttype",
3892                              m_initialMessageType);
3893         m_initialMessage.reset();
3894
3895         // TODO: set "sendrespuri" session key to control
3896         // whether the generated messages contain a respURI
3897         // (not needed for OBEX)
3898     }
3899
3900     // Sync main loop: runs until SessionStep() signals end or error.
3901     // Exceptions are caught and lead to a call of SessionStep() with
3902     // parameter STEPCMD_ABORT -> abort session as soon as possible.
3903     bool aborting = false;
3904     int suspending = 0;
3905     Timespec sendStart, resendStart;
3906     int requestNum = 0;
3907     sysync::uInt16 previousStepCmd = stepCmd;
3908     std::vector<int> numItemsReceived; // source->getTotalNumItemsReceived() for each source, see STEPCMD_SENDDATA
3909     do {
3910         try {
3911             // check for suspend, if so, modify step command for next step
3912             // Since the suspend will actually be committed until it is
3913             // sending out a message, we can safely delay the suspend to
3914             // GOTDATA state.
3915             // After exception occurs, stepCmd will be set to abort to force
3916             // aborting, must avoid to change it back to suspend cmd.
3917             if (flags.isSuspended() && stepCmd == sysync::STEPCMD_GOTDATA) {
3918                 SE_LOG_DEBUG(NULL, "suspending before SessionStep() in STEPCMD_GOTDATA as requested by user");
3919                 stepCmd = sysync::STEPCMD_SUSPEND;
3920             }
3921
3922             // Aborting is useful while waiting for a reply and before
3923             // sending a message (which will just lead to us waiting
3924             // for the reply, but possibly after doing some slow network
3925             // IO for setting up the message send).
3926             //
3927             // While processing a message we let the engine run, because
3928             // that is a) likely to be done soon and b) may reduce the
3929             // breakage caused by aborting a running sync.
3930             //
3931             // This check here covers the "waiting for reply" case.
3932             if ((stepCmd == sysync::STEPCMD_RESENDDATA ||
3933                  stepCmd == sysync::STEPCMD_SENTDATA ||
3934                  stepCmd == sysync::STEPCMD_NEEDDATA) &&
3935                 flags.isAborted()) {
3936                 SE_LOG_DEBUG(NULL, "aborting before SessionStep() in %s as requested by script",
3937                              Step2String(stepCmd).c_str());
3938                 stepCmd = sysync::STEPCMD_ABORT;
3939             }
3940
3941             // take next step, but don't abort twice: instead
3942             // let engine contine with its shutdown
3943             if (stepCmd == sysync::STEPCMD_ABORT) {
3944                 if (aborting) {
3945                     SE_LOG_DEBUG(NULL, "engine already notified of abort request, reverting to %s",
3946                                  Step2String(previousStepCmd).c_str());
3947                     stepCmd = previousStepCmd;
3948                 } else {
3949                     aborting = true;
3950                 }
3951             }
3952             // same for suspending
3953             if (stepCmd == sysync::STEPCMD_SUSPEND) {
3954                 if (suspending) {
3955                     SE_LOG_DEBUG(NULL, "engine already notified of suspend request, reverting to %s",
3956                                  Step2String(previousStepCmd).c_str());
3957                     stepCmd = previousStepCmd;
3958                     suspending++;
3959                 } else {
3960                     suspending++;
3961                 }
3962             }
3963
3964             if (stepCmd == sysync::STEPCMD_NEEDDATA) {
3965                 // Engine already notified. Don't call it twice
3966                 // with this state, because it doesn't know how
3967                 // to handle this. Skip the SessionStep() call
3968                 // and wait for response.
3969             } else {
3970                 if (getLogLevel() > 4) {
3971                     SE_LOG_DEBUG(NULL, "before SessionStep: %s", Step2String(stepCmd).c_str());
3972                 }
3973                 m_engine.SessionStep(session, stepCmd, &progressInfo);
3974                 if (getLogLevel() > 4) {
3975                     SE_LOG_DEBUG(NULL, "after SessionStep: %s", Step2String(stepCmd).c_str());
3976                 }
3977                 reportStepCmd(stepCmd);
3978             }
3979
3980             if (stepCmd == sysync::STEPCMD_SENDDATA &&
3981                 checkForScriptAbort(session)) {
3982                 SE_LOG_DEBUG(NULL, "aborting after SessionStep() in STEPCMD_SENDDATA as requested by script");
3983
3984                 // Catch outgoing message and abort if requested by script.
3985                 // Report which sources are affected, based on their status code.
3986                 set<string> sources;
3987                 BOOST_FOREACH(SyncSource *source, *m_sourceListPtr) {
3988                     if (source->getStatus() == STATUS_UNEXPECTED_SLOW_SYNC) {
3989                         string name = source->getVirtualSource();
3990                         if (name.empty()) {
3991                             name = source->getName();
3992                         }
3993                         sources.insert(name);
3994                     }
3995                 }
3996                 string explanation = SyncReport::slowSyncExplanation(m_server,
3997                                                                      sources);
3998                 if (!explanation.empty()) {
3999                     string sourceparam = boost::join(sources, " ");
4000                     SE_LOG_ERROR(NULL,
4001                                  "Aborting because of unexpected slow sync for source(s): %s",
4002                                  sourceparam.c_str());
4003                     SE_LOG_INFO(NULL, "%s", explanation.c_str());
4004                 } else {
4005                     // we should not get here, but if we do, at least log something
4006                     SE_LOG_ERROR(NULL, "aborting as requested by script");
4007                 }
4008                 stepCmd = sysync::STEPCMD_ABORT;
4009                 continue;
4010             } else if (stepCmd == sysync::STEPCMD_SENDDATA &&
4011                        flags.isAborted()) {
4012                 // Catch outgoing message and abort if requested by user.
4013                 SE_LOG_DEBUG(NULL, "aborting after SessionStep() in STEPCMD_SENDDATA as requested by user");
4014                 stepCmd = sysync::STEPCMD_ABORT;
4015                 continue;
4016             } else if (suspending == 1) {
4017                 //During suspention we actually insert a STEPCMD_SUSPEND cmd
4018                 //Should restore to the original step here
4019                 stepCmd = previousStepCmd;
4020                 continue;
4021             }
4022
4023             switch (stepCmd) {
4024             case sysync::STEPCMD_OK:
4025                 // no progress info, call step again
4026                 stepCmd = sysync::STEPCMD_STEP;
4027                 break;
4028             case sysync::STEPCMD_PROGRESS:
4029                 // new progress info to show
4030                 // Check special case of interactive display alert
4031                 if (progressInfo.eventtype == sysync::PEV_DISPLAY100) {
4032                     // alert 100 received from remote, message text is in
4033                     // SessionKey's "displayalert" field
4034                     SharedKey sessionKey = m_engine.OpenSessionKey(session);
4035                     // get message from server to display
4036                     s = m_engine.GetStrValue(sessionKey,
4037                                              "displayalert");
4038                     displayServerMessage(s);
4039                 } else {
4040                     switch (progressInfo.targetID) {
4041                     case sysync::KEYVAL_ID_UNKNOWN:
4042                     case 0 /* used with PEV_SESSIONSTART?! */:
4043                         displaySyncProgress(sysync::TProgressEventEnum(progressInfo.eventtype),
4044                                             progressInfo.extra1,
4045                                             progressInfo.extra2,
4046                                             progressInfo.extra3);
4047                         if (progressInfo.eventtype == sysync::PEV_SESSIONEND &&
4048                             !status) {
4049                             // remember sync result
4050                             status = SyncMLStatus(progressInfo.extra1);
4051                         }
4052                         break;
4053                     default: {
4054                         // specific for a certain sync source:
4055                         // find it...
4056                         SyncSource *source = m_sourceListPtr->lookupBySynthesisID(progressInfo.targetID);
4057                         if (source) {
4058                             displaySourceProgress(*source,
4059                                                   SyncSourceEvent(sysync::TProgressEventEnum(progressInfo.eventtype),
4060                                                                   progressInfo.extra1,
4061                                                                   progressInfo.extra2,
4062                                                                   progressInfo.extra3),
4063                                                   false);
4064                         } else {
4065                             throwError(std::string("unknown target ") + s);
4066                         }
4067                         target.reset();
4068                         break;
4069                     }
4070                     }
4071                 }
4072                 stepCmd = sysync::STEPCMD_STEP;
4073                 break;
4074             case sysync::STEPCMD_ERROR:
4075                 // error, terminate (should not happen, as status is
4076                 // already checked above)
4077                 break;
4078             case sysync::STEPCMD_RESTART:
4079                 // make sure connection is closed and will be re-opened for next request
4080                 // tbd: close communication channel if still open to make sure it is
4081                 //       re-opened for the next request
4082                 stepCmd = sysync::STEPCMD_STEP;
4083                 m_retries = 0;
4084                 break;
4085             case sysync::STEPCMD_SENDDATA: {
4086                 // We'll be busy for a while with network IO, so give
4087                 // sources a chance to do some work in parallel and
4088                 // flush pending progress notifications.
4089                 if (m_sourceListPtr) {
4090                     bool needResults = true;
4091                     if (numItemsReceived.size() < m_sourceListPtr->size()) {
4092                         numItemsReceived.insert(numItemsReceived.end(),
4093                                                 m_sourceListPtr->size() - numItemsReceived.size(),
4094                                                 0);
4095                     }
4096                     for (size_t i = 0; i < numItemsReceived.size(); i++) {
4097                         SyncSource *source = (*m_sourceListPtr->getSourceSet())[i];
4098                         int received = source->getTotalNumItemsReceived();
4099                         SE_LOG_DEBUG(source->getDisplayName(), "total number of items received %d",
4100                                      received);
4101                         if (numItemsReceived[i] != received) {
4102                             numItemsReceived[i] = received;
4103                             needResults = false;
4104                         }
4105                     }
4106
4107                     BOOST_FOREACH (SyncSource *source, *m_sourceListPtr) {
4108                         source->flushItemChanges();
4109                         if (needResults) {
4110                             source->finishItemChanges();
4111                         }
4112                         displaySourceProgress(*source, SyncSourceEvent(), false);
4113                     }
4114                 }
4115
4116                 // send data to remote
4117
4118                 SharedKey sessionKey = m_engine.OpenSessionKey(session);
4119                 if (m_serverMode) {
4120                     m_agent->setURL("");
4121                 } else {
4122                     // use OpenSessionKey() and GetValue() to retrieve "connectURI"
4123                     // and "contenttype" to be used to send data to the server
4124                     s = m_engine.GetStrValue(sessionKey,
4125                                              "connectURI");
4126                     m_agent->setURL(s);
4127                 }
4128                 s = m_engine.GetStrValue(sessionKey,
4129                                          "contenttype");
4130                 m_agent->setContentType(s);
4131                 sessionKey.reset();
4132
4133                 sendStart = resendStart = Timespec::monotonic();
4134                 requestNum ++;
4135                 // use GetSyncMLBuffer()/RetSyncMLBuffer() to access the data to be
4136                 // sent or have it copied into caller's buffer using
4137                 // ReadSyncMLBuffer(), then send it to the server
4138                 sendBuffer = m_engine.GetSyncMLBuffer(session, true);
4139                 m_agent->send(sendBuffer.get(), sendBuffer.size());
4140                 stepCmd = sysync::STEPCMD_SENTDATA; // we have sent the data
4141                 break;
4142             }
4143             case sysync::STEPCMD_RESENDDATA: {
4144                 SE_LOG_INFO(NULL, "resend previous message, retry #%d", m_retries);
4145                 resendStart = Timespec::monotonic();
4146                 /* We are resending previous message, just read from the
4147                  * previous buffer */
4148                 m_agent->send(sendBuffer.get(), sendBuffer.size());
4149                 stepCmd = sysync::STEPCMD_SENTDATA; // we have sent the data
4150                 break;
4151             }
4152             case sysync::STEPCMD_NEEDDATA:
4153                 if (!sendStart) {
4154                     // no message sent yet, record start of wait for data
4155                     sendStart = Timespec::monotonic();
4156                 }
4157                 switch (m_agent->wait()) {
4158                 case TransportAgent::ACTIVE:
4159                     // Still sending the data?! Don't change anything,
4160                     // skip SessionStep() above.
4161                     break;
4162
4163                 case TransportAgent::TIME_OUT: {
4164                     double duration = (Timespec::monotonic() - sendStart).duration();
4165                     // HTTP SyncML servers cannot resend a HTTP POST
4166                     // reply.  Other server transports could in theory
4167                     // resend, but don't have the necessary D-Bus APIs
4168                     // (MB #6370).
4169                     // Same if() as below for FAILED.
4170                     if (m_serverMode ||
4171                         !m_retryInterval || duration + 0.1 >= m_retryDuration || requestNum == 1) {
4172                         SE_LOG_INFO(NULL,
4173                                     "Transport giving up after %d retries and %ld:%02ldmin",
4174                                     m_retries,
4175                                     (long)duration / 60,
4176                                     (long)duration % 60);
4177                         SE_THROW_EXCEPTION(TransportException, "timeout, retry period exceeded");
4178                     }else {
4179                         // Timeout must have been due to retryInterval having passed, resend
4180                         // immediately.
4181                         m_retries ++;
4182                         stepCmd = sysync::STEPCMD_RESENDDATA;
4183                     }
4184                     break;
4185                     }
4186                 case TransportAgent::GOT_REPLY: {
4187                     const char *reply;
4188                     size_t replylen;
4189                     string contentType;
4190                     m_agent->getReply(reply, replylen, contentType);
4191
4192                     // sanity check for reply: if known at all, it must be either XML or WBXML
4193                     if (contentType.empty() ||
4194                         contentType.find("application/vnd.syncml+wbxml") != contentType.npos ||
4195                         contentType.find("application/vnd.syncml+xml") != contentType.npos) {
4196                         // put answer received earlier into SyncML engine's buffer
4197                         m_retries = 0;
4198                         sendBuffer.reset();
4199                         m_engine.WriteSyncMLBuffer(session,
4200                                                    reply,
4201                                                    replylen);
4202                         if (m_serverMode) {
4203                             SharedKey sessionKey = m_engine.OpenSessionKey(session);
4204                             m_engine.SetStrValue(sessionKey,
4205                                                  "contenttype",
4206                                                  contentType);
4207                         }
4208                         stepCmd = sysync::STEPCMD_GOTDATA; // we have received response data
4209                         break;
4210                     } else {
4211                         SE_LOG_DEBUG(NULL, "unexpected content type '%s' in reply, %d bytes:\n%.*s",
4212                                      contentType.c_str(), (int)replylen, (int)replylen, reply);
4213                         SE_LOG_ERROR(NULL, "unexpected reply from peer; might be a temporary problem, try again later");
4214                       } //fall through to network failure case
4215                 }
4216                 /* If this is a network error, it usually failed quickly, retry
4217                  * immediately has likely no effect. Manually sleep here to wait a while
4218                  * before retry. Sleep time will be calculated so that the
4219                  * message sending interval equals m_retryInterval.
4220                  */
4221                 case TransportAgent::FAILED: {
4222                     // Send might have failed because of abort or
4223                     // suspend request.
4224                     if (flags.isSuspended()) {
4225                         SE_LOG_DEBUG(NULL, "suspending after TransportAgent::FAILED as requested by user");
4226                         stepCmd = sysync::STEPCMD_SUSPEND;
4227                         break;
4228                     } else if (flags.isAborted()) {
4229                         SE_LOG_DEBUG(NULL, "aborting after TransportAgent::FAILED as requested by user");
4230                         stepCmd = sysync::STEPCMD_ABORT;
4231                         break;
4232                     }
4233
4234                     Timespec curTime = Timespec::monotonic();
4235                     double duration = (curTime - sendStart).duration();
4236                     double resendDelay = m_retryInterval - (curTime - resendStart).duration();
4237                     if (resendDelay < 0) {
4238                         resendDelay = 0;
4239                     }
4240                     // Similar if() as above for TIME_OUT. In addition, we must check that
4241                     // the next resend won't happen after the retryDuration, because then
4242                     // we might as well give up now immediately. Include some fuzz factor
4243                     // in case we woke up slightly too early.
4244                     if (m_serverMode ||
4245                         !m_retryInterval || duration + resendDelay + 0.1 >= m_retryDuration || requestNum == 1) {
4246                         SE_LOG_INFO(NULL,
4247                                     "Transport giving up after %d retries and %ld:%02ldmin",
4248                                     m_retries,
4249                                     (long)duration / 60,
4250                                     (long)duration % 60);
4251                         SE_THROW_EXCEPTION(TransportException, "transport failed, retry period exceeded");
4252                     } else {
4253                         // Resend after having ensured that the retryInterval is over.
4254                         if (resendDelay > 0) {
4255                             if (Sleep(resendDelay) > 0) {
4256                                 if (flags.isSuspended()) {
4257                                     SE_LOG_DEBUG(NULL, "suspending after premature exit from sleep() caused by user suspend");
4258                                     stepCmd = sysync::STEPCMD_SUSPEND;
4259                                 } else {
4260                                     SE_LOG_DEBUG(NULL, "aborting after premature exit from sleep() caused by user abort");
4261                                     stepCmd = sysync::STEPCMD_ABORT;
4262                                 }
4263                                 break;
4264                             }
4265                         }
4266
4267                         m_retries ++;
4268                         stepCmd = sysync::STEPCMD_RESENDDATA;
4269                     }
4270                     break;
4271                 }
4272                 case TransportAgent::CANCELED:
4273                     // Send might have failed because of abort or
4274                     // suspend request.
4275                     if (flags.isSuspended()) {
4276                         SE_LOG_DEBUG(NULL, "suspending after TransportAgent::CANCELED as requested by user");
4277                         stepCmd = sysync::STEPCMD_SUSPEND;
4278                         break;
4279                     } else if (flags.isAborted()) {
4280                         SE_LOG_DEBUG(NULL, "aborting after TransportAgent::CANCELED as requested by user");
4281                         stepCmd = sysync::STEPCMD_ABORT;
4282                         break;
4283                     }
4284                     // not sure exactly why it is canceled
4285                     SE_THROW_EXCEPTION_STATUS(BadSynthesisResult,
4286                                               "transport canceled",
4287                                               sysync::LOCERR_USERABORT);
4288                     break;
4289                 default:
4290                     stepCmd = sysync::STEPCMD_TRANSPFAIL; // communication with server failed
4291                     break;
4292                 }
4293             }
4294
4295             // Don't tell engine to abort when it already did.
4296             if (aborting && stepCmd == sysync::STEPCMD_ABORT) {
4297                 stepCmd = sysync::STEPCMD_DONE;
4298             }
4299
4300             previousStepCmd = stepCmd;
4301             // loop until session done or aborted with error
4302         } catch (const BadSynthesisResult &result) {
4303             if (result.result() == sysync::LOCERR_USERABORT && aborting) {
4304                 SE_LOG_INFO(NULL, "Aborted as requested.");
4305                 stepCmd = sysync::STEPCMD_DONE;
4306             } else if (result.result() == sysync::LOCERR_USERSUSPEND && suspending) {
4307                 SE_LOG_INFO(NULL, "Suspended as requested.");
4308                 stepCmd = sysync::STEPCMD_DONE;
4309             } else if (aborting) {
4310                 // aborting very early can lead to results different from LOCERR_USERABORT
4311                 // => don't treat this as error
4312                 SE_LOG_INFO(NULL, "Aborted with unexpected result (%d)",
4313                             static_cast<int>(result.result()));
4314                 stepCmd = sysync::STEPCMD_DONE;
4315             } else {
4316                 Exception::handle(&status);
4317                 SE_LOG_DEBUG(NULL, "aborting after catching fatal error");
4318                 // Don't tell engine to abort when it already did.
4319                 stepCmd = aborting ? sysync::STEPCMD_DONE : sysync::STEPCMD_ABORT;
4320             }
4321         } catch (...) {
4322             Exception::handle(&status);
4323             SE_LOG_DEBUG(NULL, "aborting after catching fatal error");
4324             // Don't tell engine to abort when it already did.
4325             stepCmd = aborting ? sysync::STEPCMD_DONE : sysync::STEPCMD_ABORT;
4326         }
4327     } while (stepCmd != sysync::STEPCMD_DONE && stepCmd != sysync::STEPCMD_ERROR);
4328
4329     // If we get here without error, then close down connection normally.
4330     // Otherwise destruct the agent without further communication.
4331     if (!status && !flags.isAborted()) {
4332         try {
4333             m_agent->shutdown();
4334             // TODO: implement timeout for peers which fail to respond
4335             while (!flags.isAborted() &&
4336                    m_agent->wait(true) == TransportAgent::ACTIVE) {
4337                 // TODO: allow aborting the sync here
4338             }
4339         } catch (...) {
4340             status = handleException();
4341         }
4342     }
4343
4344     // Let session shut down before auto-destructing anything else
4345     // (like our signal blocker). This may take a while, because it
4346     // may involve shutting down the helper background thread which
4347     // opened our local datastore.
4348     SE_LOG_DEBUG(NULL, "closing session");
4349     sessionSentinel.reset();
4350     session.reset();
4351     SE_LOG_DEBUG(NULL, "session closed");
4352
4353     return status;
4354 }
4355
4356 string SyncContext::getSynthesisDatadir()
4357 {
4358     if (isEphemeral() && m_sourceListPtr) {
4359         return m_sourceListPtr->getLogdir() + "/synthesis";
4360     } else if (m_localSync && !m_serverMode) {
4361         return m_localClientRootPath + "/.synthesis";
4362     } else {
4363         return getRootPath() + "/.synthesis";
4364     }
4365 }
4366
4367 SyncMLStatus SyncContext::handleException()
4368 {
4369     SyncMLStatus res = Exception::handle();
4370     return res;
4371 }
4372
4373 void SyncContext::status()
4374 {
4375     checkConfig("status check");
4376
4377     SourceList sourceList(*this, false);
4378     initSources(sourceList);
4379     PasswordConfigProperty::checkPasswords(getUserInterfaceNonNull(), *this,
4380                                            // Don't need sync passwords.
4381                                            PasswordConfigProperty::CHECK_PASSWORD_ALL & ~PasswordConfigProperty::CHECK_PASSWORD_SYNC,
4382                                            sourceList.getSourceNames());
4383     BOOST_FOREACH(SyncSource *source, sourceList) {
4384         source->open();
4385     }
4386
4387     SyncReport changes;
4388     checkSourceChanges(sourceList, changes);
4389
4390     stringstream out;
4391     changes.prettyPrint(out,
4392                         SyncReport::WITHOUT_SERVER|
4393                         SyncReport::WITHOUT_CONFLICTS|
4394                         SyncReport::WITHOUT_REJECTS|
4395                         SyncReport::WITH_TOTAL);
4396     SE_LOG_INFO(NULL, "Local item changes:\n%s",
4397                 out.str().c_str());
4398
4399     sourceList.accessSession(getLogDir());
4400     Logger::instance().setLevel(Logger::INFO);
4401     string prevLogdir = sourceList.getPrevLogdir();
4402     bool found = access(prevLogdir.c_str(), R_OK|X_OK) == 0;
4403
4404     if (found) {
4405         if (!m_quiet && getPrintChanges()) {
4406             try {
4407                 sourceList.setPath(prevLogdir);
4408                 sourceList.dumpDatabases("current", NULL);
4409                 sourceList.dumpLocalChanges("", "after", "current", "");
4410             } catch(...) {
4411                 Exception::handle();
4412             }
4413         }
4414     } else {
4415         SE_LOG_SHOW(NULL, "Previous log directory not found.");
4416         if (getLogDir().empty()) {
4417             SE_LOG_SHOW(NULL, "Enable the 'logdir' option and synchronize to use this feature.");
4418         }
4419     }
4420 }
4421
4422 void SyncContext::checkStatus(SyncReport &report)
4423 {
4424     checkConfig("status check");
4425
4426     SourceList sourceList(*this, false);
4427     initSources(sourceList);
4428     PasswordConfigProperty::checkPasswords(getUserInterfaceNonNull(), *this,
4429                                            // Don't need sync passwords.
4430                                            PasswordConfigProperty::CHECK_PASSWORD_ALL & ~PasswordConfigProperty::CHECK_PASSWORD_SYNC,
4431                                            sourceList.getSourceNames());
4432     BOOST_FOREACH(SyncSource *source, sourceList) {
4433         source->open();
4434     }
4435
4436     checkSourceChanges(sourceList, report);
4437 }
4438
4439 static void logRestoreReport(const SyncReport &report, bool dryrun)
4440 {
4441     if (!report.empty()) {
4442         stringstream out;
4443         report.prettyPrint(out, SyncReport::WITHOUT_SERVER|SyncReport::WITHOUT_CONFLICTS|SyncReport::WITH_TOTAL);
4444         SE_LOG_INFO(NULL, "Item changes %s applied locally during restore:\n%s",
4445                     dryrun ? "to be" : "that were",
4446                     out.str().c_str());
4447         SE_LOG_INFO(NULL, "The same incremental changes will be applied to the server during the next sync.");
4448         SE_LOG_INFO(NULL, "Use -sync refresh-from-client to replace the complete data on the server.");
4449     }
4450 }
4451
4452 void SyncContext::checkSourceChanges(SourceList &sourceList, SyncReport &changes)
4453 {
4454     changes.setStart(time(NULL));
4455     BOOST_FOREACH(SyncSource *source, sourceList) {
4456         SyncSourceReport local;
4457         if (source->getOperations().m_checkStatus) {
4458             source->getOperations().m_checkStatus(local);
4459         } else {
4460             // no information available
4461             local.setItemStat(SyncSourceReport::ITEM_LOCAL,
4462                               SyncSourceReport::ITEM_ADDED,
4463                               SyncSourceReport::ITEM_TOTAL,
4464                               -1);
4465             local.setItemStat(SyncSourceReport::ITEM_LOCAL,
4466                               SyncSourceReport::ITEM_UPDATED,
4467                               SyncSourceReport::ITEM_TOTAL,
4468                               -1);
4469             local.setItemStat(SyncSourceReport::ITEM_LOCAL,
4470                               SyncSourceReport::ITEM_REMOVED,
4471                               SyncSourceReport::ITEM_TOTAL,
4472                               -1);
4473             local.setItemStat(SyncSourceReport::ITEM_LOCAL,
4474                               SyncSourceReport::ITEM_ANY,
4475                               SyncSourceReport::ITEM_TOTAL,
4476                               -1);
4477         }
4478         changes.addSyncSourceReport(source->getName(), local);
4479     }
4480     changes.setEnd(time(NULL));
4481 }
4482
4483 bool SyncContext::checkForScriptAbort(SharedSession session)
4484 {
4485     try {
4486         SharedKey sessionKey = m_engine.OpenSessionKey(session);
4487         SharedKey contextKey = m_engine.OpenKeyByPath(sessionKey, "/sessionvars");
4488         bool abort = m_engine.GetInt32Value(contextKey, "delayedabort");
4489         return abort;
4490     } catch (NoSuchKey) {
4491         // this is necessary because the session might already have
4492         // been closed, which removes the variable
4493         return false;
4494     } catch (BadSynthesisResult) {
4495         return false;
4496     }
4497 }
4498
4499 void SyncContext::restore(const string &dirname, RestoreDatabase database)
4500 {
4501     checkConfig("restore");
4502
4503     SourceList sourceList(*this, false);
4504     sourceList.accessSession(dirname.c_str());
4505     Logger::instance().setLevel(Logger::INFO);
4506     initSources(sourceList);
4507     PasswordConfigProperty::checkPasswords(getUserInterfaceNonNull(), *this,
4508                                            // Don't need sync passwords.
4509                                            PasswordConfigProperty::CHECK_PASSWORD_ALL & ~PasswordConfigProperty::CHECK_PASSWORD_SYNC,
4510                                            sourceList.getSourceNames());
4511     string datadump = database == DATABASE_BEFORE_SYNC ? "before" : "after";
4512
4513     BOOST_FOREACH(SyncSource *source, sourceList) {
4514         // fake a source alert event
4515         displaySourceProgress(*source, SyncSourceEvent(sysync::PEV_ALERTED, -1, 0, 0), true);
4516         source->open();
4517     }
4518
4519     if (!m_quiet && getPrintChanges()) {
4520         sourceList.dumpDatabases("current", NULL);
4521         sourceList.dumpLocalChanges(dirname, "current", datadump, "",
4522                                     "Data changes to be applied locally during restore:\n",
4523                                     "CLIENT_TEST_LEFT_NAME='current data' "
4524                                     "CLIENT_TEST_REMOVED='after restore' "
4525                                     "CLIENT_TEST_REMOVED='to be removed' "
4526                                     "CLIENT_TEST_ADDED='to be added'");
4527     }
4528
4529     SyncReport report;
4530     try {
4531         BOOST_FOREACH(SyncSource *source, sourceList) {
4532             SyncSourceReport sourcereport;
4533             try {
4534                 displaySourceProgress(*source, SyncSourceEvent(sysync::PEV_SYNCSTART, 0, 0, 0), true);
4535                 sourceList.restoreDatabase(*source,
4536                                            datadump,
4537                                            m_dryrun,
4538                                            sourcereport);
4539                 displaySourceProgress(*source, SyncSourceEvent(sysync::PEV_SYNCEND, 0, 0, 0), true);
4540                 report.addSyncSourceReport(source->getName(), sourcereport);
4541             } catch (...) {
4542                 sourcereport.recordStatus(STATUS_FATAL);
4543                 report.addSyncSourceReport(source->getName(), sourcereport);
4544                 throw;
4545             }
4546         }
4547     } catch (...) {
4548         logRestoreReport(report, m_dryrun);
4549         throw;
4550     }
4551     logRestoreReport(report, m_dryrun);
4552 }
4553
4554 void SyncContext::getSessions(vector<string> &dirs)
4555 {
4556     LogDir::create(*this)->previousLogdirs(dirs);
4557 }
4558
4559 string SyncContext::readSessionInfo(const string &dir, SyncReport &report)
4560 {
4561     boost::shared_ptr<LogDir> logging(LogDir::create(*this));
4562     logging->openLogdir(dir);
4563     logging->readReport(report);
4564     return logging->getPeerNameFromLogdir(dir);
4565 }
4566
4567 #ifdef ENABLE_UNIT_TESTS
4568 /**
4569  * This class works LogDirTest as scratch directory.
4570  * LogDirTest/[file_event|file_contact]_[one|two|empty] contain different
4571  * sets of items for use in a FileSyncSource.
4572  *
4573  * With that setup and a fake SyncContext it is possible to simulate
4574  * sessions and test the resulting logdirs.
4575  */
4576 class LogDirTest : public CppUnit::TestFixture
4577 {
4578     class LogContext : public SyncContext, public Logger
4579     {
4580     public:
4581         LogContext() :
4582             SyncContext("nosuchconfig@nosuchcontext")
4583         {}
4584
4585         ostringstream m_out;
4586
4587         /** capture output produced while test ran */
4588         void messagev(const MessageOptions &options,
4589                       const char *format,
4590                       va_list args)
4591         {
4592             std::string str = StringPrintfV(format, args);
4593             m_out << '[' << levelToStr(options.m_level) << ']' << str;
4594             if (!boost::ends_with(str, "\n")) {
4595                 m_out << std::endl;
4596             }
4597         }
4598     };
4599
4600     boost::shared_ptr<LogContext> m_logContext;
4601
4602 public:
4603     LogDirTest() :
4604         m_maxLogDirs(10)
4605     {
4606     }
4607
4608     ~LogDirTest() {
4609     }
4610
4611     void setUp() {
4612         static const char *vcard_1 =
4613             "BEGIN:VCARD\n"
4614             "VERSION:2.1\n"
4615             "TITLE:tester\n"
4616             "FN:John Doe\n"
4617             "N:Doe;John;;;\n"
4618             "X-MOZILLA-HTML:FALSE\n"
4619             "TEL;TYPE=WORK;TYPE=VOICE:business 1\n"
4620             "EMAIL:john.doe@work.com\n"
4621             "X-AIM:AIM JOHN\n"
4622             "END:VCARD\n";
4623         static const char *vcard_2 =
4624             "BEGIN:VCARD\n"
4625             "VERSION:2.1\n"
4626             "TITLE:developer\n"
4627             "FN:John Doe\n"
4628             "N:Doe;John;;;\n"
4629             "X-MOZILLA-HTML:TRUE\n"
4630             "BDAY:2006-01-08\n"
4631             "END:VCARD\n";
4632         static const char *ical_1 =
4633             "BEGIN:VCALENDAR\n"
4634             "PRODID:-//Ximian//NONSGML Evolution Calendar//EN\n"
4635             "VERSION:2.0\n"
4636             "METHOD:PUBLISH\n"
4637             "BEGIN:VEVENT\n"
4638             "SUMMARY:phone meeting\n"
4639             "DTEND:20060406T163000Z\n"
4640             "DTSTART:20060406T160000Z\n"
4641             "UID:1234567890!@#$%^&*()<>@dummy\n"
4642             "DTSTAMP:20060406T211449Z\n"
4643             "LAST-MODIFIED:20060409T213201\n"
4644             "CREATED:20060409T213201\n"
4645             "LOCATION:calling from home\n"
4646             "DESCRIPTION:let's talk\n"
4647             "CLASS:PUBLIC\n"
4648             "TRANSP:OPAQUE\n"
4649             "SEQUENCE:1\n"
4650             "BEGIN:VALARM\n"
4651             "DESCRIPTION:alarm\n"
4652             "ACTION:DISPLAY\n"
4653             "TRIGGER;VALUE=DURATION;RELATED=START:-PT15M\n"
4654             "END:VALARM\n"
4655             "END:VEVENT\n"
4656             "END:VCALENDAR\n";
4657         static const char *ical_2 =
4658             "BEGIN:VCALENDAR\n"
4659             "PRODID:-//Ximian//NONSGML Evolution Calendar//EN\n"
4660             "VERSION:2.0\n"
4661             "METHOD:PUBLISH\n"
4662             "BEGIN:VEVENT\n"
4663             "SUMMARY:phone meeting\n"
4664             "DTEND:20060406T163000Z\n"
4665             "DTSTART:20060406T160000Z\n"
4666             "UID:1234567890!@#$%^&*()<>@dummy\n"
4667             "DTSTAMP:20060406T211449Z\n"
4668             "LAST-MODIFIED:20060409T213201\n"
4669             "CREATED:20060409T213201\n"
4670             "LOCATION:my office\n"
4671             "CATEGORIES:WORK\n"
4672             "DESCRIPTION:what the heck\\, let's even shout a bit\n"
4673             "CLASS:PUBLIC\n"
4674             "TRANSP:OPAQUE\n"
4675             "SEQUENCE:1\n"
4676             "END:VEVENT\n"
4677             "END:VCALENDAR\n";
4678         rm_r("LogDirTest");
4679         dump("file_event.one", "1", ical_1);
4680         dump("file_event.two", "1", ical_1);
4681         dump("file_event.two", "2", ical_2);
4682         mkdir_p(getLogData() + "/file_event.empty");
4683         dump("file_contact.one", "1", vcard_1);
4684         dump("file_contact.two", "1", vcard_1);
4685         dump("file_contact.two", "2", vcard_2);
4686         mkdir_p(getLogData() + "/file_contact.empty");
4687
4688         mkdir_p(getLogDir());
4689         m_maxLogDirs = 0;
4690
4691         // Suppress output by redirecting into LogContext::m_out.
4692         // It's not tested at the moment.
4693         m_logContext.reset(new LogContext);
4694         Logger::addLogger(m_logContext);
4695     }
4696
4697     void tearDown() {
4698         Logger::removeLogger(m_logContext.get());
4699         m_logContext.reset();
4700     }
4701
4702 private:
4703
4704     string getLogData() { return "LogDirTest/data"; }
4705     virtual InitStateString getLogDir() const { return "LogDirTest/cache/syncevolution"; }
4706     int m_maxLogDirs;
4707
4708     void dump(const char *dir, const char *file, const char *data) {
4709         string name = getLogData();
4710         name += "/";
4711         name += dir;
4712         mkdir_p(name);
4713         name += "/";
4714         name += file;
4715         ofstream out(name.c_str());
4716         out << data;
4717     }
4718
4719     CPPUNIT_TEST_SUITE(LogDirTest);
4720     CPPUNIT_TEST(testQuickCompare);
4721     CPPUNIT_TEST(testSessionNoChanges);
4722     CPPUNIT_TEST(testSessionChanges);
4723     CPPUNIT_TEST(testMultipleSessions);
4724     CPPUNIT_TEST(testExpire);
4725     CPPUNIT_TEST_SUITE_END();
4726
4727     /**
4728      * Simulate a session involving one or more sources.
4729      *
4730      * @param changeServer   pretend that peer got changed
4731      * @param status         result of session
4732      * @param varargs        sourcename ("file_event"),
4733      *                       statebefore (NULL for no dump, or suffix like "_one"),
4734      *                       stateafter (NULL for same as before), ..., NULL
4735      * @return logdir created for the session
4736      */
4737     string session(bool changeServer, SyncMLStatus status, ...) {
4738         Logger::Level level = Logger::instance().getLevel();
4739         SourceList list(*m_logContext, true);
4740         list.setLogLevel(SourceList::LOGGING_QUIET);
4741         SyncReport report;
4742         list.startSession("", m_maxLogDirs, 0, &report);
4743         va_list ap;
4744         va_start(ap, status);
4745         while (true) {
4746             const char *sourcename = va_arg(ap, const char *);
4747             if (!sourcename) {
4748                 break;
4749             }
4750             const char *type = NULL;
4751             if (!strcmp(sourcename, "file_event")) {
4752                 type = "file:text/calendar:2.0";
4753             } else if (!strcmp(sourcename, "file_contact")) {
4754                 type = "file:text/vcard:3.0";
4755             }
4756             CPPUNIT_ASSERT(type);
4757             string datadir = getLogData() + "/";
4758             cxxptr<SyncSource> source(SyncSource::createTestingSource(sourcename, type, true,
4759                                                                       (string("file://") + datadir).c_str()));
4760             datadir += sourcename;
4761             datadir += "_1";
4762             source->open();
4763             if (changeServer) {
4764                 // fake one added item on server
4765                 source->setItemStat(SyncSourceReport::ITEM_REMOTE,
4766                                     SyncSourceReport::ITEM_ADDED,
4767                                     SyncSourceReport::ITEM_TOTAL,
4768                                     1);
4769             }
4770             list.addSource(source);
4771             const char *before = va_arg(ap, const char *);
4772             const char *after = va_arg(ap, const char *);
4773             if (before) {
4774                 // do a "before" dump after directing the source towards the desired data
4775                 rm_r(datadir);
4776                 CPPUNIT_ASSERT_EQUAL(0, symlink((string(sourcename) + before).c_str(),
4777                                                 datadir.c_str()));
4778                 list.syncPrepare(sourcename);
4779                 if (after) {
4780                     rm_r(datadir);
4781                     CPPUNIT_ASSERT_EQUAL(0, symlink((string(sourcename) + after).c_str(),
4782                                                     datadir.c_str()));
4783                 }
4784             }
4785         }
4786         list.syncDone(status, &report);
4787
4788         Logger::instance().setLevel(level);
4789         return list.getLogdir();
4790     }
4791
4792     typedef vector<string> Sessions_t;
4793     // full paths to all sessions, sorted
4794     Sessions_t listSessions() {
4795         Sessions_t sessions;
4796         string logdir = getLogDir();
4797         ReadDir dirs(logdir);
4798         BOOST_FOREACH(const string &dir, dirs) {
4799             sessions.push_back(logdir + "/" + dir);
4800         }
4801         sort(sessions.begin(), sessions.end());
4802         return sessions;
4803     }
4804
4805     void testQuickCompare() {
4806         // identical dirs => identical files
4807         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_event",
4808                                                      getLogData(), "empty",
4809                                                      getLogData(), "empty"));
4810         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_event",
4811                                                      getLogData(), "one",
4812                                                      getLogData(), "one"));
4813         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_event",
4814                                                      getLogData(), "two",
4815                                                      getLogData(), "two"));
4816         // some files shared
4817         CPPUNIT_ASSERT(!system("cp -l -r LogDirTest/data/file_event.two LogDirTest/data/file_event.copy && rm LogDirTest/data/file_event.copy/2"));
4818         CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_event",
4819                                                     getLogData(), "two",
4820                                                     getLogData(), "copy"));
4821         CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_event",
4822                                                     getLogData(), "copy",
4823                                                     getLogData(), "one"));
4824     }
4825
4826     void testSessionNoChanges() {
4827         ScopedEnvChange config("XDG_CONFIG_HOME", "LogDirTest/config");
4828         ScopedEnvChange cache("XDG_CACHE_HOME", "LogDirTest/cache");
4829
4830         // simple session with no changes
4831         string dir = session(false, STATUS_OK, "file_event", ".one", ".one", (char *)0);
4832         Sessions_t sessions = listSessions();
4833         CPPUNIT_ASSERT_EQUAL((size_t)1, sessions.size());
4834         CPPUNIT_ASSERT_EQUAL(dir, sessions[0]);
4835         IniFileConfigNode status(dir, "status.ini", true);
4836         CPPUNIT_ASSERT(status.exists());
4837         CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__event-backup-before").get());
4838         CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__event-backup-after").get());
4839         CPPUNIT_ASSERT_EQUAL(string("200"), status.readProperty("status").get());
4840         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_event",
4841                                                      dir, "before",
4842                                                      dir, "after"));
4843     }
4844
4845     void testSessionChanges() {
4846         ScopedEnvChange config("XDG_CONFIG_HOME", "LogDirTest/config");
4847         ScopedEnvChange cache("XDG_CACHE_HOME", "LogDirTest/cache");
4848
4849         // session with local changes
4850         string dir = session(false, STATUS_OK, "file_event", ".one", ".two", (char *)0);
4851         Sessions_t sessions = listSessions();
4852         CPPUNIT_ASSERT_EQUAL((size_t)1, sessions.size());
4853         CPPUNIT_ASSERT_EQUAL(dir, sessions[0]);
4854         IniFileConfigNode status(dir, "status.ini", true);
4855         CPPUNIT_ASSERT(status.exists());
4856         CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__event-backup-before").get());
4857         CPPUNIT_ASSERT_EQUAL(string("2"), status.readProperty("source-file__event-backup-after").get());
4858         CPPUNIT_ASSERT_EQUAL(string("200"), status.readProperty("status").get());
4859         CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_event",
4860                                                     dir, "before",
4861                                                     dir, "after"));
4862     }
4863
4864     void testMultipleSessions() {
4865         ScopedEnvChange config("XDG_CONFIG_HOME", "LogDirTest/config");
4866         ScopedEnvChange cache("XDG_CACHE_HOME", "LogDirTest/cache");
4867
4868         // two sessions, starting with 1 item, adding 1 during the sync, then
4869         // removing it again during the second
4870         string dir = session(false, STATUS_OK,
4871                              "file_event", ".one", ".two",
4872                              "file_contact", ".one", ".two",
4873                              (char *)0);
4874         {
4875             Sessions_t sessions = listSessions();
4876             CPPUNIT_ASSERT_EQUAL((size_t)1, sessions.size());
4877             CPPUNIT_ASSERT_EQUAL(dir, sessions[0]);
4878             IniFileConfigNode status(dir, "status.ini", true);
4879             CPPUNIT_ASSERT(status.exists());
4880             CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__event-backup-before").get());
4881             CPPUNIT_ASSERT_EQUAL(string("2"), status.readProperty("source-file__event-backup-after").get());
4882             CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__contact-backup-before").get());
4883             CPPUNIT_ASSERT_EQUAL(string("2"), status.readProperty("source-file__contact-backup-after").get());
4884             CPPUNIT_ASSERT_EQUAL(string("200"), status.readProperty("status").get());
4885             CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_event",
4886                                                         dir, "before",
4887                                                         dir, "after"));
4888             CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_contact",
4889                                                         dir, "before",
4890                                                         dir, "after"));
4891         }
4892
4893         string seconddir = session(false, STATUS_OK,
4894                                    "file_event", ".two", ".one",
4895                                    "file_contact", ".two", ".one",
4896                                    (char *)0);
4897         {
4898             Sessions_t sessions = listSessions();
4899             CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
4900             CPPUNIT_ASSERT_EQUAL(dir, sessions[0]);
4901             CPPUNIT_ASSERT_EQUAL(seconddir, sessions[1]);
4902             IniFileConfigNode status(seconddir, "status.ini", true);
4903             CPPUNIT_ASSERT(status.exists());
4904             CPPUNIT_ASSERT_EQUAL(string("2"), status.readProperty("source-file__event-backup-before").get());
4905             CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__event-backup-after").get());
4906             CPPUNIT_ASSERT_EQUAL(string("2"), status.readProperty("source-file__contact-backup-before").get());
4907             CPPUNIT_ASSERT_EQUAL(string("1"), status.readProperty("source-file__contact-backup-after").get());
4908             CPPUNIT_ASSERT_EQUAL(string("200"), status.readProperty("status").get());
4909             CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_event",
4910                                                         seconddir, "before",
4911                                                         seconddir, "after"));
4912             CPPUNIT_ASSERT(LogDir::haveDifferentContent("file_contact",
4913                                                         seconddir, "before",
4914                                                         seconddir, "after"));
4915         }
4916
4917         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_event",
4918                                                      dir, "after",
4919                                                      seconddir, "before"));
4920         CPPUNIT_ASSERT(!LogDir::haveDifferentContent("file_contact",
4921                                                      dir, "after",
4922                                                      seconddir, "before"));
4923     }
4924
4925     void testExpire() {
4926         ScopedEnvChange config("XDG_CONFIG_HOME", "LogDirTest/config");
4927         ScopedEnvChange cache("XDG_CACHE_HOME", "LogDirTest/cache");
4928
4929         string dirs[5];
4930         Sessions_t sessions;
4931
4932         m_maxLogDirs = 1;
4933
4934         // The latest session always must be preserved, even if it
4935         // is normally considered less important (no error in this case).
4936         dirs[0] = session(false, STATUS_FATAL, (char *)0);
4937         dirs[0] = session(false, STATUS_OK, (char *)0);
4938         sessions = listSessions();
4939         CPPUNIT_ASSERT_EQUAL((size_t)1, sessions.size());
4940         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4941
4942         // all things being equal, then expire the oldest session,
4943         // leaving us with two here
4944         m_maxLogDirs = 2;
4945         dirs[0] = session(false, STATUS_OK, (char *)0);
4946         dirs[1] = session(false, STATUS_OK, (char *)0);
4947         sessions = listSessions();
4948         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
4949         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4950         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
4951
4952         // When syncing first file_event, then file_contact, both sessions
4953         // must be preserved despite m_maxLogDirs = 1, otherwise
4954         // we would loose the only existent backup of file_event.
4955         dirs[0] = session(false, STATUS_OK, "file_event", ".two", ".one", (char *)0);
4956         dirs[1] = session(false, STATUS_OK, "file_contact", ".two", ".one", (char *)0);
4957         sessions = listSessions();
4958         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
4959         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4960         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
4961
4962         // after synchronizing both, we can expire both the old sessions
4963         m_maxLogDirs = 1;
4964         dirs[0] = session(false, STATUS_OK,
4965                           "file_event", ".two", ".one",
4966                           "file_contact", ".two", ".one",
4967                           (char *)0);
4968         sessions = listSessions();
4969         CPPUNIT_ASSERT_EQUAL((size_t)1, sessions.size());
4970         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4971
4972         // when doing multiple failed syncs without dumps, keep the sessions
4973         // which have database dumps
4974         m_maxLogDirs = 2;
4975         dirs[1] = session(false, STATUS_FATAL, (char *)0);
4976         dirs[1] = session(false, STATUS_FATAL, (char *)0);
4977         sessions = listSessions();
4978         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
4979         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4980         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
4981
4982         // when doing syncs which don't change data, keep the sessions which
4983         // did change something: keep oldest backup because it created the
4984         // backups for the first time
4985         dirs[1] = session(false, STATUS_OK,
4986                           "file_event", ".one", ".one",
4987                           "file_contact", ".one", ".one",
4988                           (char *)0);
4989         dirs[1] = session(false, STATUS_OK,
4990                           "file_event", ".one", ".one",
4991                           "file_contact", ".one", ".one",
4992                           (char *)0);
4993         sessions = listSessions();
4994         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
4995         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
4996         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
4997
4998         // when making a change in each sync, we end up with the two
4999         // most recent sessions eventually: first change server,
5000         // then local
5001         dirs[1] = session(true, STATUS_OK,
5002                           "file_event", ".one", ".one",
5003                           "file_contact", ".one", ".one",
5004                           (char *)0);
5005         sessions = listSessions();
5006         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
5007         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
5008         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
5009         dirs[0] = dirs[1];
5010         dirs[1] = session(false, STATUS_OK,
5011                           "file_event", ".one", ".two",
5012                           "file_contact", ".one", ".two",
5013                           (char *)0);
5014         sessions = listSessions();
5015         CPPUNIT_ASSERT_EQUAL((size_t)2, sessions.size());
5016         CPPUNIT_ASSERT_EQUAL(dirs[0], sessions[0]);
5017         CPPUNIT_ASSERT_EQUAL(dirs[1], sessions[1]);
5018     }
5019 };
5020 SYNCEVOLUTION_TEST_SUITE_REGISTRATION(LogDirTest);
5021 #endif // ENABLE_UNIT_TESTS
5022
5023 SE_END_CXX