Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-17455

Drive: security updates sometimes irrelevant in change summary

    XMLWordPrintable

    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

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  PagerDuty

                  Error rendering 'com.pagerduty.jira-server-plugin:PagerDuty'. Please contact your Jira administrators.