[NXP-17455] Drive: security updates sometimes irrelevant in change summary - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 7.3
Fix Version/s: 6.0-HF16, 7.4
Component/s: Nuxeo Drive

Sprint:
Drive V2 EA feedback
Story Points:
3

Description

As shown by the frequent random failures at line 159, in test_file_readonly_change:

13:31:23 [INFO]      [exec] ======================================================================
13:31:23 [INFO]      [exec] FAIL: test_file_readonly_change (nxdrive.tests.test_readonly.TestReadOnly)
13:31:23 [INFO]      [exec] ----------------------------------------------------------------------
13:31:23 [INFO]      [exec] Traceback (most recent call last):
13:31:23 [INFO]      [exec]   File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_readonly.py", line 159, in test_file_readonly_change
13:31:23 [INFO]      [exec]     self.assertTrue(self.touch(fname))
13:31:23 [INFO]      [exec] AssertionError: False is not true
13:31:23 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
13:31:23 [INFO]      [exec] nxdrive.osi: DEBUG: Using Darwin OS integration
13:31:23 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
13:31:23 [INFO]      [exec] nxdrive.osi: DEBUG: Using Darwin OS integration
13:31:23 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"cc3a6889-d0b0-4e9e-95cc-9f022fdea00a","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"cc3a6889-d0b0-4e9e-95cc-9f022fdea00a","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":null,"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":null,"dc:modified":null,"dc:lastContributor":null,"dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":null,"dc:title":null,"dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":[],"dc:source":null,"dc:publisher":null},"facets":["Folderish","NotCollectionMember"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"userNames": "user_1, user_2", "permission": "ReadWrite"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] has content-type 'text/plain;charset=UTF-8'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_a277e8421fe411e59685002500d3a152.db
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_a277e8421fe411e59685002500d3a152.db (dir exists: 1 / file exists: 0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Mac+OSX+Desktop&revoke=false&deviceId=a26327111fe411e5836e002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '05fb1b0c-0c16-44d2-a761-e6c2effa92e8' with cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.4-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'7.4-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":481,"creator":"system","folder":true,"lastContributor":"system","lastModificationDate":481,"parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/, remote_ref=None]
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|a26327111fe411e5836e002500d3a152|a277e8421fe411e59685002500d3a152' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_a28f92451fe411e58820002500d3a152.db
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_a28f92451fe411e58820002500d3a152.db (dir exists: 1 / file exists: 0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'a26435421fe411e5bd23002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjphODBhYmM='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Mac+OSX+Desktop&revoke=false&deviceId=a26435421fe411e5bd23002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'a26435421fe411e5bd23002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjphODBhYmM='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '3b899796-7cfa-42b6-83dd-662e4fff3db0' with cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '3b899796-7cfa-42b6-83dd-662e4fff3db0', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26435421fe411e5bd23002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.4-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'7.4-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '3b899796-7cfa-42b6-83dd-662e4fff3db0', 'X-Device-Id': 'a26435421fe411e5bd23002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '3b899796-7cfa-42b6-83dd-662e4fff3db0', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26435421fe411e5bd23002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":651,"creator":"system","folder":true,"lastContributor":"system","lastModificationDate":651,"parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_2"}'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/Nuxeo Drive/, remote_ref=None]
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|a26435421fe411e5bd23002500d3a152|a28f92451fe411e58820002500d3a152' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp21sjIp-nxdrive-tests-user-2/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"6dfeb987-4825-4e79-9cdf-a2feb855583c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cbf0ec6f-2620-4ef5-8a5e-203e994cafbf","isCheckedOut":true,"changeToken":"1435750254311","title":"Nuxeo Drive Test Workspace","lastModified":"2015-07-01T11:30:54.31Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-07-01T11:30:54.31Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:30:54.31Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"params": {"value": "6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"6dfeb987-4825-4e79-9cdf-a2feb855583c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cbf0ec6f-2620-4ef5-8a5e-203e994cafbf","isCheckedOut":true,"changeToken":"1435750254311","title":"Nuxeo Drive Test Workspace","lastModified":"2015-07-01T11:30:54.31Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-07-01T11:30:54.31Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:30:54.31Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjphODBhYmM='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjphODBhYmM='}, cookies [] and JSON payload '{"params": {"value": "6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"6dfeb987-4825-4e79-9cdf-a2feb855583c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cbf0ec6f-2620-4ef5-8a5e-203e994cafbf","isCheckedOut":true,"changeToken":"1435750254311","title":"Nuxeo Drive Test Workspace","lastModified":"2015-07-01T11:30:54.31Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-07-01T11:30:54.31Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:30:54.31Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjphODBhYmM='} and cookies []
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:6dfeb987-4825-4e79-9cdf-a2feb855583c', 'params': {'enable': True}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:6dfeb987-4825-4e79-9cdf-a2feb855583c", "params": {"enable": true}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: UnitTest thread started
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Removing xattr drive-fs-test from /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine start
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4766543872) start
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watching FS modification on : /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion' with cookies [] has content-type ''
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watchdog setup finished
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan started
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan finished in 1ms
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4773433344) start
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=True
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote full scan
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [deleted] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":401,"creator":"system","folder":true,"lastContributor":"system","lastModificationDate":401,"parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair RemoteFileInfo(name=u'Nuxeo Drive', uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', parent_uid=None, path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', folderish=True, last_modification_time=datetime.datetime(1970, 1, 1, 1, 0), last_contributor=u'system', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3121,"fileSystemChanges":[],"syncDate":1435750257000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","creationDate":1435750254311,"creator":"Administrator","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750254895,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 30, 54), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 30, 54), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[2](Folderish:True, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scan finished in 541ms
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Remote scan completed
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Init processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4772896768) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4772896768 for row 2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b63e0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=Nuxeo Drive Test Workspace, version=0] with version=0
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 0 children of '/Nuxeo Drive Test Workspace'
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b63e0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4772896768
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4772896768) end
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c]
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c]
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[2](Folderish:True, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4772896768) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4772896768 for row 2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","creationDate":1435750254311,"creator":"Administrator","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750254895,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c0b65a8>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=Nuxeo Drive Test Workspace, version=1] with version=1
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c0b65a8>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4772896768
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4772896768) end
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3121, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3121, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3131,"fileSystemChanges":[],"syncDate":1435750260000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = False, found 0 remote change(s)
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine a277e8421fe411e59685002500d3a152 stopping
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4773433344) interrupted
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Shutdown processors
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: INFO: Stopping FS Observer thread
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4766543872) interrupted
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine a277e8421fe411e59685002500d3a152 stopped
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/', 'params': {'type': 'Folder', 'name': 'Test folder', 'properties': 'dc:title=Test folder'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "Folder", "name": "Test folder", "properties": "dc:title=Test folder"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"19b3780d-a649-4c34-9f84-08feee15750c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"6dfeb987-4825-4e79-9cdf-a2feb855583c","isCheckedOut":true,"changeToken":"1435750261546","title":"Test folder","lastModified":"2015-07-01T11:31:01.54Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.54Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.54Z","dc:title":"Test folder","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'File', 'name': 'joe.odt', 'properties': 'dc:title=joe.odt'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "File", "name": "joe.odt", "properties": "dc:title=joe.odt"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/joe.odt","type":"File","state":"project","parentRef":"19b3780d-a649-4c34-9f84-08feee15750c","isCheckedOut":true,"changeToken":"1435750261585","title":"joe.odt","lastModified":"2015-07-01T11:31:01.58Z","properties":{"uid:uid":null,"uid:major_version":0,"uid:minor_version":0,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/file.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.58Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.58Z","dc:title":"joe.odt","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null,"relatedtext:relatedtextresources":[]},"facets":["Versionable","Publishable","Commentable","HasRelatedText","Downloadable"]}'
13:31:23 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'joe.odt'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 12, 'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 12, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1435750261.62_321797819', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'joe.odt'} and cookies [] for file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpdvHxhj-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1435750261.62_321797819"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpdvHxhj-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1435750261.62_321797819', 'document': u'dde2e8b2-d7d5-4191-823a-d8eace1ac340', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"params": {"batchId": "1435750261.62_321797819", "document": "dde2e8b2-d7d5-4191-823a-d8eace1ac340", "fileIdx": "0", "operationId": "Blob.Attach"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'File', 'name': 'jack.odt', 'properties': 'dc:title=jack.odt'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "File", "name": "jack.odt", "properties": "dc:title=jack.odt"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"2ebcad0c-6748-44a4-ab82-512bfcb55859","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/jack.odt","type":"File","state":"project","parentRef":"19b3780d-a649-4c34-9f84-08feee15750c","isCheckedOut":true,"changeToken":"1435750261706","title":"jack.odt","lastModified":"2015-07-01T11:31:01.70Z","properties":{"uid:uid":null,"uid:major_version":0,"uid:minor_version":0,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/file.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.70Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.70Z","dc:title":"jack.odt","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null,"relatedtext:relatedtextresources":[]},"facets":["Versionable","Publishable","Commentable","HasRelatedText","Downloadable"]}'
13:31:23 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'jack.odt'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 12, 'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 12, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1435750261.74_797672813', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'jack.odt'} and cookies [] for file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpoqkThy-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1435750261.74_797672813"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpoqkThy-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1435750261.74_797672813', 'document': u'2ebcad0c-6748-44a4-ab82-512bfcb55859', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"params": {"batchId": "1435750261.74_797672813", "document": "2ebcad0c-6748-44a4-ab82-512bfcb55859", "fileIdx": "0", "operationId": "Blob.Attach"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'Folder', 'name': 'Sub folder 1', 'properties': 'dc:title=Sub folder 1'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "Folder", "name": "Sub folder 1", "properties": "dc:title=Sub folder 1"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1","type":"Folder","state":"project","parentRef":"19b3780d-a649-4c34-9f84-08feee15750c","isCheckedOut":true,"changeToken":"1435750261809","title":"Sub folder 1","lastModified":"2015-07-01T11:31:01.80Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.80Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.80Z","dc:title":"Sub folder 1","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1', 'params': {'type': 'File', 'name': 'sub file 1.txt', 'properties': 'dc:title=sub file 1.txt'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1", "params": {"type": "File", "name": "sub file 1.txt", "properties": "dc:title=sub file 1.txt"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1/sub file 1.txt","type":"File","state":"project","parentRef":"9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","isCheckedOut":true,"changeToken":"1435750261859","title":"sub file 1.txt","lastModified":"2015-07-01T11:31:01.85Z","properties":{"uid:uid":null,"uid:major_version":0,"uid:minor_version":0,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/file.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.85Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.85Z","dc:title":"sub file 1.txt","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null,"relatedtext:relatedtextresources":[]},"facets":["Versionable","Publishable","Commentable","HasRelatedText","Downloadable"]}'
13:31:23 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'sub file 1.txt'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 7, 'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 7, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1435750261.89_565299334', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'sub%20file%201.txt'} and cookies [] for file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpq87Syt-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1435750261.89_565299334"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmpfDT8JC-nxdrive-uploads/tmpq87Syt-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1435750261.89_565299334', 'document': u'2dd0070b-4402-43ca-8880-89790e2ba9f8', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTphMzQ3OGQ='}, cookies [] and JSON payload '{"params": {"batchId": "1435750261.89_565299334", "document": "2dd0070b-4402-43ca-8880-89790e2ba9f8", "fileIdx": "0", "operationId": "Blob.Attach"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'text/plain'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'user': 'nuxeoDriveTestUser_user_1', 'permission': 'Read'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetACE with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"user": "nuxeoDriveTestUser_user_1", "permission": "Read"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetACE' with cookies []: '{"entity-type":"document","repository":"default","uid":"19b3780d-a649-4c34-9f84-08feee15750c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"6dfeb987-4825-4e79-9cdf-a2feb855583c","isCheckedOut":true,"changeToken":"1435750261546","title":"Test folder","lastModified":"2015-07-01T11:31:01.54Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.54Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.54Z","dc:title":"Test folder","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'user': 'Administrator', 'overwrite': False, 'permission': 'Everything'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetACE with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"user": "Administrator", "overwrite": false, "permission": "Everything"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetACE' with cookies []: '{"entity-type":"document","repository":"default","uid":"19b3780d-a649-4c34-9f84-08feee15750c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"6dfeb987-4825-4e79-9cdf-a2feb855583c","isCheckedOut":true,"changeToken":"1435750261546","title":"Test folder","lastModified":"2015-07-01T11:31:01.54Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.54Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.54Z","dc:title":"Test folder","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'permission': 'Everything', 'user': 'Everyone', 'overwrite': False, 'grant': 'false'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetACE with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"permission": "Everything", "user": "Everyone", "overwrite": false, "grant": "false"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetACE' with cookies []: '{"entity-type":"document","repository":"default","uid":"19b3780d-a649-4c34-9f84-08feee15750c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"6dfeb987-4825-4e79-9cdf-a2feb855583c","isCheckedOut":true,"changeToken":"1435750261546","title":"Test folder","lastModified":"2015-07-01T11:31:01.54Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.54Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.54Z","dc:title":"Test folder","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Removing xattr drive-fs-test from /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine start
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4766543872) start
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watching FS modification on : /Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watchdog setup finished
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan started
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan finished in 4ms
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4773146624) start
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion' with cookies [] has content-type ''
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=True
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3131, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3131, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3165,"fileSystemChanges":[{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","eventDate":1435750262125,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"19b3780d-a649-4c34-9f84-08feee15750c"},{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","eventDate":1435750262056,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"19b3780d-a649-4c34-9f84-08feee15750c"},{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","eventDate":1435750261987,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"19b3780d-a649-4c34-9f84-08feee15750c"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","eventDate":1435750261924,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"sub file 1.txt","docUuid":"2dd0070b-4402-43ca-8880-89790e2ba9f8"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","eventDate":1435750261859,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"sub file 1.txt","docUuid":"2dd0070b-4402-43ca-8880-89790e2ba9f8"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","eventDate":1435750261809,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","creationDate":1435750261809,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261809,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Sub folder 1","docUuid":"9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","eventDate":1435750261764,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"jack.odt","id":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","creationDate":1435750261706,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261761,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"jack.odt","docUuid":"2ebcad0c-6748-44a4-ab82-512bfcb55859"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","eventDate":1435750261706,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"jack.odt","id":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","creationDate":1435750261706,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261761,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"jack.odt","docUuid":"2ebcad0c-6748-44a4-ab82-512bfcb55859"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","eventDate":1435750261651,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261647,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"joe.odt","docUuid":"dde2e8b2-d7d5-4191-823a-d8eace1ac340"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","eventDate":1435750261585,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261647,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"joe.odt","docUuid":"dde2e8b2-d7d5-4191-823a-d8eace1ac340"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","eventDate":1435750261546,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"19b3780d-a649-4c34-9f84-08feee15750c"}],"syncDate":1435750265000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: 11 remote changes detected
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Test folder', uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', parent_uid=u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:True, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Marked doc_pair 'Test folder' as remote creation
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote recursive scan of the content of Test folder
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261647,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"downloadURL":"nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"jack.odt","id":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","creationDate":1435750261706,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261761,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","creationDate":1435750261809,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261809,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'jack.odt', uid=u'defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'Sub folder 1', uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt' (force_recursion:0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder/Sub folder 1' (force_recursion:0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair RemoteFileInfo(name=u'Sub folder 1', uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder/jack.odt' (force_recursion:0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair RemoteFileInfo(name=u'jack.odt', uid=u'defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder/joe.odt' (force_recursion:0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Init processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4773683200) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4773683200 for row 3
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b6c30>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Test folder' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder, remote_name=Test folder, version=0] with version=0
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 3 children of '/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x120b19fa0>
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[4](Folderish:0, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x120b19690>
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:0, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x1207fa230>
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[6](Folderish:1, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b6c30>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4773683200
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote file processor
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4774219776) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4773683200 for row 6
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b6c30>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Sub folder 1' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4774219776 for row 4
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'joe.odt' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', 'parentId': u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340", "parentId": "defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c"}}'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, remote_name=Sub folder 1, version=1] with version=1
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 1 children of '/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x1206aac80>
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[7](Folderish:0, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c0b6c30>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4773683200
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4773683200) end
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261647,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt' with headers: {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c]
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, remote_ref=defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e]
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, remote_ref=defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e]
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[6](Folderish:True, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 1 for pair FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder, remote_ref=defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c]
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder, remote_ref=defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c]
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:True, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/joe.odt, remote_name=joe.odt, version=1] with version=1
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4773683200) start
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4774219776
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4774219776 for row 5
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Test folder/jack.odt', Remote: defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Test folder/jack.odt', Remote: defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'jack.odt' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4773683200 for row 6
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"}}'
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/jack.odt, remote_name=jack.odt, version=1] with version=1
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","creationDate":1435750261809,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261809,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Test folder/jack.odt', Remote: defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c120218>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, remote_name=Sub folder 1, version=2] with version=2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c120218>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', Remote: defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4773683200
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4773683200 for row 3
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c"}}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Test folder/joe.odt
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Test folder/jack.odt
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4774219776
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4774219776 for row 7
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt', Remote: defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt', Remote: defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'sub file 1.txt' in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', 'parentId': u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8", "parentId": "defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c120218>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder, remote_name=Test folder, version=1] with version=1
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x11c120218>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: modified, Remote state: synchronized, State: locally_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4773683200
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4773683200) end
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt' with headers: {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, remote_name=sub file 1.txt, version=2] with version=2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x11c11bb98>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt', Remote: defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8, Local state: unknown, Remote state: created, State: remotely_created)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4774219776
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4774219776) end
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3165, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3165, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3185,"fileSystemChanges":[],"syncDate":1435750268000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = True, found 11 remote change(s)
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
13:31:23 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'joe.odt'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 29, 'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'X-File-Size': 29, 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1435750269.26_8031565', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'joe.odt'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpbU5CiI-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1435750269.26_8031565"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpbU5CiI-nxdrive-file-to-upload
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1435750269.26_8031565', 'document': u'/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/joe.odt', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"batchId": "1435750269.26_8031565", "document": "/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/joe.odt", "fileIdx": "0", "operationId": "Blob.Attach"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text'
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion' with cookies [] has content-type ''
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3185, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3185, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3192,"fileSystemChanges":[{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","eventDate":1435750269302,"repositoryId":"default","fileSystemItem":{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"699d56ed98093dcac5c735d6922baa71","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"Administrator","lastModificationDate":1435750269299,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"joe.odt","docUuid":"dde2e8b2-d7d5-4191-823a-d8eace1ac340"}],"syncDate":1435750272000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: 1 remote changes detected
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder/joe.odt' (force_recursion:0)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 9), last_contributor=u'Administrator', digest=u'699d56ed98093dcac5c735d6922baa71', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 9), last_contributor=u'Administrator', digest=u'699d56ed98093dcac5c735d6922baa71', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[4](Folderish:False, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote file processor
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4772073472) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4772073472 for row 4
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is active, overall size = 0, empty polls count = 0
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x11c120f28>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Updating content of local file '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'.
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', 'parentId': u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340", "parentId": "defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"699d56ed98093dcac5c735d6922baa71","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"Administrator","lastModificationDate":1435750269299,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt' with headers: {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 2 ko/s
13:31:23 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340' on u'/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder/joe.odt, remote_name=joe.odt, version=2] with version=2
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x11c120f28>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', Remote: defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4772073472
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4772073472) end
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [deleted] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Test folder/joe.odt
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair FileInfo[/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/tmp/tmp47HQsI-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder, remote_ref=defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c]
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3192, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3192, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3198,"fileSystemChanges":[],"syncDate":1435750275000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = True, found 1 remote change(s)
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'permission': 'Write', 'user': 'nuxeoDriveTestUser_user_1', 'grant': 'true'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetACE with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"permission": "Write", "user": "nuxeoDriveTestUser_user_1", "grant": "true"}}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3198, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3198, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3202,"fileSystemChanges":[{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","eventDate":1435750276413,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","creationDate":1435750261546,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261546,"parentId":"defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"19b3780d-a649-4c34-9f84-08feee15750c"}],"syncDate":1435750278000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: 1 remote changes detected
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Test folder' (force_recursion:1)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 3 for pair RemoteFileInfo(name=u'Test folder', uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', parent_uid=u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Test folder', uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', parent_uid=u'defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:True, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
13:31:23 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c"}}'
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4772335616) start
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4772335616 for row 3
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x11c1333e0>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.processor: DEBUG: No local impact of metadata update on document 'Test folder'.
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Test folder, remote_name=Test folder, version=3] with version=3
13:31:23 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x11c1333e0>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Test folder', Remote: defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c, Local state: synchronized, Remote state: modified, State: remotely_modified)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4772335616
13:31:23 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4772335616) end
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"699d56ed98093dcac5c735d6922baa71","name":"joe.odt","id":"defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340","creationDate":1435750261585,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"Administrator","lastModificationDate":1435750269299,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"downloadURL":"nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt","digestAlgorithm":"md5","canUpdate":false,"digest":"b53227da4280f0e18270f21dd77c91d0","name":"jack.odt","id":"defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859","creationDate":1435750261706,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261761,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","creationDate":1435750261809,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261809,"parentId":"defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 9), last_contributor=u'Administrator', digest=u'699d56ed98093dcac5c735d6922baa71', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 3 for pair RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#dde2e8b2-d7d5-4191-823a-d8eace1ac340', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 9), last_contributor=u'Administrator', digest=u'699d56ed98093dcac5c735d6922baa71', digest_algorithm=u'md5', download_url=u'nxbigfile/default/dde2e8b2-d7d5-4191-823a-d8eace1ac340/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'jack.odt', uid=u'defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 2 for pair RemoteFileInfo(name=u'jack.odt', uid=u'defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#2ebcad0c-6748-44a4-ab82-512bfcb55859', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2ebcad0c-6748-44a4-ab82-512bfcb55859/blobholder:0/jack.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'Sub folder 1', uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 3 for pair RemoteFileInfo(name=u'Sub folder 1', uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', parent_uid=u'defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', folderish=True, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt","digestAlgorithm":"md5","canUpdate":false,"digest":"f15c1cae7882448b3fb0404682e17e61","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8","creationDate":1435750261859,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1435750261921,"parentId":"defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: TRACE: Scanning remote child: RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Increasing version to 3 for pair RemoteFileInfo(name=u'sub file 1.txt', uid=u'defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', parent_uid=u'defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6dfeb987-4825-4e79-9cdf-a2feb855583c/defaultFileSystemItemFactory#default#19b3780d-a649-4c34-9f84-08feee15750c/defaultFileSystemItemFactory#default#9b1a1b7d-e4ae-47fc-ab83-416fb2f54d6e/defaultFileSystemItemFactory#default#2dd0070b-4402-43ca-8880-89790e2ba9f8', folderish=False, last_modification_time=datetime.datetime(2015, 7, 1, 13, 31, 1), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxbigfile/default/2dd0070b-4402-43ca-8880-89790e2ba9f8/blobholder:0/sub%20file%201.txt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 0
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetACE' with cookies []: '{"entity-type":"document","repository":"default","uid":"19b3780d-a649-4c34-9f84-08feee15750c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"6dfeb987-4825-4e79-9cdf-a2feb855583c","isCheckedOut":true,"changeToken":"1435750261546","title":"Test folder","lastModified":"2015-07-01T11:31:01.54Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-07-01T11:31:01.54Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-07-01T11:31:01.54Z","dc:title":"Test folder","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}'
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForElasticsearchCompletion' with cookies [] has content-type ''
13:31:23 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes, first_pass=False
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3202, 'lastSyncActiveRootDefinitions': u'default:6dfeb987-4825-4e79-9cdf-a2feb855583c'}}
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '05fb1b0c-0c16-44d2-a761-e6c2effa92e8', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'a26327111fe411e5836e002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3202, "lastSyncActiveRootDefinitions": "default:6dfeb987-4825-4e79-9cdf-a2feb855583c"}}'
13:31:23 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":3210,"fileSystemChanges":[],"syncDate":1435750282000,"activeSynchronizationRootDefinitions":"default:6dfeb987-4825-4e79-9cdf-a2feb855583c","hasTooManyChanges":false}'
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
13:31:23 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = True, found 1 remote change(s)
13:31:23 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
13:31:23 [INFO]      [exec] nxdrive.tests.test_readonly: DEBUG: Exception occurs during touch: IOError(13, 'Permission denied')
13:31:23 [INFO]      [exec] --------------------- >> end captured logging << ---------------------

