Uploaded image for project: 'Nuxeo Drive '
  1. Nuxeo Drive
  2. NXDRIVE-314

Readonly deleted folder not re-created in test_rename_readonly_file

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 2.0.0626
    • Fix Version/s: 2.0.818
    • Component/s: Synchronizer, Tests
    • Sprint:
      Drive Next, Drive August
    • Story Points:
      2

      Description

      As we can see in http://qa.nuxeo.org/jenkins/view/Drive/job/FT-nuxeo-drive-master-osx/405/consoleFull

      18:43:41 [INFO]      [exec] ======================================================================
18:43:41 [INFO]      [exec] FAIL: test_rename_readonly_file (nxdrive.tests.test_readonly.TestReadOnly)
18:43:41 [INFO]      [exec] ----------------------------------------------------------------------
18:43:41 [INFO]      [exec] Traceback (most recent call last):
18:43:41 [INFO]      [exec]   File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_readonly.py", line 90, in test_rename_readonly_file
18:43:41 [INFO]      [exec]     self.assertTrue(local.exists(delete_folder))
18:43:41 [INFO]      [exec] AssertionError: False is not true
18:43:41 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
18:43:41 [INFO]      [exec] nxdrive.osi: DEBUG: Using Darwin OS integration
18:43:41 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
18:43:41 [INFO]      [exec] nxdrive.osi: DEBUG: Using Darwin OS integration
18:43:41 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
18:43:41 [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 []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
18:43:41 [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": "/"}}'
18:43:41 [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":"c2bebf52-873e-498c-b215-974c969693ef","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"c2bebf52-873e-498c-b215-974c969693ef","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"]}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
18:43:41 [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"}}'
18:43:41 [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'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_01400145eaa111e48d1e002500d3a152.db
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_01400145eaa111e48d1e002500d3a152.db (dir exists: 1 / file exists: 0)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
18:43:41 [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': '00d08baeeaa111e4abac002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='} and cookies []
18:43:41 [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=00d08baeeaa111e4abac002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='} and cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '794b832c-27c2-4a52-9fbd-c5d7f695360b' with cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": {}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"updateSiteURL":"http://community.nuxeo.com/static/drive/","serverVersion":"7.3-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'7.3-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": {}}'
18:43:41 [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":90,"creator":"system","folder":true,"lastModificationDate":90,"lastContributor":"system","parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/, remote_ref=None]
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|00d08baeeaa111e4abac002500d3a152|01400145eaa111e48d1e002500d3a152' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_01564ee1eaa111e48663002500d3a152.db
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_01564ee1eaa111e48663002500d3a152.db (dir exists: 1 / file exists: 0)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
18:43:41 [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': '00d16ec0eaa111e4bc99002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpmNWFhNjM='} and cookies []
18:43:41 [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=00d16ec0eaa111e4bc99002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '00d16ec0eaa111e4bc99002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpmNWFhNjM='} and cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token 'ba74ac9c-f621-4f46-abde-baa43aaa3403' with cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'ba74ac9c-f621-4f46-abde-baa43aaa3403', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d16ec0eaa111e4bc99002500d3a152', '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": {}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"updateSiteURL":"http://community.nuxeo.com/static/drive/","serverVersion":"7.3-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'7.3-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'ba74ac9c-f621-4f46-abde-baa43aaa3403', 'X-Device-Id': '00d16ec0eaa111e4bc99002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'ba74ac9c-f621-4f46-abde-baa43aaa3403', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d16ec0eaa111e4bc99002500d3a152', '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": {}}'
18:43:41 [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":227,"creator":"system","folder":true,"lastModificationDate":227,"lastContributor":"system","parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_2"}'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/Nuxeo Drive/, remote_ref=None]
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|00d16ec0eaa111e4bc99002500d3a152|01564ee1eaa111e48663002500d3a152' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmppCL1I4-nxdrive-tests-user-2/Nuxeo Drive'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
18:43:41 [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"}}'
18:43:41 [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":"d308d235-ea09-4baf-9f3c-d042632c74e1","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"ae8f6bad-3115-4da0-8dc3-100669c50259","isCheckedOut":true,"changeToken":"1429893795309","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-24T16:43:15.30Z","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-04-24T16:43:15.30Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:15.30Z","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"]}'
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='} and cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'd308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"value": "d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [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":"d308d235-ea09-4baf-9f3c-d042632c74e1","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"ae8f6bad-3115-4da0-8dc3-100669c50259","isCheckedOut":true,"changeToken":"1429893795309","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-24T16:43:15.30Z","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-04-24T16:43:15.30Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:15.30Z","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"]}'
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpmNWFhNjM='} and cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'd308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpmNWFhNjM='}, cookies [] and JSON payload '{"params": {"value": "d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [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":"d308d235-ea09-4baf-9f3c-d042632c74e1","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"ae8f6bad-3115-4da0-8dc3-100669c50259","isCheckedOut":true,"changeToken":"1429893795309","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-24T16:43:15.30Z","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-04-24T16:43:15.30Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:15.30Z","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"]}'
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='} and cookies []
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpmNWFhNjM='} and cookies []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:d308d235-ea09-4baf-9f3c-d042632c74e1', 'params': {'enable': True}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"input": "doc:d308d235-ea09-4baf-9f3c-d042632c74e1", "params": {"enable": true}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: UnitTest thread started
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Removing xattr drive-fs-test from /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine start
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion 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": {}}'
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4932796416) start
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watching FS modification on : /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watchdog setup finished
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan started
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Found new file /Icon
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Icon
18:43:41 [INFO]      [exec] , remote_ref=None]nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[2](Folderish:0, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_file_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan finished in 3ms
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4933332992) start
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [deleted] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote full scan
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#"}}'
18:43:41 [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":628,"creator":"system","folder":true,"lastModificationDate":628,"lastContributor":"system","parentId":null,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": {}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":2625,"fileSystemChanges":[],"syncDate":1429893798000,"activeSynchronizationRootDefinitions":"default:d308d235-ea09-4baf-9f3c-d042632c74e1","hasTooManyChanges":false}'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#"}}'
18:43:41 [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#d308d235-ea09-4baf-9f3c-d042632c74e1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","creationDate":1429893795309,"creator":"Administrator","folder":true,"lastModificationDate":1429893796473,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}]'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1', folderish=True, last_modification_time=datetime.datetime(2015, 4, 24, 18, 43, 16), 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)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:1, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scan finished in 76ms
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Remote scan completed
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Init processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local file processor
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFileProcessor(4934393856) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4934930432) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 2
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934930432 for row 3
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db5a8>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[2](Local: /Icon
18:43:41 [INFO]      [exec] , Remote: None, Local state: created, Remote state: unknown, State: locally_created)nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260db478>> on doc pair StateRow[2](Local: /Icon
18:43:41 [INFO]      [exec] , Remote: None, Local state: created, Remote state: unknown, State: locally_created)nxdrive.engine.processor: WARNING: Won't synchronize file 'Icon
18:43:41 [INFO]      [exec] ' created in local folder '' since it is readonlynxdrive.engine.processor: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260db478>> on doc pair StateRow[2](Local: /Icon
18:43:41 [INFO]      [exec] , Remote: None, Local state: created, Remote state: unknown, State: locally_created)nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFileProcessor(4934393856) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 0 children of '/Nuxeo Drive Test Workspace'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db5a8>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934930432
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4934930432) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1]
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:1, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4934393856) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 3
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [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#d308d235-ea09-4baf-9f3c-d042632c74e1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","creationDate":1429893795309,"creator":"Administrator","folder":true,"lastModificationDate":1429893796473,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1260dbb98>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1260dbb98>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4934393856) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 2625, 'lastSyncActiveRootDefinitions': u'default:d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": 2625, "lastSyncActiveRootDefinitions": "default:d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":2633,"fileSystemChanges":[],"syncDate":1429893802000,"activeSynchronizationRootDefinitions":"default:d308d235-ea09-4baf-9f3c-d042632c74e1","hasTooManyChanges":false}'
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = False, found 0 remote change(s)
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine 01400145eaa111e48d1e002500d3a152 stopping
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4933332992) interrupted
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: INFO: Stopping FS Observer thread
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4932796416) interrupted
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine 01400145eaa111e48d1e002500d3a152 stopped
18:43:41 [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'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "Folder", "name": "Test folder", "properties": "dc:title=Test folder"}}'
18:43:41 [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":"cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"d308d235-ea09-4baf-9f3c-d042632c74e1","isCheckedOut":true,"changeToken":"1429893804847","title":"Test folder","lastModified":"2015-04-24T16:43:24.84Z","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-04-24T16:43:24.84Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:24.84Z","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"]}'
18:43:41 [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'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, 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"}}'
18:43:41 [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":"6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/joe.odt","type":"File","state":"project","parentRef":"cedf2ced-03b6-4bf3-aa57-696218265e13","isCheckedOut":true,"changeToken":"1429893807325","title":"joe.odt","lastModified":"2015-04-24T16:43:27.32Z","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-04-24T16:43:27.32Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:27.32Z","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"]}'
18:43:41 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'joe.odt'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429893807.39_574005438', '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/tmpu9tjaR-nxdrive-uploads/tmpB_VL17-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429893807.39_574005438"}'
18:43:41 [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/tmpu9tjaR-nxdrive-uploads/tmpB_VL17-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429893807.39_574005438', 'document': u'6916a83c-d258-47d0-8ee7-e08e98be4df6', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"batchId": "1429893807.39_574005438", "document": "6916a83c-d258-47d0-8ee7-e08e98be4df6", "fileIdx": "0", "operationId": "Blob.Attach"}}'
18:43:41 [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'
18:43:41 [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'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, 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"}}'
18:43:41 [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":"514a2130-cb33-4c67-a673-c923638f9915","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/jack.odt","type":"File","state":"project","parentRef":"cedf2ced-03b6-4bf3-aa57-696218265e13","isCheckedOut":true,"changeToken":"1429893807494","title":"jack.odt","lastModified":"2015-04-24T16:43:27.49Z","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-04-24T16:43:27.49Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:27.49Z","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"]}'
18:43:41 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'jack.odt'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429893807.61_603707229', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'jack.odt'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpu9tjaR-nxdrive-uploads/tmpAlkRfl-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429893807.61_603707229"}'
18:43:41 [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/tmpu9tjaR-nxdrive-uploads/tmpAlkRfl-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429893807.61_603707229', 'document': u'514a2130-cb33-4c67-a673-c923638f9915', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"batchId": "1429893807.61_603707229", "document": "514a2130-cb33-4c67-a673-c923638f9915", "fileIdx": "0", "operationId": "Blob.Attach"}}'
18:43:41 [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'
18:43:41 [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'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, 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"}}'
18:43:41 [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":"d93d5b9a-f373-4910-874a-42efbdb9f782","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1","type":"Folder","state":"project","parentRef":"cedf2ced-03b6-4bf3-aa57-696218265e13","isCheckedOut":true,"changeToken":"1429893807750","title":"Sub folder 1","lastModified":"2015-04-24T16:43:27.75Z","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-04-24T16:43:27.75Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:27.75Z","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"]}'
18:43:41 [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'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, 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"}}'
18:43:41 [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":"41256e54-4ead-4ca4-9476-04239ea94d51","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1/sub file 1.txt","type":"File","state":"project","parentRef":"d93d5b9a-f373-4910-874a-42efbdb9f782","isCheckedOut":true,"changeToken":"1429893807826","title":"sub file 1.txt","lastModified":"2015-04-24T16:43:27.82Z","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-04-24T16:43:27.82Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:27.82Z","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"]}'
18:43:41 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'sub file 1.txt'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429893807.87_410209736', '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 /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpu9tjaR-nxdrive-uploads/tmpLEkHwy-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429893807.87_410209736"}'
18:43:41 [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/tmpu9tjaR-nxdrive-uploads/tmpLEkHwy-nxdrive-file-to-upload
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429893807.87_410209736', 'document': u'41256e54-4ead-4ca4-9476-04239ea94d51', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
18:43:41 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"batchId": "1429893807.87_410209736", "document": "41256e54-4ead-4ca4-9476-04239ea94d51", "fileIdx": "0", "operationId": "Blob.Attach"}}'
18:43:41 [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'
18:43:41 [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'}}
18:43:41 [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"}}'
18:43:41 [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":"cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"d308d235-ea09-4baf-9f3c-d042632c74e1","isCheckedOut":true,"changeToken":"1429893804847","title":"Test folder","lastModified":"2015-04-24T16:43:24.84Z","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-04-24T16:43:24.84Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:24.84Z","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"]}'
18:43:41 [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'}}
18:43:41 [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"}}'
18:43:41 [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":"cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"d308d235-ea09-4baf-9f3c-d042632c74e1","isCheckedOut":true,"changeToken":"1429893804847","title":"Test folder","lastModified":"2015-04-24T16:43:24.84Z","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-04-24T16:43:24.84Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:24.84Z","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"]}'
18:43:41 [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'}}
18:43:41 [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"}}'
18:43:41 [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":"cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"d308d235-ea09-4baf-9f3c-d042632c74e1","isCheckedOut":true,"changeToken":"1429893804847","title":"Test folder","lastModified":"2015-04-24T16:43:24.84Z","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-04-24T16:43:24.84Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:24.84Z","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"]}'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Removing xattr drive-fs-test from /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine start
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(4932796416) start
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watching FS modification on : /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watchdog setup finished
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan started
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan finished in 2ms
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(4933332992) start
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion 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": {}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 2633, 'lastSyncActiveRootDefinitions': u'default:d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": 2633, "lastSyncActiveRootDefinitions": "default:d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":2669,"fileSystemChanges":[{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","eventDate":1429893808060,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","creationDate":1429893804847,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893804847,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"cedf2ced-03b6-4bf3-aa57-696218265e13"},{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","eventDate":1429893807990,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","creationDate":1429893804847,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893804847,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"cedf2ced-03b6-4bf3-aa57-696218265e13"},{"eventId":"securityUpdated","fileSystemItemId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","eventDate":1429893807952,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","creationDate":1429893804847,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893804847,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"cedf2ced-03b6-4bf3-aa57-696218265e13"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","eventDate":1429893807906,"repositoryId":"default","fileSystemItem":{"digest":"f15c1cae7882448b3fb0404682e17e61","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782/defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","creationDate":1429893807826,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807899,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"sub file 1.txt","docUuid":"41256e54-4ead-4ca4-9476-04239ea94d51"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","eventDate":1429893807826,"repositoryId":"default","fileSystemItem":{"digest":"f15c1cae7882448b3fb0404682e17e61","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782/defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","creationDate":1429893807826,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807899,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"sub file 1.txt","docUuid":"41256e54-4ead-4ca4-9476-04239ea94d51"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","eventDate":1429893807750,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","creationDate":1429893807750,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893807750,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Sub folder 1","docUuid":"d93d5b9a-f373-4910-874a-42efbdb9f782"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","eventDate":1429893807627,"repositoryId":"default","fileSystemItem":{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/514a2130-cb33-4c67-a673-c923638f9915/blobholder:0/jack.odt","name":"jack.odt","id":"defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","creationDate":1429893807494,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807624,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"jack.odt","docUuid":"514a2130-cb33-4c67-a673-c923638f9915"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","eventDate":1429893807494,"repositoryId":"default","fileSystemItem":{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/514a2130-cb33-4c67-a673-c923638f9915/blobholder:0/jack.odt","name":"jack.odt","id":"defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","creationDate":1429893807494,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807624,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"jack.odt","docUuid":"514a2130-cb33-4c67-a673-c923638f9915"},{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","eventDate":1429893807425,"repositoryId":"default","fileSystemItem":{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt","name":"joe.odt","id":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","creationDate":1429893807325,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807421,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"joe.odt","docUuid":"6916a83c-d258-47d0-8ee7-e08e98be4df6"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","eventDate":1429893807325,"repositoryId":"default","fileSystemItem":{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt","name":"joe.odt","id":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","creationDate":1429893807325,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807421,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"joe.odt","docUuid":"6916a83c-d258-47d0-8ee7-e08e98be4df6"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","eventDate":1429893804847,"repositoryId":"default","fileSystemItem":{"canCreateChild":false,"name":"Test folder","id":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","creationDate":1429893804847,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893804847,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"cedf2ced-03b6-4bf3-aa57-696218265e13"}],"syncDate":1429893811000,"activeSynchronizationRootDefinitions":"default:d308d235-ea09-4baf-9f3c-d042632c74e1","hasTooManyChanges":false}'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: 11 remote changes detected
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Test folder', uid=u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13', parent_uid=u'defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13', folderish=True, last_modification_time=datetime.datetime(2015, 4, 24, 18, 43, 24), 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)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[4](Folderish:1, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Marked doc_pair 'Test folder' as remote creation
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote recursive scan of the content of Test folder
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4809318400) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#cedf2ced-03b6-4bf3-aa57-696218265e13"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt","name":"joe.odt","id":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","creationDate":1429893807325,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807421,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/514a2130-cb33-4c67-a673-c923638f9915/blobholder:0/jack.odt","name":"jack.odt","id":"defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915","creationDate":1429893807494,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807624,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":false,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","creationDate":1429893807750,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893807750,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4809318400 for row 4
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#d93d5b9a-f373-4910-874a-42efbdb9f782"}}'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db0e8>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Test folder' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 3 children of '/Nuxeo Drive Test Workspace/Test folder'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x1260eef00>
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:0, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x1260eefa0>
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[6](Folderish:0, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x126381050>
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[7](Folderish:1, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote file processor
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db0e8>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4809318400
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4934393856) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"f15c1cae7882448b3fb0404682e17e61","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782/defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","creationDate":1429893807826,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807899,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4809318400 for row 7
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db0e8>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Sub folder 1' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
18:43:41 [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)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 1 children of '/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x1260eea00>
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[8](Folderish:0, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x1260db0e8>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 5
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4809318400
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4809318400) end
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [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)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'joe.odt' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Sub folder 1', uid=u'defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782', parent_uid=u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782', folderish=True, last_modification_time=datetime.datetime(2015, 4, 24, 18, 43, 27), 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)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[7](Folderish:1, State: remotely_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4809318400) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#d93d5b9a-f373-4910-874a-42efbdb9f782"}}'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6', 'parentId': u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#6916a83c-d258-47d0-8ee7-e08e98be4df6", "parentId": "defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13"}}'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder, remote_ref=defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13]
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[4](Folderish:1, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, remote_ref=defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782]
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4944093184) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"f15c1cae7882448b3fb0404682e17e61","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782/defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","creationDate":1429893807826,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807899,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}]'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt","name":"joe.odt","id":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","creationDate":1429893807325,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807421,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt' with headers: {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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'}
18:43:41 [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)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4809318400 for row 7
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: modified, Remote state: modified, State: conflicted)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_conflicted of <nxdrive.engine.processor.Processor object at 0x11eac3df8>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: modified, Remote state: modified, State: conflicted)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Auto-resolve conflict has folder has same remote_id
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4944093184 for row 4
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_conflicted of <nxdrive.engine.processor.Processor object at 0x11eac3df8>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782, Local state: modified, Remote state: modified, State: conflicted)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#cedf2ced-03b6-4bf3-aa57-696218265e13"}}'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4809318400
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(4809318400) end
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 6
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[6](Local: /Nuxeo Drive Test Workspace/Test folder/jack.odt, Remote: defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[6](Local: /Nuxeo Drive Test Workspace/Test folder/jack.odt, Remote: defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'jack.odt' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt
18:43:41 [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
18:43:41 [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#cedf2ced-03b6-4bf3-aa57-696218265e13","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","creationDate":1429893804847,"creator":"nuxeoDriveTestUser_user_1","folder":true,"lastModificationDate":1429893804847,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[6](Local: /Nuxeo Drive Test Workspace/Test folder/jack.odt, Remote: defaultFileSystemItemFactory#default#514a2130-cb33-4c67-a673-c923638f9915, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 8
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[8](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, Remote: defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[8](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, Remote: defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'sub file 1.txt' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51', 'parentId': u'defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#41256e54-4ead-4ca4-9476-04239ea94d51", "parentId": "defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f15c1cae7882448b3fb0404682e17e61","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt","name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782/defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51","creationDate":1429893807826,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807899,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#d93d5b9a-f373-4910-874a-42efbdb9f782","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/41256e54-4ead-4ca4-9476-04239ea94d51/blobholder:0/sub%20file%201.txt' with headers: {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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'}
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1263906d8>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1263906d8>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Test folder, Remote: defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4944093184
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4944093184) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt
18:43:41 [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
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
18:43:41 [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)
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'joe.odt', uid=u'defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6', parent_uid=u'defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6', folderish=False, last_modification_time=datetime.datetime(2015, 4, 24, 18, 43, 27), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'b53227da4280f0e18270f21dd77c91d0', digest_algorithm=u'md5', download_url=u'nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt', can_rename=False, can_delete=False, can_update=False, can_create_child=False)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:0, State: remotely_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[8](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, Remote: defaultFileSystemItemFactory#default#41256e54-4ead-4ca4-9476-04239ea94d51, Local state: unknown, Remote state: created, State: remotely_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Init processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4934393856 for row 5
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: synchronized, Remote state: modified, State: remotely_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: synchronized, Remote state: modified, State: remotely_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: No local impact of metadata update on document 'joe.odt'.
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x126390b00>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: synchronized, Remote state: modified, State: remotely_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4934393856
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(4934393856) end
18:43:41 [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
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 2669, 'lastSyncActiveRootDefinitions': u'default:d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": 2669, "lastSyncActiveRootDefinitions": "default:d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":2683,"fileSystemChanges":[],"syncDate":1429893815000,"activeSynchronizationRootDefinitions":"default:d308d235-ea09-4baf-9f3c-d042632c74e1","hasTooManyChanges":false}'
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, _wait_remote_scan = True, found 11 remote change(s)
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Ended wait for sync, setting _wait_remote_scan to True and _remote_changes_count to 0
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value 'defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6' on u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/local.odt' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/local.odt\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":0,"pageSize":0,"maxPageSize":1000,"currentPageSize":0,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":0,"pageIndex":0,"pageCount":1,"entries":[]}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Local sub folder 2' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Local sub folder 2\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":0,"pageSize":0,"maxPageSize":1000,"currentPageSize":0,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":0,"pageIndex":0,"pageCount":1,"entries":[]}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Local sub folder 2/local sub file 2.txt' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Local sub folder 2/local sub file 2.txt\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt, remote_ref=defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6]
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:0, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_file_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local file processor
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFileProcessor(4807196672) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/local.odt
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/local.odt, remote_ref=None]
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[9](Folderish:0, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_file_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":0,"pageSize":0,"maxPageSize":1000,"currentPageSize":0,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":0,"pageIndex":0,"pageCount":1,"entries":[]}'
18:43:41 [INFO]      [exec] nxdrive.client.local_client: TRACE: Send /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1 to trash
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Local sub folder 2/local sub file 2.txt
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Local sub folder 2
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpTwVc42-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Local sub folder 2, remote_ref=None]
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[11](Folderish:1, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4940189696) start
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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 []
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4807196672 for row 5
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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#6916a83c-d258-47d0-8ee7-e08e98be4df6"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b53227da4280f0e18270f21dd77c91d0","digestAlgorithm":"md5","canUpdate":false,"downloadURL":"nxbigfile/default/6916a83c-d258-47d0-8ee7-e08e98be4df6/blobholder:0/joe.odt","name":"joe.odt","id":"defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#d308d235-ea09-4baf-9f3c-d042632c74e1/defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13/defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6","creationDate":1429893807325,"creator":"nuxeoDriveTestUser_user_1","folder":false,"lastModificationDate":1429893807421,"lastContributor":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#cedf2ced-03b6-4bf3-aa57-696218265e13","canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1260dbe90>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Skip update of remote document 'joe.odt' as it is readonly.
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x1260dbe90>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Test folder/joe.odt, Remote: defaultFileSystemItemFactory#default#6916a83c-d258-47d0-8ee7-e08e98be4df6, Local state: modified, Remote state: synchronized, State: locally_modified)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4807196672
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4807196672 for row 9
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[9](Local: /Nuxeo Drive Test Workspace/Test folder/local.odt, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260dbe90>> on doc pair StateRow[9](Local: /Nuxeo Drive Test Workspace/Test folder/local.odt, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: WARNING: Won't synchronize file 'local.odt' created in local folder 'Test folder' since it is readonly
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260dbe90>> on doc pair StateRow[9](Local: /Nuxeo Drive Test Workspace/Test folder/local.odt, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4807196672
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFileProcessor(4807196672) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 4940189696 for row 11
18:43:41 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[11](Local: /Nuxeo Drive Test Workspace/Test folder/Local sub folder 2, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260db938>> on doc pair StateRow[11](Local: /Nuxeo Drive Test Workspace/Test folder/Local sub folder 2, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.processor: WARNING: Won't synchronize folder 'Local sub folder 2' created in local folder 'Test folder' since it is readonly
18:43:41 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x1260db938>> on doc pair StateRow[11](Local: /Nuxeo Drive Test Workspace/Test folder/Local sub folder 2, Remote: None, Local state: created, Remote state: unknown, State: locally_created)
18:43:41 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 4940189696
18:43:41 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(4940189696) end
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
18:43:41 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 2683, 'lastSyncActiveRootDefinitions': u'default:d308d235-ea09-4baf-9f3c-d042632c74e1'}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'794b832c-27c2-4a52-9fbd-c5d7f695360b', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '00d08baeeaa111e4abac002500d3a152', '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": 2683, "lastSyncActiveRootDefinitions": "default:d308d235-ea09-4baf-9f3c-d042632c74e1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":2690,"fileSystemChanges":[],"syncDate":1429893819000,"activeSynchronizationRootDefinitions":"default:d308d235-ea09-4baf-9f3c-d042632c74e1","hasTooManyChanges":false}'
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 2
18:43:41 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
18:43:41 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed, ended wait for sync
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZGRkZTI='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
18:43:41 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":1,"pageSize":0,"maxPageSize":1000,"currentPageSize":1,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":1,"pageIndex":0,"pageCount":1,"entries":[{"entity-type":"document","repository":"default","uid":"d93d5b9a-f373-4910-874a-42efbdb9f782","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1","type":"Folder","state":"project","parentRef":"cedf2ced-03b6-4bf3-aa57-696218265e13","isCheckedOut":true,"changeToken":"1429893807750","title":"Sub folder 1","lastModified":"2015-04-24T16:43:27.75Z","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-04-24T16:43:27.75Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-24T16:43:27.75Z","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"]}]}'
18:43:41 [INFO]      [exec] --------------------- >> end captured logging << ---------------------

      Comparing with a successful build, the following line that indicates that the folder re-creation is forced (markes as remotely created) is missing:

      07:54:20 [INFO]      [exec] 2015-04-24 07:54:20,223 29030 140655858796288 DEBUG    nxdrive.engine.processor Marking StateRow[6](Local: /Nuxeo Drive Test Workspace/Test folder/Sub folder 1, Remote: defaultFileSystemItemFactory#default#8bcb5e29-1158-4196-bf25-c2bdc6b197f7, Local state: deleted, Remote state: synchronized, State: locally_deleted) as remotely created since remote document 'Sub folder 1' (defaultFileSystemItemFactory#default#8bcb5e29-1158-4196-bf25-c2bdc6b197f7) can not be deleted: either it is readonly or it is a virtual folder that doesn't exist in the server hierarchy

        Attachments

          Issue Links

          is required by

          Bug - A problem which impairs or prevents the functions of the product. NXDRIVE-228 Fix random readonly test issues

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Resolved

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: