Class org.syncany.tests.integration.scenarios.ManyRenamesScenarioTest

1

tests

0

failures

0

ignored

0.606s

duration

100%

successful

Tests

Test Duration Result
testManyRenames 0.606s passed

Standard error

16-2-17 8:20:30.419 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.419 | LocalTransferMa | Test worker    | INFO : testTargetExists: Target exists.
16-2-17 8:20:30.424 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.424 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.424 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.424 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.424 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.424 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.424 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.424 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.424 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.424 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.424 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.425 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.425 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.442 | hsqldb.db.HSQLD | Test worker    | INFO : Checkpoint start
16-2-17 8:20:30.443 | hsqldb.db.HSQLD | Test worker    | INFO : checkpointClose start
16-2-17 8:20:30.451 | hsqldb.db.HSQLD | Test worker    | FINE : log close size: 0
16-2-17 8:20:30.453 | hsqldb.db.HSQLD | Test worker    | INFO : checkpointClose end
16-2-17 8:20:30.454 | hsqldb.db.HSQLD | Test worker    | INFO : Checkpoint end - txts: 1
16-2-17 8:20:30.460 | DatabaseConnect | Test worker    | INFO : Found 0 tables.
16-2-17 8:20:30.460 | DatabaseConnect | Test worker    | INFO : Database has no tables. Creating tables from script.create.all.sql
16-2-17 8:20:30.460 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Tables
16-2-17 8:20:30.460 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS databaseversion ( id int NOT NULL IDENTITY, status varchar(45) NOT NULL, localtime datetime NOT NULL, client varchar(45) NOT NULL, vectorclock_serialized varchar(1024) NOT NULL, UNIQUE (vectorclock_serialized) ); 
16-2-17 8:20:30.463 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  chunk ( checksum varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (checksum), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.465 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  databaseversion_vectorclock ( databaseversion_id int NOT NULL, client varchar(45) NOT NULL, logicaltime int NOT NULL, PRIMARY KEY (databaseversion_id, client), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.467 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filecontent ( checksum varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (checksum), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.469 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filecontent_chunk ( filecontent_checksum varchar(40) NOT NULL, chunk_checksum varchar(40) NOT NULL, num int NOT NULL, PRIMARY KEY (filecontent_checksum, chunk_checksum, num), FOREIGN KEY (filecontent_checksum) REFERENCES filecontent (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (chunk_checksum) REFERENCES chunk (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.471 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filehistory ( id varchar(40) NOT NULL, databaseversion_id int NOT NULL, PRIMARY KEY (id, databaseversion_id), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.473 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  fileversion ( filehistory_id varchar(40) NOT NULL, version int NOT NULL, databaseversion_id int NOT NULL, path varchar(1024) NOT NULL, type varchar(45) NOT NULL, status varchar(45) NOT NULL, size bigint NOT NULL, lastmodified datetime NOT NULL, linktarget varchar(1024), filecontent_checksum varchar(40) DEFAULT NULL, updated datetime NOT NULL, posixperms varchar(45) DEFAULT NULL, dosattrs varchar(45) DEFAULT NULL, PRIMARY KEY (filehistory_id, version, databaseversion_id), FOREIGN KEY (filehistory_id, databaseversion_id) REFERENCES filehistory (id, databaseversion_id) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (filecontent_checksum) REFERENCES filecontent (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.475 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk ( id varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (id), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.478 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk_chunk ( multichunk_id varchar(40) NOT NULL, chunk_checksum varchar(40) NOT NULL, PRIMARY KEY (multichunk_id, chunk_checksum), FOREIGN KEY (multichunk_id) REFERENCES multichunk (id) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (chunk_checksum) REFERENCES chunk (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.479 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk_muddy ( id varchar(40) NOT NULL, machine_name varchar(255) NOT NULL, machine_version int NOT NULL, PRIMARY KEY (id) ); 
16-2-17 8:20:30.481 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  known_databases ( id int NOT NULL IDENTITY, client varchar(45) NOT NULL, filenumber int NOT NULL, UNIQUE (client, filenumber) ); 
16-2-17 8:20:30.483 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  general_settings ( key varchar(255) NOT NULL, value varchar(255) NOT NULL, PRIMARY KEY (key) ); 
16-2-17 8:20:30.485 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Non-primary indices
16-2-17 8:20:30.485 | SqlRunner       | Test worker    | INFO : SQL:   CREATE INDEX idx_databaseversion_status ON databaseversion (status); 
16-2-17 8:20:30.486 | hsqldb.db.HSQLD | Test worker    | INFO : dataFileCache open start
16-2-17 8:20:30.488 | hsqldb.db.HSQLD | Test worker    | INFO : dataFileCache open end
16-2-17 8:20:30.490 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_databaseversion_vectorclock_serialized ON databaseversion (vectorclock_serialized); 
16-2-17 8:20:30.491 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_path ON fileversion (path); 
16-2-17 8:20:30.493 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_status ON fileversion (status); 
16-2-17 8:20:30.496 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_filecontent_checksum ON fileversion (filecontent_checksum); 
16-2-17 8:20:30.498 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Views
16-2-17 8:20:30.498 | SqlRunner       | Test worker    | INFO : SQL:    CREATE VIEW databaseversion_master AS SELECT dbv.*, vc.logicaltime as client_version FROM databaseversion dbv JOIN databaseversion_vectorclock vc on dbv.id=vc.databaseversion_id and dbv.client=vc.client WHERE dbv.status='MASTER'; 
16-2-17 8:20:30.500 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master AS SELECT fv0.* FROM fileversion fv0 JOIN databaseversion dbv ON fv0.databaseversion_id=dbv.id AND dbv.status='MASTER'; 
16-2-17 8:20:30.503 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master_maxversion AS SELECT DISTINCT filehistory_id, MAX(version) version FROM fileversion_master GROUP BY filehistory_id; 
16-2-17 8:20:30.505 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master_last AS SELECT fv.* FROM fileversion_master_maxversion fvmax JOIN fileversion_master fv ON fvmax.filehistory_id=fv.filehistory_id AND fvmax.version=fv.version WHERE fv.status<>'DELETED'; 
16-2-17 8:20:30.507 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Full Views
16-2-17 8:20:30.507 | SqlRunner       | Test worker    | INFO : SQL:    create view filehistory_full as select dbv.status as databaseversion_status, dbv.localtime as databaseversion_localtime, dbv.client as databaseversion_client, dbv.vectorclock_serialized as databaseversion_vectorclock_serialized, fh.* from databaseversion dbv join filehistory fh on dbv.id=fh.databaseversion_id; 
16-2-17 8:20:30.509 | SqlRunner       | Test worker    | INFO : SQL:  create view fileversion_full as select fhf.databaseversion_status, fhf.databaseversion_localtime, fhf.databaseversion_client, fhf.databaseversion_vectorclock_serialized, fv.* from filehistory_full fhf join fileversion fv on fhf.id=fv.filehistory_id and fhf.databaseversion_id=fv.databaseversion_id; 
16-2-17 8:20:30.511 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Functions
16-2-17 8:20:30.511 | SqlRunner       | Test worker    | INFO : SQL (new delimiter): end;
16-2-17 8:20:30.511 | SqlRunner       | Test worker    | INFO : SQL:     create function substr_count(haystack varchar(255), needle varchar(255)) returns integer begin atomic declare strCount integer; declare lastIndex integer;  set strCount = 0; set lastIndex = 1;  while lastIndex <> 0 do set lastIndex = locate(needle, haystack, lastIndex);  if lastIndex <> 0 then set strCount = strCount + 1; set lastIndex = lastIndex + length(needle); end if; end while;  return strCount; end; 
16-2-17 8:20:30.513 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.513 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client A ...
16-2-17 8:20:30.513 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.513 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@357021a6) ...
16-2-17 8:20:30.514 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.514 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.514 | StatusOperation | Test worker    | INFO : Running 'Status' at client A ...
16-2-17 8:20:30.514 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.514 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.514 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@3c93ca2f) ...
16-2-17 8:20:30.515 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-A ...
16-2-17 8:20:30.515 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.515 | StatusOperation | Test worker    | FINE : - New file: A-original
16-2-17 8:20:30.515 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@2d5c6eaa) ...
16-2-17 8:20:30.515 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.516 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.516 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.516 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.516 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.516 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@3c8a5a0e) ...
16-2-17 8:20:30.516 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.516 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@58268e9e) ...
16-2-17 8:20:30.516 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.516 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-A-1487233230425] ...
16-2-17 8:20:30.516 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-A-1487233230425]
16-2-17 8:20:30.516 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-A-1487233230425] ...
16-2-17 8:20:30.517 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.517 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.517 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.517 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@7bc5657f) ...
16-2-17 8:20:30.517 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.517 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original
16-2-17 8:20:30.517 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original
16-2-17 8:20:30.518 | Indexer         | AsyncI/syncany | FINE : - Chunk new: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.519 | Indexer         | AsyncI/syncany | FINE : - +MultiChunk e1a629f47ad3db272b35655812123badde0a7bd8
16-2-17 8:20:30.519 | Indexer         | AsyncI/syncany | FINE : - Chunk > MultiChunk: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > e1a629f47ad3db272b35655812123badde0a7bd8
16-2-17 8:20:30.519 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original
16-2-17 8:20:30.519 | Indexer         | AsyncI/syncany | FINE : - /File: A-original (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.520 | Indexer         | AsyncI/syncany | FINE :    * No old file history found, starting new history (path: A-original, checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.520 | FileVersionComp | AsyncI/syncany | INFO :      - [DELETED]: Local file DIFFERS from file version, actual file is NULL, for file A-original
16-2-17 8:20:30.520 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.520 | Indexer         | AsyncI/syncany | INFO :      based on file version: null
16-2-17 8:20:30.520 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@39f415a5) ...
16-2-17 8:20:30.520 | Indexer         | AsyncI/syncany | FINE : - /MultiChunk e1a629f47ad3db272b35655812123badde0a7bd8
16-2-17 8:20:30.520 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@119f76d7) ...
16-2-17 8:20:30.520 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230517, chunks=1, multiChunks=1, fileContents=1, fileHistories=1]
16-2-17 8:20:30.520 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@37a00576) ...
16-2-17 8:20:30.520 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.521 | UpOperation     | Test worker    | INFO : Last vector clock was: ()
16-2-17 8:20:30.521 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.522 | UpOperation     | Test worker    | INFO : - Uploading multichunk e1a629f47ad3db272b35655812123badde0a7bd8 from /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/multichunk-e1a629f47ad3db272b35655812123badde0a7bd8 to RemoteFile[name=multichunk-e1a629f47ad3db272b35655812123badde0a7bd8] ...
16-2-17 8:20:30.522 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/multichunk-e1a629f47ad3db272b35655812123badde0a7bd8 -> Temp. remote file: RemoteFile[name=temp-GdQCg-multichunk-e1a629f47ad3db272b35655812123badde0a7bd8], final location: RemoteFile[name=multichunk-e1a629f47ad3db272b35655812123badde0a7bd8]
16-2-17 8:20:30.522 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=A/(A1)/T=1487233230521, chunks=1, multiChunks=1, fileContents=1, fileHistories=1]
16-2-17 8:20:30.523 | UpOperation     | Test worker    | INFO : Saving local delta database, version A/(A1)/T=1487233230521 to file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000001 ... 
16-2-17 8:20:30.523 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000001 ...
16-2-17 8:20:30.523 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.523 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.523 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000001 to RemoteFile[name=database-A-0000000001] ...
16-2-17 8:20:30.523 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000001 -> Temp. remote file: RemoteFile[name=temp-pikDG-database-A-0000000001], final location: RemoteFile[name=database-A-0000000001]
16-2-17 8:20:30.524 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.524 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.524 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/temp-transaction-2341728989139558231.tmp
16-2-17 8:20:30.524 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@3c9dbb88) ...
16-2-17 8:20:30.525 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-17a89276] ...
16-2-17 8:20:30.525 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.525 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@580ee05d) ...
16-2-17 8:20:30.525 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/multichunk-e1a629f47ad3db272b35655812123badde0a7bd8 to temp. file RemoteFile[name=temp-GdQCg-multichunk-e1a629f47ad3db272b35655812123badde0a7bd8] ...
16-2-17 8:20:30.525 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@2466418b) ...
16-2-17 8:20:30.525 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000001 to temp. file RemoteFile[name=temp-pikDG-database-A-0000000001] ...
16-2-17 8:20:30.526 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-GdQCg-multichunk-e1a629f47ad3db272b35655812123badde0a7bd8] to final location RemoteFile[name=multichunk-e1a629f47ad3db272b35655812123badde0a7bd8] ...
16-2-17 8:20:30.526 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-pikDG-database-A-0000000001] to final location RemoteFile[name=database-A-0000000001] ...
16-2-17 8:20:30.526 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-17a89276] ...
16-2-17 8:20:30.526 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.526 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.526 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version A/(A1)/T=1487233230521) ...
16-2-17 8:20:30.527 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.532 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=A/(A1)/T=1487233230521, chunks=1, multiChunks=1, fileContents=1, fileHistories=1]
16-2-17 8:20:30.532 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.532 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.532 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230523, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.532 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.534 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-A-1487233230425] ...
16-2-17 8:20:30.534 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-A-1487233230425]
16-2-17 8:20:30.534 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.534 | Cache           | Test worker    | INFO : Cache size okay (51 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.535 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@3d204e1b) ...
16-2-17 8:20:30.535 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.535 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.535 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.535 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.542 | hsqldb.db.HSQLD | Test worker    | INFO : Checkpoint start
16-2-17 8:20:30.543 | hsqldb.db.HSQLD | Test worker    | INFO : checkpointClose start
16-2-17 8:20:30.549 | hsqldb.db.HSQLD | Test worker    | FINE : log close size: 0
16-2-17 8:20:30.551 | hsqldb.db.HSQLD | Test worker    | INFO : checkpointClose end
16-2-17 8:20:30.552 | hsqldb.db.HSQLD | Test worker    | INFO : Checkpoint end - txts: 1
16-2-17 8:20:30.557 | DatabaseConnect | Test worker    | INFO : Found 0 tables.
16-2-17 8:20:30.557 | DatabaseConnect | Test worker    | INFO : Database has no tables. Creating tables from script.create.all.sql
16-2-17 8:20:30.557 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Tables
16-2-17 8:20:30.557 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS databaseversion ( id int NOT NULL IDENTITY, status varchar(45) NOT NULL, localtime datetime NOT NULL, client varchar(45) NOT NULL, vectorclock_serialized varchar(1024) NOT NULL, UNIQUE (vectorclock_serialized) ); 
16-2-17 8:20:30.559 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  chunk ( checksum varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (checksum), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.562 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  databaseversion_vectorclock ( databaseversion_id int NOT NULL, client varchar(45) NOT NULL, logicaltime int NOT NULL, PRIMARY KEY (databaseversion_id, client), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.564 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filecontent ( checksum varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (checksum), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.567 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filecontent_chunk ( filecontent_checksum varchar(40) NOT NULL, chunk_checksum varchar(40) NOT NULL, num int NOT NULL, PRIMARY KEY (filecontent_checksum, chunk_checksum, num), FOREIGN KEY (filecontent_checksum) REFERENCES filecontent (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (chunk_checksum) REFERENCES chunk (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.569 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  filehistory ( id varchar(40) NOT NULL, databaseversion_id int NOT NULL, PRIMARY KEY (id, databaseversion_id), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.571 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  fileversion ( filehistory_id varchar(40) NOT NULL, version int NOT NULL, databaseversion_id int NOT NULL, path varchar(1024) NOT NULL, type varchar(45) NOT NULL, status varchar(45) NOT NULL, size bigint NOT NULL, lastmodified datetime NOT NULL, linktarget varchar(1024), filecontent_checksum varchar(40) DEFAULT NULL, updated datetime NOT NULL, posixperms varchar(45) DEFAULT NULL, dosattrs varchar(45) DEFAULT NULL, PRIMARY KEY (filehistory_id, version, databaseversion_id), FOREIGN KEY (filehistory_id, databaseversion_id) REFERENCES filehistory (id, databaseversion_id) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (filecontent_checksum) REFERENCES filecontent (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.573 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk ( id varchar(40) NOT NULL, databaseversion_id int NOT NULL, size bigint NOT NULL, PRIMARY KEY (id), FOREIGN KEY (databaseversion_id) REFERENCES databaseversion (id) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.575 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk_chunk ( multichunk_id varchar(40) NOT NULL, chunk_checksum varchar(40) NOT NULL, PRIMARY KEY (multichunk_id, chunk_checksum), FOREIGN KEY (multichunk_id) REFERENCES multichunk (id) ON DELETE NO ACTION ON UPDATE NO ACTION, FOREIGN KEY (chunk_checksum) REFERENCES chunk (checksum) ON DELETE NO ACTION ON UPDATE NO ACTION ); 
16-2-17 8:20:30.578 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  multichunk_muddy ( id varchar(40) NOT NULL, machine_name varchar(255) NOT NULL, machine_version int NOT NULL, PRIMARY KEY (id) ); 
16-2-17 8:20:30.580 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  known_databases ( id int NOT NULL IDENTITY, client varchar(45) NOT NULL, filenumber int NOT NULL, UNIQUE (client, filenumber) ); 
16-2-17 8:20:30.582 | SqlRunner       | Test worker    | INFO : SQL:  CREATE CACHED TABLE IF NOT EXISTS  general_settings ( key varchar(255) NOT NULL, value varchar(255) NOT NULL, PRIMARY KEY (key) ); 
16-2-17 8:20:30.584 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Non-primary indices
16-2-17 8:20:30.584 | SqlRunner       | Test worker    | INFO : SQL:   CREATE INDEX idx_databaseversion_status ON databaseversion (status); 
16-2-17 8:20:30.584 | hsqldb.db.HSQLD | Test worker    | INFO : dataFileCache open start
16-2-17 8:20:30.587 | hsqldb.db.HSQLD | Test worker    | INFO : dataFileCache open end
16-2-17 8:20:30.589 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_databaseversion_vectorclock_serialized ON databaseversion (vectorclock_serialized); 
16-2-17 8:20:30.591 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_path ON fileversion (path); 
16-2-17 8:20:30.593 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_status ON fileversion (status); 
16-2-17 8:20:30.595 | SqlRunner       | Test worker    | INFO : SQL: CREATE INDEX idx_fileversion_filecontent_checksum ON fileversion (filecontent_checksum); 
16-2-17 8:20:30.597 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Views
16-2-17 8:20:30.597 | SqlRunner       | Test worker    | INFO : SQL:    CREATE VIEW databaseversion_master AS SELECT dbv.*, vc.logicaltime as client_version FROM databaseversion dbv JOIN databaseversion_vectorclock vc on dbv.id=vc.databaseversion_id and dbv.client=vc.client WHERE dbv.status='MASTER'; 
16-2-17 8:20:30.601 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master AS SELECT fv0.* FROM fileversion fv0 JOIN databaseversion dbv ON fv0.databaseversion_id=dbv.id AND dbv.status='MASTER'; 
16-2-17 8:20:30.603 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master_maxversion AS SELECT DISTINCT filehistory_id, MAX(version) version FROM fileversion_master GROUP BY filehistory_id; 
16-2-17 8:20:30.606 | SqlRunner       | Test worker    | INFO : SQL:  CREATE VIEW fileversion_master_last AS SELECT fv.* FROM fileversion_master_maxversion fvmax JOIN fileversion_master fv ON fvmax.filehistory_id=fv.filehistory_id AND fvmax.version=fv.version WHERE fv.status<>'DELETED'; 
16-2-17 8:20:30.608 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Full Views
16-2-17 8:20:30.608 | SqlRunner       | Test worker    | INFO : SQL:    create view filehistory_full as select dbv.status as databaseversion_status, dbv.localtime as databaseversion_localtime, dbv.client as databaseversion_client, dbv.vectorclock_serialized as databaseversion_vectorclock_serialized, fh.* from databaseversion dbv join filehistory fh on dbv.id=fh.databaseversion_id; 
16-2-17 8:20:30.610 | SqlRunner       | Test worker    | INFO : SQL:  create view fileversion_full as select fhf.databaseversion_status, fhf.databaseversion_localtime, fhf.databaseversion_client, fhf.databaseversion_vectorclock_serialized, fv.* from filehistory_full fhf join fileversion fv on fhf.id=fv.filehistory_id and fhf.databaseversion_id=fv.databaseversion_id; 
16-2-17 8:20:30.612 | SqlRunner       | Test worker    | INFO : SQL (comment): -- Functions
16-2-17 8:20:30.612 | SqlRunner       | Test worker    | INFO : SQL (new delimiter): end;
16-2-17 8:20:30.612 | SqlRunner       | Test worker    | INFO : SQL:     create function substr_count(haystack varchar(255), needle varchar(255)) returns integer begin atomic declare strCount integer; declare lastIndex integer;  set strCount = 0; set lastIndex = 1;  while lastIndex <> 0 do set lastIndex = locate(needle, haystack, lastIndex);  if lastIndex <> 0 then set strCount = strCount + 1; set lastIndex = lastIndex + length(needle); end if; end while;  return strCount; end; 
16-2-17 8:20:30.615 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.615 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client B ...
16-2-17 8:20:30.615 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.615 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@44417fc8) ...
16-2-17 8:20:30.615 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.616 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.616 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.616 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.616 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.616 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@53a279a0) ...
16-2-17 8:20:30.616 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.616 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is new.
16-2-17 8:20:30.616 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@51fe16f1) ...
16-2-17 8:20:30.616 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@64af919) ...
16-2-17 8:20:30.616 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-B-1487233230535] ...
16-2-17 8:20:30.616 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-B-1487233230535]
16-2-17 8:20:30.616 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-B-1487233230535] ...
16-2-17 8:20:30.617 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.617 | DownOperation   | Test worker    | INFO : - Downloading database-A-0000000001 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000001
16-2-17 8:20:30.617 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@d47a845) ...
16-2-17 8:20:30.617 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.617 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000001 ...
16-2-17 8:20:30.618 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A1)/T=1487233230521
16-2-17 8:20:30.619 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.619 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A1)/T=1487233230521], B=[]}
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO : - Winner is A with branch: 
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO : Losers Branch: []
16-2-17 8:20:30.619 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521]
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [A/(A1)/T=1487233230521]
16-2-17 8:20:30.619 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.620 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000001 ...
16-2-17 8:20:30.620 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A1)/T=1487233230521
16-2-17 8:20:30.620 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.621 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.622 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.622 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.622 | FileSystemActio | Test worker    | INFO :   + Comparing local version: null
16-2-17 8:20:30.622 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.622 | FileVersionComp | Test worker    | INFO :      - [DELETED]: Local file DIFFERS from file version, expected EXISTS = true, but actual EXISTS = false, for file A-original
16-2-17 8:20:30.623 | FileSystemActio | Test worker    | INFO :      -> (2) Deleted: Local file does NOT exist, but it should, winning version not known: FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-] AND /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-original
16-2-17 8:20:30.623 | FileSystemActio | Test worker    | INFO :      -> NewFileSystemAction [file1=null, file2=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.623 | DownOperation   | Test worker    | INFO :   + Adding multichunk e1a629f47ad3db272b35655812123badde0a7bd8 to download list ...
16-2-17 8:20:30.623 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.623 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@26def865) ...
16-2-17 8:20:30.623 | Downloader      | Test worker    | INFO :   + Downloading multichunk e1a629f47ad3db272b35655812123badde0a7bd8 ...
16-2-17 8:20:30.624 | Downloader      | Test worker    | INFO :   + Decrypting multichunk e1a629f47ad3db272b35655812123badde0a7bd8 ...
16-2-17 8:20:30.624 | Downloader      | Test worker    | FINE :   + Locally deleting multichunk e1a629f47ad3db272b35655812123badde0a7bd8 ...
16-2-17 8:20:30.625 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.625 | FileSystemActio | Test worker    | INFO :    + NewFileSystemAction [file1=null, file2=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.625 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.625 | DownOperation   | Test worker    | FINE :    +  NewFileSystemAction [file1=null, file2=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.625 | Assembler       | Test worker    | INFO :      - Creating file A-original to /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/temp-reconstructedFileVersion-3613744461039791032.tmp ...
16-2-17 8:20:30.626 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.626 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.626 | DownOperation   | Test worker    | INFO :   + Applying database version (A1)
16-2-17 8:20:30.626 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=A/(A1)/T=1487233230521, chunks=1, multiChunks=1, fileContents=1, fileHistories=1]
16-2-17 8:20:30.631 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-B-1487233230535] ...
16-2-17 8:20:30.632 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-B-1487233230535]
16-2-17 8:20:30.632 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.632 | Cache           | Test worker    | INFO : Cache size okay (51 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.632 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@2e56448e) ...
16-2-17 8:20:30.632 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.635 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/A-original, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/A-original
16-2-17 8:20:30.636 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.637 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.669 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.669 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.670 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.670 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.671 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.672 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.672 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.673 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.673 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.673 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.674 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.674 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.674 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.676 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.676 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.676 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client B ...
16-2-17 8:20:30.676 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.676 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@78f85051) ...
16-2-17 8:20:30.677 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.677 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.677 | StatusOperation | Test worker    | INFO : Running 'Status' at client B ...
16-2-17 8:20:30.677 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.677 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.677 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@268677bd) ...
16-2-17 8:20:30.677 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-B ...
16-2-17 8:20:30.677 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.677 | StatusOperation | Test worker    | FINE : - New file: B-moved
16-2-17 8:20:30.677 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@2203891e) ...
16-2-17 8:20:30.677 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.678 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.678 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.678 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.678 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.678 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@68cdb63a) ...
16-2-17 8:20:30.678 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.678 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.678 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@5e8a2cfd) ...
16-2-17 8:20:30.678 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.678 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-B-1487233230674] ...
16-2-17 8:20:30.678 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-B-1487233230674]
16-2-17 8:20:30.679 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-B-1487233230674] ...
16-2-17 8:20:30.679 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.679 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.679 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.680 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@5dc778b8) ...
16-2-17 8:20:30.680 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.680 | Indexer         | AsyncI/syncany | FINE :   + Deleted: Adding DELETED version: FileVersion [version=2, path=A-original, type=FILE, status=DELETED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.681 | Indexer         | AsyncI/syncany | FINE :                            based on: FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.681 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.681 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.681 | Indexer         | AsyncI/syncany | FINE : - Chunk exists: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.681 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.682 | Indexer         | AsyncI/syncany | FINE : - /File: B-moved (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.682 | Indexer         | AsyncI/syncany | FINE :    * Found old file history 1f8676aeecb30fdace71c68ee0c5999de61277d8 (by checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c), appending new version.
16-2-17 8:20:30.682 | FileVersionComp | AsyncI/syncany | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = B-moved, but actual PATH = A-original, for file A-original
16-2-17 8:20:30.682 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.683 | Indexer         | AsyncI/syncany | INFO :      based on file version: FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.683 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@274a8bf1) ...
16-2-17 8:20:30.683 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@17149547) ...
16-2-17 8:20:30.683 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230679, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.683 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.683 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@5b5aff7a) ...
16-2-17 8:20:30.683 | UpOperation     | Test worker    | INFO : Last vector clock was: (A1)
16-2-17 8:20:30.684 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.684 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=B/(A1,B1)/T=1487233230684, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.684 | UpOperation     | Test worker    | INFO : Saving local delta database, version B/(A1,B1)/T=1487233230684 to file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000001 ... 
16-2-17 8:20:30.684 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000001 ...
16-2-17 8:20:30.685 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.685 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000001 to RemoteFile[name=database-B-0000000001] ...
16-2-17 8:20:30.686 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000001 -> Temp. remote file: RemoteFile[name=temp-GHUtd-database-B-0000000001], final location: RemoteFile[name=database-B-0000000001]
16-2-17 8:20:30.686 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.686 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.686 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.687 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/temp-transaction-138615887718567967.tmp
16-2-17 8:20:30.687 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@7dc283f7) ...
16-2-17 8:20:30.687 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-3598127e] ...
16-2-17 8:20:30.687 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.687 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@37a9fa98) ...
16-2-17 8:20:30.687 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000001 to temp. file RemoteFile[name=temp-GHUtd-database-B-0000000001] ...
16-2-17 8:20:30.688 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-GHUtd-database-B-0000000001] to final location RemoteFile[name=database-B-0000000001] ...
16-2-17 8:20:30.688 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-3598127e] ...
16-2-17 8:20:30.688 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.688 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.688 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version B/(A1,B1)/T=1487233230684) ...
16-2-17 8:20:30.688 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.692 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=B/(A1,B1)/T=1487233230684, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.692 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.692 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.692 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230686, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.692 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.694 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-B-1487233230674] ...
16-2-17 8:20:30.694 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-B-1487233230674]
16-2-17 8:20:30.694 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.694 | Cache           | Test worker    | INFO : Cache size okay (52 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.694 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@7d2fd172) ...
16-2-17 8:20:30.694 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.695 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.695 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.695 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.695 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.696 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.696 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.696 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.697 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.697 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.697 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client A ...
16-2-17 8:20:30.697 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.697 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@600664b3) ...
16-2-17 8:20:30.697 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.697 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.697 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.697 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.697 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.697 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@240ec10f) ...
16-2-17 8:20:30.698 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.698 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is new.
16-2-17 8:20:30.698 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.698 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@7b7ab108) ...
16-2-17 8:20:30.698 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@153b6956) ...
16-2-17 8:20:30.698 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-A-1487233230696] ...
16-2-17 8:20:30.698 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-A-1487233230696]
16-2-17 8:20:30.698 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-A-1487233230696] ...
16-2-17 8:20:30.699 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.699 | DownOperation   | Test worker    | INFO : - Downloading database-B-0000000001 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000001
16-2-17 8:20:30.699 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@1298c346) ...
16-2-17 8:20:30.699 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.699 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000001 ...
16-2-17 8:20:30.700 | DatabaseXmlPars | Test worker    | INFO :    + Added database version B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.700 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.701 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.701 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.701 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A1)/T=1487233230521], B=[B/(A1,B1)/T=1487233230684]}
16-2-17 8:20:30.701 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : - Winner is B with branch: 
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO :   + B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.701 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.701 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : Losers Branch: [A/(A1)/T=1487233230521]
16-2-17 8:20:30.701 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684]
16-2-17 8:20:30.702 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.702 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [B/(A1,B1)/T=1487233230684]
16-2-17 8:20:30.702 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.702 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000001 ...
16-2-17 8:20:30.702 | DatabaseXmlPars | Test worker    | INFO :    + Added database version B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.702 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.703 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.703 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.703 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.703 | FileSystemActio | Test worker    | INFO :   + Comparing local version: FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.703 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.704 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = B-moved, but actual PATH = A-original, for file A-original
16-2-17 8:20:30.704 | FileSystemActio | Test worker    | INFO :      -> (12) Rename / Changed file attributes: Local file has different file attributes: local file = /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original, local version = FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], winning version = FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.704 | FileSystemActio | Test worker    | INFO :      -> RenameFileSystemAction [file1=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.704 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.704 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.704 | FileSystemActio | Test worker    | INFO :    + RenameFileSystemAction [file1=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.704 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.704 | DownOperation   | Test worker    | FINE :    +  RenameFileSystemAction [file1=FileVersion [version=1, path=A-original, type=FILE, status=NEW, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.705 | FileSystemActio | Test worker    | INFO :      - (1) Renaming file /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-original to /tmp/syncanytest/syncany-170216081829395-20216-client-A/B-moved ...
16-2-17 8:20:30.705 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.705 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.705 | DownOperation   | Test worker    | INFO :   + Applying database version (A1,B1)
16-2-17 8:20:30.705 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=B/(A1,B1)/T=1487233230684, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.710 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-A-1487233230696] ...
16-2-17 8:20:30.710 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-A-1487233230696]
16-2-17 8:20:30.710 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.710 | Cache           | Test worker    | INFO : Cache size okay (52 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.710 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@3ea6557c) ...
16-2-17 8:20:30.710 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.713 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/B-moved, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.713 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.714 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.724 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.725 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.725 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.726 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.726 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.726 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.727 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.727 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.727 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.728 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.728 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.728 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.728 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.729 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.729 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.729 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client A ...
16-2-17 8:20:30.729 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.729 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@74f3cd1b) ...
16-2-17 8:20:30.730 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.730 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.730 | StatusOperation | Test worker    | INFO : Running 'Status' at client A ...
16-2-17 8:20:30.730 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.730 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.730 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@78586712) ...
16-2-17 8:20:30.730 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-A ...
16-2-17 8:20:30.730 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.730 | StatusOperation | Test worker    | FINE : - New file: A-moved
16-2-17 8:20:30.731 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@6aba4c3b) ...
16-2-17 8:20:30.731 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.731 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.731 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@79f01fea) ...
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.731 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.731 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@36f10217) ...
16-2-17 8:20:30.732 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.732 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-A-1487233230729] ...
16-2-17 8:20:30.732 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-A-1487233230729]
16-2-17 8:20:30.732 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-A-1487233230729] ...
16-2-17 8:20:30.732 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.732 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.732 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.733 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@2549f202) ...
16-2-17 8:20:30.733 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.734 | Indexer         | AsyncI/syncany | FINE :   + Deleted: Adding DELETED version: FileVersion [version=3, path=B-moved, type=FILE, status=DELETED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.734 | Indexer         | AsyncI/syncany | FINE :                            based on: FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.734 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.734 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.735 | Indexer         | AsyncI/syncany | FINE : - Chunk exists: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.735 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.735 | Indexer         | AsyncI/syncany | FINE : - /File: A-moved (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.735 | Indexer         | AsyncI/syncany | FINE :    * Found old file history 1f8676aeecb30fdace71c68ee0c5999de61277d8 (by checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c), appending new version.
16-2-17 8:20:30.735 | FileVersionComp | AsyncI/syncany | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved, but actual PATH = B-moved, for file B-moved
16-2-17 8:20:30.736 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.736 | Indexer         | AsyncI/syncany | INFO :      based on file version: FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.736 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@7ea3cb) ...
16-2-17 8:20:30.736 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@79cadea4) ...
16-2-17 8:20:30.736 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230733, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.736 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@5ad9715a) ...
16-2-17 8:20:30.736 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.736 | UpOperation     | Test worker    | INFO : Last vector clock was: (A1,B1)
16-2-17 8:20:30.737 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.737 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=A/(A2,B1)/T=1487233230737, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.737 | UpOperation     | Test worker    | INFO : Saving local delta database, version A/(A2,B1)/T=1487233230737 to file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000002 ... 
16-2-17 8:20:30.737 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000002 ...
16-2-17 8:20:30.738 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.738 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000002 to RemoteFile[name=database-A-0000000002] ...
16-2-17 8:20:30.738 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000002 -> Temp. remote file: RemoteFile[name=temp-wLPpT-database-A-0000000002], final location: RemoteFile[name=database-A-0000000002]
16-2-17 8:20:30.739 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.739 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.739 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/temp-transaction-7635573800462814523.tmp
16-2-17 8:20:30.740 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@4c7bb8d0) ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-20f25a51] ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.740 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@5a5497d4) ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000002 to temp. file RemoteFile[name=temp-wLPpT-database-A-0000000002] ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-wLPpT-database-A-0000000002] to final location RemoteFile[name=database-A-0000000002] ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-20f25a51] ...
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.740 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.740 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version A/(A2,B1)/T=1487233230737) ...
16-2-17 8:20:30.741 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.744 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=A/(A2,B1)/T=1487233230737, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.744 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.744 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.744 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230739, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.744 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.746 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-A-1487233230729] ...
16-2-17 8:20:30.746 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-A-1487233230729]
16-2-17 8:20:30.747 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.747 | Cache           | Test worker    | INFO : Cache size okay (52 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.747 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@6cc6f5c2) ...
16-2-17 8:20:30.747 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.747 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.747 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.747 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.748 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.748 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.748 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.748 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.748 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.748 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.748 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.748 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client B ...
16-2-17 8:20:30.748 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.748 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@b138694) ...
16-2-17 8:20:30.748 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.749 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.749 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@4e32d7f1) ...
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is new.
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.749 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.749 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@24d90f7b) ...
16-2-17 8:20:30.749 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@3b04a16e) ...
16-2-17 8:20:30.749 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-B-1487233230748] ...
16-2-17 8:20:30.749 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-B-1487233230748]
16-2-17 8:20:30.750 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-B-1487233230748] ...
16-2-17 8:20:30.750 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.750 | DownOperation   | Test worker    | INFO : - Downloading database-A-0000000002 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000002
16-2-17 8:20:30.750 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@74480aea) ...
16-2-17 8:20:30.750 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.750 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000002 ...
16-2-17 8:20:30.751 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.752 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.752 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.752 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.752 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A2,B1)/T=1487233230737], B=[A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684]}
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : - Winner is A with branch: 
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO :   + B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO :   + A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Losers Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684]
16-2-17 8:20:30.752 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737]
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [A/(A2,B1)/T=1487233230737]
16-2-17 8:20:30.752 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.752 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000002 ...
16-2-17 8:20:30.753 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.753 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.754 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.754 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.754 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.754 | FileSystemActio | Test worker    | INFO :   + Comparing local version: FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.754 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.755 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved, but actual PATH = B-moved, for file B-moved
16-2-17 8:20:30.755 | FileSystemActio | Test worker    | INFO :      -> (12) Rename / Changed file attributes: Local file has different file attributes: local file = /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved, local version = FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], winning version = FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.755 | FileSystemActio | Test worker    | INFO :      -> RenameFileSystemAction [file1=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.755 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.755 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.755 | FileSystemActio | Test worker    | INFO :    + RenameFileSystemAction [file1=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.755 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.755 | DownOperation   | Test worker    | FINE :    +  RenameFileSystemAction [file1=FileVersion [version=2, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.755 | FileSystemActio | Test worker    | INFO :      - (1) Renaming file /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved to /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved ...
16-2-17 8:20:30.756 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.756 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.756 | DownOperation   | Test worker    | INFO :   + Applying database version (A2,B1)
16-2-17 8:20:30.756 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=A/(A2,B1)/T=1487233230737, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.761 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-B-1487233230748] ...
16-2-17 8:20:30.761 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-B-1487233230748]
16-2-17 8:20:30.761 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.761 | Cache           | Test worker    | INFO : Cache size okay (52 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.761 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@44268397) ...
16-2-17 8:20:30.761 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.763 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved
16-2-17 8:20:30.764 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.764 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.776 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.777 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.777 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.778 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.778 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.778 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.779 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.779 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.779 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.780 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.780 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.780 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.780 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.781 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.781 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.781 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.781 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client A ...
16-2-17 8:20:30.781 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.781 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@5c1028ba) ...
16-2-17 8:20:30.781 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.782 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.782 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@524c34d) ...
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.782 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.782 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@7481b9a7) ...
16-2-17 8:20:30.783 | DownOperation   | Test worker    | INFO : * Nothing new. Skipping down operation.
16-2-17 8:20:30.783 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@19ca0702) ...
16-2-17 8:20:30.785 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved
16-2-17 8:20:30.785 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.786 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.797 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.797 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.798 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.798 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.799 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.799 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.800 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.800 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.801 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.801 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.801 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.801 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.801 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.802 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.802 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.802 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client A ...
16-2-17 8:20:30.802 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.802 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@546208ee) ...
16-2-17 8:20:30.803 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.803 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.803 | StatusOperation | Test worker    | INFO : Running 'Status' at client A ...
16-2-17 8:20:30.803 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.803 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.803 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@2eb4f793) ...
16-2-17 8:20:30.803 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-A ...
16-2-17 8:20:30.803 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.803 | StatusOperation | Test worker    | FINE : - New file: A-moved-again
16-2-17 8:20:30.804 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@4d90f9a9) ...
16-2-17 8:20:30.804 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.804 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.804 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@4493532c) ...
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.804 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.805 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@1ee7ff8c) ...
16-2-17 8:20:30.805 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.805 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-A-1487233230801] ...
16-2-17 8:20:30.805 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-A-1487233230801]
16-2-17 8:20:30.805 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-A-1487233230801] ...
16-2-17 8:20:30.805 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.805 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.805 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.806 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@228f7ce5) ...
16-2-17 8:20:30.806 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.806 | Indexer         | AsyncI/syncany | FINE :   + Deleted: Adding DELETED version: FileVersion [version=4, path=A-moved, type=FILE, status=DELETED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.806 | Indexer         | AsyncI/syncany | FINE :                            based on: FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.806 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again
16-2-17 8:20:30.806 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again
16-2-17 8:20:30.807 | Indexer         | AsyncI/syncany | FINE : - Chunk exists: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.807 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again
16-2-17 8:20:30.807 | Indexer         | AsyncI/syncany | FINE : - /File: A-moved-again (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.808 | Indexer         | AsyncI/syncany | FINE :    * Found old file history 1f8676aeecb30fdace71c68ee0c5999de61277d8 (by checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c), appending new version.
16-2-17 8:20:30.808 | FileVersionComp | AsyncI/syncany | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved-again, but actual PATH = A-moved, for file A-moved
16-2-17 8:20:30.808 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.808 | Indexer         | AsyncI/syncany | INFO :      based on file version: FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.808 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@10f66970) ...
16-2-17 8:20:30.808 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@25a42a00) ...
16-2-17 8:20:30.808 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230806, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.809 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@1569663d) ...
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : Last vector clock was: (A2,B1)
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=A/(A3,B1)/T=1487233230809, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : Saving local delta database, version A/(A3,B1)/T=1487233230809 to file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000003 ... 
16-2-17 8:20:30.809 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000003 ...
16-2-17 8:20:30.811 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.811 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000003 to RemoteFile[name=database-A-0000000003] ...
16-2-17 8:20:30.811 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000003 -> Temp. remote file: RemoteFile[name=temp-sPKmU-database-A-0000000003], final location: RemoteFile[name=database-A-0000000003]
16-2-17 8:20:30.811 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.811 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.812 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/temp-transaction-8365713850534287849.tmp
16-2-17 8:20:30.812 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@3b7b31f1) ...
16-2-17 8:20:30.812 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-65d45c0b] ...
16-2-17 8:20:30.812 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.812 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.812 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@6df8618d) ...
16-2-17 8:20:30.812 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000003 to temp. file RemoteFile[name=temp-sPKmU-database-A-0000000003] ...
16-2-17 8:20:30.813 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-sPKmU-database-A-0000000003] to final location RemoteFile[name=database-A-0000000003] ...
16-2-17 8:20:30.813 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-65d45c0b] ...
16-2-17 8:20:30.813 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.813 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.813 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version A/(A3,B1)/T=1487233230809) ...
16-2-17 8:20:30.813 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.817 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=A/(A3,B1)/T=1487233230809, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.817 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.817 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.817 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230812, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.817 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.819 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-A-1487233230801] ...
16-2-17 8:20:30.824 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-A-1487233230801]
16-2-17 8:20:30.824 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.824 | Cache           | Test worker    | INFO : Cache size okay (53 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.824 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@4c043421) ...
16-2-17 8:20:30.824 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.825 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.825 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.825 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.825 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.826 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.826 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.826 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.827 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.827 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.827 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client B ...
16-2-17 8:20:30.827 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.827 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@2969d96b) ...
16-2-17 8:20:30.827 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.828 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.828 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@5ef93207) ...
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000003 is new.
16-2-17 8:20:30.828 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.829 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.829 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@5066245a) ...
16-2-17 8:20:30.829 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@6e02a9e7) ...
16-2-17 8:20:30.829 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-B-1487233230826] ...
16-2-17 8:20:30.829 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-B-1487233230826]
16-2-17 8:20:30.829 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-B-1487233230826] ...
16-2-17 8:20:30.829 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.829 | DownOperation   | Test worker    | INFO : - Downloading database-A-0000000003 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000003
16-2-17 8:20:30.829 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@37df7a81) ...
16-2-17 8:20:30.830 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.830 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000003 ...
16-2-17 8:20:30.831 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.831 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.831 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.832 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.832 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000003; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.832 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.832 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A3,B1)/T=1487233230809], B=[A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737]}
16-2-17 8:20:30.832 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : - Winner is A with branch: 
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO :   + B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO :   + A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO :   + A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.832 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.832 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Losers Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737]
16-2-17 8:20:30.832 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809]
16-2-17 8:20:30.832 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.833 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [A/(A3,B1)/T=1487233230809]
16-2-17 8:20:30.833 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.833 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000003 ...
16-2-17 8:20:30.834 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.834 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.834 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.835 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.835 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.835 | FileSystemActio | Test worker    | INFO :   + Comparing local version: FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.835 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.836 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved-again, but actual PATH = A-moved, for file A-moved
16-2-17 8:20:30.836 | FileSystemActio | Test worker    | INFO :      -> (12) Rename / Changed file attributes: Local file has different file attributes: local file = /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved, local version = FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], winning version = FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.836 | FileSystemActio | Test worker    | INFO :      -> RenameFileSystemAction [file1=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.836 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.836 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.836 | FileSystemActio | Test worker    | INFO :    + RenameFileSystemAction [file1=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.836 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.836 | DownOperation   | Test worker    | FINE :    +  RenameFileSystemAction [file1=FileVersion [version=3, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.837 | FileSystemActio | Test worker    | INFO :      - (1) Renaming file /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved to /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved-again ...
16-2-17 8:20:30.837 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.837 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.837 | DownOperation   | Test worker    | INFO :   + Applying database version (A3,B1)
16-2-17 8:20:30.837 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=A/(A3,B1)/T=1487233230809, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.842 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-B-1487233230826] ...
16-2-17 8:20:30.842 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-B-1487233230826]
16-2-17 8:20:30.842 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.843 | Cache           | Test worker    | INFO : Cache size okay (53 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.843 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@490512fd) ...
16-2-17 8:20:30.843 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.846 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved-again, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved-again
16-2-17 8:20:30.847 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.848 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.870 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.870 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.871 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.872 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.872 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.872 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.873 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.873 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.874 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.874 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.874 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.874 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.874 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.874 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.874 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.874 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.875 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.875 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.875 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.877 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.877 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.877 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client B ...
16-2-17 8:20:30.877 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.877 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@34155cd3) ...
16-2-17 8:20:30.877 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.877 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.877 | StatusOperation | Test worker    | INFO : Running 'Status' at client B ...
16-2-17 8:20:30.877 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.877 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.877 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@21a25999) ...
16-2-17 8:20:30.878 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-B ...
16-2-17 8:20:30.878 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.878 | StatusOperation | Test worker    | FINE : - New file: B-moved
16-2-17 8:20:30.878 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@4662669a) ...
16-2-17 8:20:30.878 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.879 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.879 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@5ee899e3) ...
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000003 is already known (in local database). Ignoring.
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.879 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.879 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@278b3575) ...
16-2-17 8:20:30.879 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.879 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-B-1487233230875] ...
16-2-17 8:20:30.879 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-B-1487233230875]
16-2-17 8:20:30.880 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-B-1487233230875] ...
16-2-17 8:20:30.880 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.884 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.884 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.884 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@22a70a73) ...
16-2-17 8:20:30.884 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.885 | Indexer         | AsyncI/syncany | FINE :   + Deleted: Adding DELETED version: FileVersion [version=5, path=A-moved-again, type=FILE, status=DELETED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.886 | Indexer         | AsyncI/syncany | FINE :                            based on: FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.886 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.886 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.887 | Indexer         | AsyncI/syncany | FINE : - Chunk exists: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.887 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.887 | Indexer         | AsyncI/syncany | FINE : - /File: B-moved (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.888 | Indexer         | AsyncI/syncany | FINE :    * Found old file history 1f8676aeecb30fdace71c68ee0c5999de61277d8 (by checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c), appending new version.
16-2-17 8:20:30.888 | FileVersionComp | AsyncI/syncany | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = B-moved, but actual PATH = A-moved-again, for file A-moved-again
16-2-17 8:20:30.888 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.888 | Indexer         | AsyncI/syncany | INFO :      based on file version: FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.888 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@5f87d3ff) ...
16-2-17 8:20:30.888 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@98271da) ...
16-2-17 8:20:30.888 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230884, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : Last vector clock was: (A3,B1)
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=B/(A3,B2)/T=1487233230889, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : Saving local delta database, version B/(A3,B2)/T=1487233230889 to file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000002 ... 
16-2-17 8:20:30.889 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000002 ...
16-2-17 8:20:30.890 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.890 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000002 to RemoteFile[name=database-B-0000000002] ...
16-2-17 8:20:30.890 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000002 -> Temp. remote file: RemoteFile[name=temp-QyUjw-database-B-0000000002], final location: RemoteFile[name=database-B-0000000002]
16-2-17 8:20:30.890 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.890 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.891 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/temp-transaction-6773557441580056376.tmp
16-2-17 8:20:30.891 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@6cff05fa) ...
16-2-17 8:20:30.891 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-640a0784] ...
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.892 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@7945f1ed) ...
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-B-0000000002 to temp. file RemoteFile[name=temp-QyUjw-database-B-0000000002] ...
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-QyUjw-database-B-0000000002] to final location RemoteFile[name=database-B-0000000002] ...
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-640a0784] ...
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.892 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.892 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version B/(A3,B2)/T=1487233230889) ...
16-2-17 8:20:30.893 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.894 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@11c85c8b) ...
16-2-17 8:20:30.897 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=B/(A3,B2)/T=1487233230889, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.897 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.897 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.899 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.899 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230899, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.899 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.901 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-B-1487233230875] ...
16-2-17 8:20:30.901 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-B-1487233230875]
16-2-17 8:20:30.901 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.902 | Cache           | Test worker    | INFO : Cache size okay (54 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.902 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@602e79e2) ...
16-2-17 8:20:30.902 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.902 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.902 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.902 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.903 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.903 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.903 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client A ...
16-2-17 8:20:30.903 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.903 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@3fb83e51) ...
16-2-17 8:20:30.903 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.904 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.904 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@29a54690) ...
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000003 is already known (in local database). Ignoring.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000002 is new.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.904 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.904 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@10992dd3) ...
16-2-17 8:20:30.904 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@1400f3c0) ...
16-2-17 8:20:30.904 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-A-1487233230902] ...
16-2-17 8:20:30.904 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-A-1487233230902]
16-2-17 8:20:30.905 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-A-1487233230902] ...
16-2-17 8:20:30.905 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.905 | DownOperation   | Test worker    | INFO : - Downloading database-B-0000000002 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000002
16-2-17 8:20:30.905 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@4ef6ea5c) ...
16-2-17 8:20:30.905 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.905 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000002 ...
16-2-17 8:20:30.907 | DatabaseXmlPars | Test worker    | INFO :    + Added database version B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.907 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.907 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.907 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.907 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.907 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000003; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.907 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.907 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809], B=[B/(A3,B2)/T=1487233230889]}
16-2-17 8:20:30.907 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : - Winner is B with branch: 
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO :   + B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO :   + A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO :   + A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO :   + B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.908 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.908 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Losers Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809]
16-2-17 8:20:30.908 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809, B/(A3,B2)/T=1487233230889]
16-2-17 8:20:30.908 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.908 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [B/(A3,B2)/T=1487233230889]
16-2-17 8:20:30.908 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.908 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-B-0000000002 ...
16-2-17 8:20:30.909 | DatabaseXmlPars | Test worker    | INFO :    + Added database version B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.909 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.910 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.910 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.910 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.910 | FileSystemActio | Test worker    | INFO :   + Comparing local version: FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.910 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.911 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = B-moved, but actual PATH = A-moved-again, for file A-moved-again
16-2-17 8:20:30.911 | FileSystemActio | Test worker    | INFO :      -> (12) Rename / Changed file attributes: Local file has different file attributes: local file = /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again, local version = FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], winning version = FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.911 | FileSystemActio | Test worker    | INFO :      -> RenameFileSystemAction [file1=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.911 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.911 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.911 | FileSystemActio | Test worker    | INFO :    + RenameFileSystemAction [file1=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.911 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.911 | DownOperation   | Test worker    | FINE :    +  RenameFileSystemAction [file1=FileVersion [version=4, path=A-moved-again, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.912 | FileSystemActio | Test worker    | INFO :      - (1) Renaming file /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved-again to /tmp/syncanytest/syncany-170216081829395-20216-client-A/B-moved ...
16-2-17 8:20:30.912 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.912 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.912 | DownOperation   | Test worker    | INFO :   + Applying database version (A3,B2)
16-2-17 8:20:30.912 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=B/(A3,B2)/T=1487233230889, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.917 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-A-1487233230902] ...
16-2-17 8:20:30.917 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-A-1487233230902]
16-2-17 8:20:30.917 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.917 | Cache           | Test worker    | INFO : Cache size okay (54 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.917 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@a7aadfc) ...
16-2-17 8:20:30.918 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.921 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/B-moved, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved
16-2-17 8:20:30.922 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.923 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.942 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:30.943 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:30.943 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:30.944 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:30.944 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:30.945 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.945 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:30.946 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:30.946 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc
16-2-17 8:20:30.946 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.947 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-A' ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.947 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.947 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.949 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.949 | UpOperation     | Test worker    | INFO : 
16-2-17 8:20:30.949 | UpOperation     | Test worker    | INFO : Running 'Sync up' at client A ...
16-2-17 8:20:30.949 | UpOperation     | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.949 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpStartSyncExternalEvent@3070ec87) ...
16-2-17 8:20:30.949 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.949 | StatusOperation | Test worker    | INFO : 
16-2-17 8:20:30.949 | StatusOperation | Test worker    | INFO : Running 'Status' at client A ...
16-2-17 8:20:30.949 | StatusOperation | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.949 | StatusOperation | Test worker    | INFO : Querying current file tree from database ...
16-2-17 8:20:30.949 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusStartSyncExternalEvent (org.syncany.operations.daemon.messages.StatusStartSyncExternalEvent@258488cb) ...
16-2-17 8:20:30.950 | StatusOperation | Test worker    | INFO : Analyzing local folder /tmp/syncanytest/syncany-170216081829395-20216-client-A ...
16-2-17 8:20:30.950 | StatusOperation | Test worker    | FINE : - Ignoring file (syncany app-related): .syncany
16-2-17 8:20:30.950 | StatusOperation | Test worker    | FINE : - New file: A-moved
16-2-17 8:20:30.950 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event StatusEndSyncExternalEvent (org.syncany.operations.daemon.messages.StatusEndSyncExternalEvent@5f82ded9) ...
16-2-17 8:20:30.950 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.951 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client A ...
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.951 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@5693901a) ...
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000003 is already known (in local database). Ignoring.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.951 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.951 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@6bc28fc) ...
16-2-17 8:20:30.951 | UpOperation     | Test worker    | INFO : No remote changes, ready to upload.
16-2-17 8:20:30.951 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-up-A-1487233230947] ...
16-2-17 8:20:30.951 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-up-A-1487233230947]
16-2-17 8:20:30.951 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-up-A-1487233230947] ...
16-2-17 8:20:30.952 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.956 | TransactionAwar | Test worker    | INFO : Done rolling back previous transactions.
16-2-17 8:20:30.956 | AsyncIndexer    | AsyncI/syncany | INFO : Starting Indexing.
16-2-17 8:20:30.956 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexStartSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexStartSyncExternalEvent@768464c6) ...
16-2-17 8:20:30.956 | Indexer         | AsyncI/syncany | FINE : - Looking for deleted files ...
16-2-17 8:20:30.957 | Indexer         | AsyncI/syncany | FINE :   + Deleted: Adding DELETED version: FileVersion [version=6, path=B-moved, type=FILE, status=DELETED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.957 | Indexer         | AsyncI/syncany | FINE :                            based on: FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.957 | Indexer         | AsyncI/syncany | FINE : - +File /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.957 | Indexer         | AsyncI/syncany | FINE : - +FileContent: /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.958 | Indexer         | AsyncI/syncany | FINE : - Chunk exists: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c
16-2-17 8:20:30.958 | Indexer         | AsyncI/syncany | FINE : - Chunk > FileContent: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c > /tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved
16-2-17 8:20:30.958 | Indexer         | AsyncI/syncany | FINE : - /File: A-moved (checksum 286eab6a0bcabc8fb6b685a58bc380f9eda6330c)
16-2-17 8:20:30.959 | Indexer         | AsyncI/syncany | FINE :    * Found old file history 1f8676aeecb30fdace71c68ee0c5999de61277d8 (by checksum: 286eab6a0bcabc8fb6b685a58bc380f9eda6330c), appending new version.
16-2-17 8:20:30.959 | FileVersionComp | AsyncI/syncany | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved, but actual PATH = B-moved, for file B-moved
16-2-17 8:20:30.960 | Indexer         | AsyncI/syncany | INFO :    * Added file version:    FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.960 | Indexer         | AsyncI/syncany | INFO :      based on file version: FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.960 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexChangesDetectedSyncExternalEvent@7c35a9ad) ...
16-2-17 8:20:30.960 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexEndSyncExternalEvent@7a467e7e) ...
16-2-17 8:20:30.960 | Indexer         | AsyncI/syncany | FINE : Processed new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230956, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.960 | UpOperation     | Test worker    | INFO : No DIRTY data found in database (no dirty databases); Nothing to do here.
16-2-17 8:20:30.960 | UpOperation     | Test worker    | INFO : Last vector clock was: (A3,B2)
16-2-17 8:20:30.960 | UpOperation     | Test worker    | INFO : Uploading new multichunks ...
16-2-17 8:20:30.961 | UpOperation     | Test worker    | INFO : Uploading database: DatabaseVersion [header=A/(A4,B2)/T=1487233230960, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.961 | UpOperation     | Test worker    | INFO : Saving local delta database, version A/(A4,B2)/T=1487233230960 to file /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000004 ... 
16-2-17 8:20:30.961 | UpOperation     | Test worker    | INFO : - Saving database to /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000004 ...
16-2-17 8:20:30.961 | UpOperation     | Test worker    | INFO : - Uploading local delta database file ...
16-2-17 8:20:30.961 | UpOperation     | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000004 to RemoteFile[name=database-A-0000000004] ...
16-2-17 8:20:30.961 | RemoteTransacti | Test worker    | INFO : - Adding file to TX for UPLOAD: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000004 -> Temp. remote file: RemoteFile[name=temp-CMAPl-database-A-0000000004], final location: RemoteFile[name=database-A-0000000004]
16-2-17 8:20:30.962 | UpOperation     | Test worker    | INFO : Adding shutdown hook (to allow resuming the upload) ...
16-2-17 8:20:30.962 | RemoteTransacti | Test worker    | INFO : Starting TX.commit() ...
16-2-17 8:20:30.963 | RemoteTransacti | Test worker    | INFO : Wrote transaction manifest to temporary file: /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/temp-transaction-5102124101500216255.tmp
16-2-17 8:20:30.963 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileSyncExternalEvent@6486b7c9) ...
16-2-17 8:20:30.963 | RemoteTransacti | Test worker    | INFO : - Uploading remote transaction file RemoteFile[name=transaction-5d5f6301] ...
16-2-17 8:20:30.963 | RemoteTransacti | Test worker    | INFO : - Starting to upload data in commit.
16-2-17 8:20:30.963 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpUploadFileInTransactionSyncExternalEvent (org.syncany.operations.daemon.messages.UpUploadFileInTransactionSyncExternalEvent@45456765) ...
16-2-17 8:20:30.963 | RemoteTransacti | Test worker    | INFO : - Uploading /tmp/syncanytest/syncany-170216081829395-20216-client-A/.syncany/cache/database-A-0000000004 to temp. file RemoteFile[name=temp-CMAPl-database-A-0000000004] ...
16-2-17 8:20:30.963 | RemoteTransacti | Test worker    | INFO : - Moving temp. file RemoteFile[name=temp-CMAPl-database-A-0000000004] to final location RemoteFile[name=database-A-0000000004] ...
16-2-17 8:20:30.964 | RemoteTransacti | Test worker    | INFO : - Deleting remote transaction file RemoteFile[name=transaction-5d5f6301] ...
16-2-17 8:20:30.964 | RemoteTransacti | Test worker    | INFO : END of TX.commmit(): Succesfully committed transaction.
16-2-17 8:20:30.964 | RemoteTransacti | Test worker    | INFO : END of TX.delTemp(): Sucessfully deleted final files.
16-2-17 8:20:30.964 | UpOperation     | Test worker    | INFO : Persisting local SQL database (new database version A/(A4,B2)/T=1487233230960) ...
16-2-17 8:20:30.964 | UpOperation     | Test worker    | INFO : Removing DIRTY database versions from database ...
16-2-17 8:20:30.966 | InternalEventBu | AsyncI/syncany | INFO : Event bus 'LocalEventBus': Posting event UpIndexMidSyncExternalEvent (org.syncany.operations.daemon.messages.UpIndexMidSyncExternalEvent@5d45f127) ...
16-2-17 8:20:30.969 | UpOperation     | Test worker    | INFO : Adding database version to result changes:DatabaseVersion [header=A/(A4,B2)/T=1487233230960, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.969 | UpOperation     | Test worker    | INFO : Committing local database.
16-2-17 8:20:30.969 | UpOperation     | Test worker    | FINE : Waiting for new database version.
16-2-17 8:20:30.971 | AsyncIndexer    | AsyncI/syncany | INFO : Stopping indexing. Signal end of stream with empty databaseversion
16-2-17 8:20:30.971 | UpOperation     | Test worker    | FINE : Took new database version: DatabaseVersion [header=UnknownMachine/()/T=1487233230971, chunks=0, multiChunks=0, fileContents=0, fileHistories=0]
16-2-17 8:20:30.971 | UpOperation     | Test worker    | INFO : Sync up done.
16-2-17 8:20:30.973 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-up-A-1487233230947] ...
16-2-17 8:20:30.973 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-up-A-1487233230947]
16-2-17 8:20:30.973 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.974 | Cache           | Test worker    | INFO : Cache size okay (54 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.974 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event UpEndSyncExternalEvent (org.syncany.operations.daemon.messages.UpEndSyncExternalEvent@74ec1c90) ...
16-2-17 8:20:30.974 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.974 | org.syncany.plu | Test worker    | FINE : Validating required fields
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : Building LocalTransferManager from config 'syncany-170216081829395-20216-client-B' ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature ReadAfterWriteConsistent
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature Retriable
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature PathAware
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - With feature TransactionAware
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking if selected features supported ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking for duplicate features ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking required feature TransactionAware in LocalTransferManager ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Checking required feature Retriable in LocalTransferManager ...
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature ReadAfterWriteConsistent
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Wrapping TransferManager LocalTransferManager in RetriableFeatureTransferManager
16-2-17 8:20:30.974 | TransferManager | Test worker    | INFO : - SKIPPING unsupported optional feature PathAware
16-2-17 8:20:30.974 | TransferManager | Test worker    | FINE : - Wrapping TransferManager RetriableFeatureTransferManager in TransactionAwareFeatureTransferManager
16-2-17 8:20:30.975 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.975 | DownOperation   | Test worker    | INFO : 
16-2-17 8:20:30.975 | DownOperation   | Test worker    | INFO : Running 'Sync down' at client B ...
16-2-17 8:20:30.975 | DownOperation   | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.975 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownStartSyncExternalEvent (org.syncany.operations.daemon.messages.DownStartSyncExternalEvent@6666ba1e) ...
16-2-17 8:20:30.975 | AbstractTransfe | Test worker    | INFO : Looking for other running remote operations ...
16-2-17 8:20:30.976 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : 
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : Running 'Remote Status' at client B ...
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : --------------------------------------------
16-2-17 8:20:30.976 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteStartSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteStartSyncExternalEvent@1e00545b) ...
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : Retrieving remote database list.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000004 is new.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000003 is already known (in local database). Ignoring.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000002 is already known (in local database). Ignoring.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-B-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.976 | LsRemoteOperati | Test worker    | INFO : - Remote database database-A-0000000001 is already known (in local database). Ignoring.
16-2-17 8:20:30.976 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event LsRemoteEndSyncExternalEvent (org.syncany.operations.daemon.messages.LsRemoteEndSyncExternalEvent@20f78d1e) ...
16-2-17 8:20:30.977 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownChangesDetectedSyncExternalEvent (org.syncany.operations.daemon.messages.DownChangesDetectedSyncExternalEvent@4c0ffc75) ...
16-2-17 8:20:30.977 | ActionFileHandl | Test worker    | INFO : Starting action for RemoteFile[name=action-down-B-1487233230974] ...
16-2-17 8:20:30.977 | ActionFileHandl | Test worker    | INFO : Uploading action file: RemoteFile[name=action-down-B-1487233230974]
16-2-17 8:20:30.977 | ActionFileHandl | Test worker    | INFO : Scheduling action renewal task for every 2 minutes, for RemoteFile[name=action-down-B-1487233230974] ...
16-2-17 8:20:30.977 | DownOperation   | Test worker    | INFO : Downloading unknown databases.
16-2-17 8:20:30.977 | DownOperation   | Test worker    | INFO : - Downloading database-A-0000000004 to local cache at /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000004
16-2-17 8:20:30.977 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownDownloadFileSyncExternalEvent (org.syncany.operations.daemon.messages.DownDownloadFileSyncExternalEvent@2cb9e156) ...
16-2-17 8:20:30.978 | DownOperation   | Test worker    | INFO : Loading database headers, creating branches ...
16-2-17 8:20:30.978 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (HEADER_ONLY) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000004 ...
16-2-17 8:20:30.979 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A4,B2)/T=1487233230960
16-2-17 8:20:30.979 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.979 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-B-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.979 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000004; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.980 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000002; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.980 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000001; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.980 | LocalTransferMa | Test worker    | INFO : Cannot create instance of CleanupRemoteFile for file /tmp/syncanytest/syncany-170216081829395-20216-repo/databases/database-A-0000000003; maybe invalid file name pattern. Ignoring file.
16-2-17 8:20:30.980 | ApplicationSqlD | Test worker    | INFO : SQL (general_settings): Read cleanupNumber  = (not set)
16-2-17 8:20:30.980 | DownOperation   | Test worker    | INFO : Populated unknown branches: {A=[A/(A4,B2)/T=1487233230960], B=[A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809, B/(A3,B2)/T=1487233230889]}
16-2-17 8:20:30.980 | DownOperation   | Test worker    | INFO : Determine winner using database reconciliator ...
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A1)/T=1487233230521
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Adding database version to winning branch: A/(A4,B2)/T=1487233230960
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : - Winner is A with branch: 
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + A/(A1)/T=1487233230521
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + B/(A1,B1)/T=1487233230684
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + A/(A2,B1)/T=1487233230737
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + A/(A3,B1)/T=1487233230809
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + B/(A3,B2)/T=1487233230889
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO :   + A/(A4,B2)/T=1487233230960
16-2-17 8:20:30.980 | DownOperation   | Test worker    | INFO : - Database versions to REMOVE locally: []
16-2-17 8:20:30.980 | DownOperation   | Test worker    | INFO :   + Nothing to purge locally. No conflicts. Only updates. Nice!
16-2-17 8:20:30.980 | DatabaseReconci | Test worker    | INFO : Finding winnersApplyBranch.
16-2-17 8:20:30.981 | DatabaseReconci | Test worker    | INFO : Losers Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809, B/(A3,B2)/T=1487233230889]
16-2-17 8:20:30.981 | DatabaseReconci | Test worker    | INFO : Winners Branch: [A/(A1)/T=1487233230521, B/(A1,B1)/T=1487233230684, A/(A2,B1)/T=1487233230737, A/(A3,B1)/T=1487233230809, B/(A3,B2)/T=1487233230889, A/(A4,B2)/T=1487233230960]
16-2-17 8:20:30.981 | DownOperation   | Test worker    | INFO : - Cleanup occurred: false
16-2-17 8:20:30.981 | DownOperation   | Test worker    | INFO : - Database versions to APPLY locally: [A/(A4,B2)/T=1487233230960]
16-2-17 8:20:30.981 | DownOperation   | Test worker    | INFO : Loading winners database (DEFAULT) ...
16-2-17 8:20:30.981 | DatabaseXmlSeri | Test worker    | INFO : - Loading database (FULL) from file /tmp/syncanytest/syncany-170216081829395-20216-client-B/.syncany/cache/database-A-0000000004 ...
16-2-17 8:20:30.982 | DatabaseXmlPars | Test worker    | INFO :    + Added database version A/(A4,B2)/T=1487233230960
16-2-17 8:20:30.982 | DownOperation   | Test worker    | INFO : Determine file system actions ...
16-2-17 8:20:30.983 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.983 | FileSystemActio | Test worker    | INFO : - Loading current file tree...
16-2-17 8:20:30.983 | FileSystemActio | Test worker    | INFO : - Determine filesystem actions ...
16-2-17 8:20:30.983 | FileSystemActio | Test worker    | INFO :   + Comparing local version: FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.983 | FileSystemActio | Test worker    | INFO :     with winning version   : FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.984 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = A-moved, but actual PATH = B-moved, for file B-moved
16-2-17 8:20:30.984 | FileSystemActio | Test worker    | INFO :      -> (12) Rename / Changed file attributes: Local file has different file attributes: local file = /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved, local version = FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], winning version = FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]
16-2-17 8:20:30.984 | FileSystemActio | Test worker    | INFO :      -> RenameFileSystemAction [file1=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.984 | Downloader      | Test worker    | INFO : Downloading and extracting multichunks ...
16-2-17 8:20:30.984 | FileSystemActio | Test worker    | INFO :    Sorted actions:
16-2-17 8:20:30.984 | FileSystemActio | Test worker    | INFO :    + RenameFileSystemAction [file1=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.984 | DownOperation   | Test worker    | FINE : - Applying file system actions (sorted!) ...
16-2-17 8:20:30.984 | DownOperation   | Test worker    | FINE :    +  RenameFileSystemAction [file1=FileVersion [version=5, path=B-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-], file2=FileVersion [version=6, path=A-moved, type=FILE, status=CHANGED, size=51200, lastModified=Thu Feb 16 08:20:30 UTC 2017, linkTarget=null, checksum=286eab6a0bcabc8fb6b685a58bc380f9eda6330c, updated=Thu Feb 16 08:20:30 UTC 2017, posixPermissions=rw-rw-r--, dosAttributes=--a-]]
16-2-17 8:20:30.985 | FileSystemActio | Test worker    | INFO :      - (1) Renaming file /tmp/syncanytest/syncany-170216081829395-20216-client-B/B-moved to /tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved ...
16-2-17 8:20:30.985 | FileSystemActio | Test worker    | INFO :      - Setting POSIX permissions: rw-rw-r-- ...
16-2-17 8:20:30.985 | DownOperation   | Test worker    | INFO : - Adding database versions to SQL database ...
16-2-17 8:20:30.985 | DownOperation   | Test worker    | INFO :   + Applying database version (A4,B2)
16-2-17 8:20:30.985 | DownOperation   | Test worker    | FINE :   + Contents: DatabaseVersion [header=A/(A4,B2)/T=1487233230960, chunks=0, multiChunks=0, fileContents=0, fileHistories=1]
16-2-17 8:20:30.991 | ActionFileHandl | Test worker    | INFO : Finishing action for RemoteFile[name=action-down-B-1487233230974] ...
16-2-17 8:20:30.991 | ActionFileHandl | Test worker    | INFO : Deleting action file: RemoteFile[name=action-down-B-1487233230974]
16-2-17 8:20:30.991 | AbstractTransfe | Test worker    | INFO : Cleaning own old action files ...
16-2-17 8:20:30.991 | Cache           | Test worker    | INFO : Cache size okay (54 KB), no need to clean (keep size is 500 MB)
16-2-17 8:20:30.992 | InternalEventBu | Test worker    | INFO : Event bus 'LocalEventBus': Posting event DownEndSyncExternalEvent (org.syncany.operations.daemon.messages.DownEndSyncExternalEvent@3f3bd69d) ...
16-2-17 8:20:30.992 | DownOperation   | Test worker    | INFO : Sync down done.
16-2-17 8:20:30.996 | FileVersionComp | Test worker    | INFO :      - [CHANGED_PATH]: Local file DIFFERS from file version, expected PATH = tmp/syncanytest/syncany-170216081829395-20216-client-A/A-moved, but actual PATH = tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved, for file tmp/syncanytest/syncany-170216081829395-20216-client-B/A-moved
16-2-17 8:20:30.996 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:30.997 | DatabaseConnect | Test worker    | INFO : Found 12 tables.
16-2-17 8:20:31.018 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from chunk order by CHECKSUM asc
16-2-17 8:20:31.019 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select STATUS, LOCALTIME, CLIENT, VECTORCLOCK_SERIALIZED from databaseversion order by ID asc
16-2-17 8:20:31.020 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CLIENT, LOGICALTIME from databaseversion_vectorclock order by DATABASEVERSION_ID asc, CLIENT asc
16-2-17 8:20:31.020 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select CHECKSUM, SIZE from filecontent order by CHECKSUM asc
16-2-17 8:20:31.021 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILECONTENT_CHECKSUM, CHUNK_CHECKSUM, NUM from filecontent_chunk order by FILECONTENT_CHECKSUM asc, CHUNK_CHECKSUM asc, NUM asc
16-2-17 8:20:31.021 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID from filehistory order by ID asc, DATABASEVERSION_ID asc
16-2-17 8:20:31.022 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select FILEHISTORY_ID, VERSION, PATH, TYPE, STATUS, SIZE, LASTMODIFIED, LINKTARGET, FILECONTENT_CHECKSUM, UPDATED, POSIXPERMS, DOSATTRS from fileversion order by FILEHISTORY_ID asc, VERSION asc, DATABASEVERSION_ID asc
16-2-17 8:20:31.022 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select ID, SIZE from multichunk order by ID asc
16-2-17 8:20:31.023 | TestAssertUtil  | Test worker    | FINE :  Comparing database table: select MULTICHUNK_ID, CHUNK_CHECKSUM from multichunk_chunk order by MULTICHUNK_ID asc, CHUNK_CHECKSUM asc