If NuxeoDrive.GetChangeSummary is called just after Document.SetACE but before the transaction is commited, then the change summary might hold a "securityUpdated" event with an irrelevant FileSystemItem:

Document.SetACE calls CoreSession.setACP that fires "beforeDocumentSecurityModification".
NuxeoDriveFileSystemDeletionListener reacts to this event synchronously and adds the "securityUpdated" virtual event to audit logs.
NuxeoDrive.GetChangeSummary is called and returns this event with a FileSystemItem badly adapted by AuditChangeFinder as ACE change has not been commited yet, for instance in the failing test case we grant Write to the test user but as it is not taken into account the local folder is still readonly at assertion time.
Transaction is finally commited.

=> We probably need to make NuxeoDriveFileSystemDeletionListener log the virtual events in an asynchronous way!

Attachments

Issue Links

depends on

NXP-15859 Fix elasticsearch audit + nuxeo drive

Resolved

NXDRIVE-228 Fix random readonly test issues

Resolved

NXP-17236 Use Elasticsearch as a default audit backend in CAP

Resolved

is required by

NXP-17389 Drive + Elasticsearch audit: fix functional tests randomly failing because of missing events in change summary

Resolved

Activity

People

Assignee:

Antoine Taillefer

Reporter:

Antoine Taillefer

Participants:

Antoine Taillefer, Jenkins

Votes:

0 Vote for this issue

Watchers:

2 Start watching this issue

Dates

Created:

2015-07-07 08:31

Updated:

2015-07-10 07:28

Resolved:

2015-07-07 14:46