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