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

Randomly failing tests because of inconsistent remote changes

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0.818
    • Component/s: Remote watcher, Tests
    • Sprint:
      Sprint Drive 7.2-3, Sprint Drive 7.2-4, Drive Next
    • Story Points:
      2

      Description

      Sometimes GetChangeSummary is called before WaitBeforeAsynCompletion returns so the change summary can be empty whereas some remote changes have been triggered by the test, thus the next assertion fails.

      This is probably because GetChangeSummary is called by the RemoteWatcher which is started in a different thread from the main test thread.

      See http://qa.nuxeo.org/jenkins/view/Drive/job/FT-nuxeo-drive-master-linux/379/console
      We can clearly see at the end of the trace the following sequence:

      Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion
Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary -> "fileSystemChanges":[]
Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion

      Full stack trace:

      20:45:59 [INFO]      [exec] ======================================================================
20:45:59 [INFO]      [exec] FAIL: test_remote_rename_sync_root_folder (nxdrive.tests.test_remote_move_and_rename.TestRemoteMoveAndRename)
20:45:59 [INFO]      [exec] ----------------------------------------------------------------------
20:45:59 [INFO]      [exec] Traceback (most recent call last):
20:45:59 [INFO]      [exec]   File "/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/test_remote_move_and_rename.py", line 433, in test_remote_rename_sync_root_folder
20:45:59 [INFO]      [exec]     self.assertFalse(local_client.exists(u'/Nuxeo Drive Test Workspace'))
20:45:59 [INFO]      [exec] AssertionError: True is not false
20:45:59 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /tmp/tmprKlZpj-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /tmp/tmprKlZpj-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
20:45:59 [INFO]      [exec] nxdrive.osi: DEBUG: Not using any OS integration
20:45:59 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /tmp/tmpcakbAj-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /tmp/tmpcakbAj-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
20:45:59 [INFO]      [exec] nxdrive.osi: DEBUG: Not using any OS integration
20:45:59 [INFO]      [exec] nxdrive.updater: DEBUG: Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
20:45:59 [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 []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
20:45:59 [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": "/"}}'
20:45:59 [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":"7af8020a-06b6-4d2e-bd0d-a153c2b8c21c","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"7af8020a-06b6-4d2e-bd0d-a153c2b8c21c","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"]}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
20:45:59 [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"}}'
20:45:59 [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'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /tmp/tmprKlZpj-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_ca369554e46811e4910fd067e5f2a1a2.db
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /tmp/tmprKlZpj-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_ca369554e46811e4910fd067e5f2a1a2.db (dir exists: 1 / file exists: 0)
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
20:45:59 [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': 'ca11e358e46811e4910fd067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=ca11e358e46811e4910fd067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '39e570e0-85e8-4f7d-89f0-6c9bc83e4362' with cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.3-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","updateSiteURL":"http://community.nuxeo.com/static/drive/"}'
20:45:59 [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/'}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":208,"creator":"system","folder":true,"canRename":false,"lastContributor":"system","lastModificationDate":208,"canDelete":false,"parentId":null,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/, remote_ref=None]
20:45:59 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|ca11e358e46811e4910fd067e5f2a1a2|ca369554e46811e4910fd067e5f2a1a2' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create DAO on /tmp/tmpcakbAj-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_ca75542ee46811e4910fd067e5f2a1a2.db
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Create main connexion on /tmp/tmpcakbAj-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_ca75542ee46811e4910fd067e5f2a1a2.db (dir exists: 1 / file exists: 0)
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Vacuum sqlite finished
20:45:59 [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': 'ca23b0d8e46811e4910fd067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiYzZhMDQ='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=ca23b0d8e46811e4910fd067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': 'ca23b0d8e46811e4910fd067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiYzZhMDQ='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '962a4dbd-1f9c-4ec0-baed-1174194c83f1' with cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '962a4dbd-1f9c-4ec0-baed-1174194c83f1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca23b0d8e46811e4910fd067e5f2a1a2', '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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.3-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","updateSiteURL":"http://community.nuxeo.com/static/drive/"}'
20:45:59 [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/'}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '962a4dbd-1f9c-4ec0-baed-1174194c83f1', 'X-Device-Id': 'ca23b0d8e46811e4910fd067e5f2a1a2', '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 []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '962a4dbd-1f9c-4ec0-baed-1174194c83f1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca23b0d8e46811e4910fd067e5f2a1a2', '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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":636,"creator":"system","folder":true,"canRename":false,"lastContributor":"system","lastModificationDate":636,"canDelete":false,"parentId":null,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_2"}'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmpcakbAj-nxdrive-tests-user-2/Nuxeo Drive/, remote_ref=None]
20:45:59 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|ca23b0d8e46811e4910fd067e5f2a1a2|ca75542ee46811e4910fd067e5f2a1a2' on u'/tmp/tmpcakbAj-nxdrive-tests-user-2/Nuxeo Drive'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
20:45:59 [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"}}'
20:45:59 [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":"1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"30bc0faa-aade-405f-b17a-37cd99697f44","isCheckedOut":true,"changeToken":"1429209944796","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-16T18:45:44.79Z","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-16T18:45:44.79Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-16T18:45:44.79Z","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"]}'
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"value": "1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:45:59 [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":"1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"30bc0faa-aade-405f-b17a-37cd99697f44","isCheckedOut":true,"changeToken":"1429209944796","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-16T18:45:44.79Z","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-16T18:45:44.79Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-16T18:45:44.79Z","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"]}'
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiYzZhMDQ='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiYzZhMDQ='}, cookies [] and JSON payload '{"params": {"value": "1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:45:59 [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":"1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"30bc0faa-aade-405f-b17a-37cd99697f44","isCheckedOut":true,"changeToken":"1429209944796","title":"Nuxeo Drive Test Workspace","lastModified":"2015-04-16T18:45:44.79Z","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-16T18:45:44.79Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-04-16T18:45:44.79Z","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"]}'
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='} and cookies []
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiYzZhMDQ='} and cookies []
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:1c1dfc38-9260-4650-a477-58c8ffca380f', 'params': {'enable': True}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"input": "doc:1c1dfc38-9260-4650-a477-58c8ffca380f", "params": {"enable": true}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
20:45:59 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive'
20:45:59 [INFO]      [exec] nxdrive.client.local_client: TRACE: Removing xattr drive-fs-test from /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:45:59 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Engine start
20:45:59 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalWatcher(140258951804672) start
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watching FS modification on : /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:45:59 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 1.txt'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14, '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': 14, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429209946.82_647453676', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%201.txt'} and cookies [] for file /tmp/tmpnWmN4r-nxdrive-uploads/tmpf4_Z29-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429209946.82_647453676"}'
20:45:59 [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 NuxeoDrive.CreateFile with file /tmp/tmpnWmN4r-nxdrive-uploads/tmpf4_Z29-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429209946.82_647453676', 'parentId': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"batchId": "1429209946.82_647453676", "parentId": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"downloadURL":"nxbigfile/default/06512075-f0eb-470c-9ce1-a759bc89b15f/blobholder:0/Original%20File%201.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","creationDate":1429209946874,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209946874,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 2.txt'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14, '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': 14, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429209946.92_658079746', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%202.txt'} and cookies [] for file /tmp/tmpnWmN4r-nxdrive-uploads/tmpz_ZwfG-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429209946.92_658079746"}'
20:45:59 [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 NuxeoDrive.CreateFile with file /tmp/tmpnWmN4r-nxdrive-uploads/tmpz_ZwfG-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429209946.92_658079746', 'parentId': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"batchId": "1429209946.92_658079746", "parentId": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"downloadURL":"nxbigfile/default/534889c9-29a0-45f1-8376-c7c479b5a695/blobholder:0/Original%20File%202.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"aa5728d0861fd3b174dc33202838ecb8","creationDate":1429209946954,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209946954,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Original Folder 1', 'parentId': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"name": "Original Folder 1", "parentId": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1429209947163,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947163,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original Folder 1","id":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Sub-Folder 1.1', 'parentId': u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"name": "Sub-Folder 1.1", "parentId": "defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1429209947248,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947248,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Sub-Folder 1.2', 'parentId': u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"name": "Sub-Folder 1.2", "parentId": "defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1429209947292,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947292,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 1.1.txt'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14, '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': 14, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429209947.32_919691737', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%201.1.txt'} and cookies [] for file /tmp/tmpnWmN4r-nxdrive-uploads/tmpOi5yrb-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429209947.32_919691737"}'
20:45:59 [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 NuxeoDrive.CreateFile with file /tmp/tmpnWmN4r-nxdrive-uploads/tmpOi5yrb-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429209947.32_919691737', 'parentId': u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"batchId": "1429209947.32_919691737", "parentId": "defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"downloadURL":"nxbigfile/default/e3b240b4-7c4d-4467-979b-31a3cd50fbf3/blobholder:0/Original%20File%201.1.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","creationDate":1429209947353,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947353,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': 'Original Folder 2', 'parentId': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"name": "Original Folder 2", "parentId": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1429209947423,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947423,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 3.txt'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14, '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': 14, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1429209947.5_325024144', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%203.txt'} and cookies [] for file /tmp/tmpnWmN4r-nxdrive-uploads/tmpo41bX0-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1429209947.5_325024144"}'
20:45:59 [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 NuxeoDrive.CreateFile with file /tmp/tmpnWmN4r-nxdrive-uploads/tmpo41bX0-nxdrive-file-to-upload
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1429209947.5_325024144', 'parentId': u'defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
20:45:59 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"batchId": "1429209947.5_325024144", "parentId": "defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"downloadURL":"nxbigfile/default/ecfdf1d5-330c-4423-a186-4e81508fd7e0/blobholder:0/Original%20File%203.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"180b2cbf65a05357269e12a1d1324635","creationDate":1429209947534,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947534,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1/defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Watchdog setup finished
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan started
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Found new folder /Nuxeo Drive Test Workspace
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=None]
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[2](Folderish:1, State: locally_created)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Full scan finished in 66ms
20:45:59 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteWatcher(140258969900800) start
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote full scan
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"creationDate":917,"creator":"system","folder":true,"canRename":false,"lastContributor":"system","lastModificationDate":917,"canDelete":false,"parentId":null,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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": {}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"syncDate":1429209947000,"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:1c1dfc38-9260-4650-a477-58c8ffca380f","upperBound":4528,"fileSystemChanges":[]}'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1429209944796,"creator":"Administrator","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209945790,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","userName":"nuxeoDriveTestUser_user_1"}]'
20:45:59 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 0 children of '/Nuxeo Drive Test Workspace'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/06512075-f0eb-470c-9ce1-a759bc89b15f/blobholder:0/Original%20File%201.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","creationDate":1429209946874,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209946874,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f","userName":"nuxeoDriveTestUser_user_1"},{"downloadURL":"nxbigfile/default/534889c9-29a0-45f1-8376-c7c479b5a695/blobholder:0/Original%20File%202.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"aa5728d0861fd3b174dc33202838ecb8","creationDate":1429209946954,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209946954,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"creationDate":1429209947163,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947163,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original Folder 1","id":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"creationDate":1429209947423,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947423,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","userName":"nuxeoDriveTestUser_user_1"}]'
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Original File 1.txt', uid=u'defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f', parent_uid=u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f', folderish=False, last_modification_time=datetime.datetime(2015, 4, 16, 20, 45, 46), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f3b09f7a82f6ac8c6077a1ca1d3778d8', digest_algorithm=u'md5', download_url=u'nxbigfile/default/06512075-f0eb-470c-9ce1-a759bc89b15f/blobholder:0/Original%20File%201.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[3](Folderish:0, State: remotely_created)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 1
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Original File 2.txt', uid=u'defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695', parent_uid=u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695', folderish=False, last_modification_time=datetime.datetime(2015, 4, 16, 20, 45, 46), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'aa5728d0861fd3b174dc33202838ecb8', digest_algorithm=u'md5', download_url=u'nxbigfile/default/534889c9-29a0-45f1-8376-c7c479b5a695/blobholder:0/Original%20File%202.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[4](Folderish:0, State: remotely_created)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Original Folder 1', uid=u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6', parent_uid=u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6', folderish=True, last_modification_time=datetime.datetime(2015, 4, 16, 20, 45, 47), 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)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:1, State: remotely_created)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 1
20:45:59 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing RemoteFileInfo(name=u'Original Folder 2', uid=u'defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1', parent_uid=u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1', folderish=True, last_modification_time=datetime.datetime(2015, 4, 16, 20, 45, 47), 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)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[6](Folderish:1, State: remotely_created)
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 2
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 1
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#23705ca5-562a-4ff5-bad4-d8e64b0629f6"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1429209947248,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947248,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b","userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"creationDate":1429209947292,"creator":"nuxeoDriveTestUser_user_1","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947292,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5","userName":"nuxeoDriveTestUser_user_1"},{"downloadURL":"nxbigfile/default/e3b240b4-7c4d-4467-979b-31a3cd50fbf3/blobholder:0/Original%20File%201.1.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","creationDate":1429209947353,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947353,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","userName":"nuxeoDriveTestUser_user_1"}]'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [deleted] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b"}}'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#de14c1a3-254e-4c78-b841-fa0ed3109ec5"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 2
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1'}}
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#96ba6aa3-e49e-4062-a372-25cc587aa1e1"}}'
20:45:59 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"downloadURL":"nxbigfile/default/ecfdf1d5-330c-4423-a186-4e81508fd7e0/blobholder:0/Original%20File%203.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"180b2cbf65a05357269e12a1d1324635","creationDate":1429209947534,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947534,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1/defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","userName":"nuxeoDriveTestUser_user_1"}]'
20:45:59 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Remote scan finished in 890ms
20:45:59 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Remote scan completed
20:45:59 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Init processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote folder processor
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating remote file processor
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(140258880993024) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(140258889385728) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(140258897778432) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258880993024 for row 3
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258897778432 for row 2
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[2](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Skip as pair is None or in non-processable state: StateRow[2](Local: /Nuxeo Drive Test Workspace, Remote: defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258897778432
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(140258897778432) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258889385728 for row 5
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: /Nuxeo Drive Test Workspace/Original Folder 1, Remote: defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Original Folder 1, Remote: defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Original Folder 1' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 3 children of '/Nuxeo Drive Test Workspace/Original Folder 1'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x7f9092038140>
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[7](Folderish:1, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 2
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x7f909f709b90>
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[8](Folderish:1, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_folder_queue, now of size: 3
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x7f909f709e60>
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[9](Folderish:0, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 2
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[5](Local: /Nuxeo Drive Test Workspace/Original Folder 1, Remote: defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258889385728
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258889385728 for row 6
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[6](Local: /Nuxeo Drive Test Workspace/Original Folder 2, Remote: defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[6](Local: /Nuxeo Drive Test Workspace/Original Folder 2, Remote: defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Original Folder 2' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 1 children of '/Nuxeo Drive Test Workspace/Original Folder 2'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing <nxdrive.engine.dao.sqlite.CustomRow object at 0x7f9092038190>
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[10](Folderish:0, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _remote_file_queue, now of size: 3
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating additional file processor
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating additional file processor
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating additional file processor
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258897778432) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258792433408) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258800826112) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[6](Local: /Nuxeo Drive Test Workspace/Original Folder 2, Remote: defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258889385728
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258889385728 for row 7
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[7](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, Remote: defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, Remote: defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Sub-Folder 1.1' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258897778432 for row 4
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[4](Local: /Nuxeo Drive Test Workspace/Original File 2.txt, Remote: defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7bef28>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Original File 2.txt, Remote: defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'Original File 2.txt' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695', 'parentId': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#534889c9-29a0-45f1-8376-c7c479b5a695", "parentId": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/534889c9-29a0-45f1-8376-c7c479b5a695/blobholder:0/Original%20File%202.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"aa5728d0861fd3b174dc33202838ecb8","creationDate":1429209946954,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209946954,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695","userName":"nuxeoDriveTestUser_user_1"}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/534889c9-29a0-45f1-8376-c7c479b5a695/blobholder:0/Original%20File%202.txt' with headers: {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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'}
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258792433408 for row 9
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258800826112 for row 10
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 0 children of '/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1'
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[7](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, Remote: defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258889385728
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258889385728 for row 8
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[8](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, Remote: defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[8](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, Remote: defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local folder 'Sub-Folder 1.2' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original File 2.txt'
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: DEBUG: Queuing 0 children of '/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2'
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f807180>> on doc pair StateRow[8](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, Remote: defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258889385728
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFolderProcessor(140258889385728) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7bef28>> on doc pair StateRow[4](Local: /Nuxeo Drive Test Workspace/Original File 2.txt, Remote: defaultFileSystemItemFactory#default#534889c9-29a0-45f1-8376-c7c479b5a695, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258897778432
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258897778432) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[9](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt, Remote: defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7bea68>> on doc pair StateRow[9](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt, Remote: defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'Original File 1.1.txt' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3', 'parentId': u'defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#e3b240b4-7c4d-4467-979b-31a3cd50fbf3", "parentId": "defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6"}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/e3b240b4-7c4d-4467-979b-31a3cd50fbf3/blobholder:0/Original%20File%201.1.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","creationDate":1429209947353,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947353,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6","name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6/defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3","userName":"nuxeoDriveTestUser_user_1"}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/e3b240b4-7c4d-4467-979b-31a3cd50fbf3/blobholder:0/Original%20File%201.1.txt' with headers: {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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'}
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[10](Local: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt, Remote: defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7be770>> on doc pair StateRow[10](Local: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt, Remote: defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'Original File 3.txt' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0', 'parentId': u'defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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#ecfdf1d5-330c-4423-a186-4e81508fd7e0", "parentId": "defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1"}}'
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 0 ko/s
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"downloadURL":"nxbigfile/default/ecfdf1d5-330c-4423-a186-4e81508fd7e0/blobholder:0/Original%20File%203.txt","canUpdate":true,"digestAlgorithm":"md5","digest":"180b2cbf65a05357269e12a1d1324635","creationDate":1429209947534,"creator":"nuxeoDriveTestUser_user_1","folder":false,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209947534,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f/defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1/defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0","userName":"nuxeoDriveTestUser_user_1"}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/ecfdf1d5-330c-4423-a186-4e81508fd7e0/blobholder:0/Original%20File%203.txt' with headers: {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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'}
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Transfer speed 1 ko/s
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7bea68>> on doc pair StateRow[9](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt, Remote: defaultFileSystemItemFactory#default#e3b240b4-7c4d-4467-979b-31a3cd50fbf3, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258792433408
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258792433408) end
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt'
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f7be770>> on doc pair StateRow[10](Local: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt, Remote: defaultFileSystemItemFactory#default#ecfdf1d5-330c-4423-a186-4e81508fd7e0, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258800826112
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread GenericProcessor(140258800826112) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1, remote_ref=defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6]
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[5](Folderish:1, State: locally_modified)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: creating local folder processor
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(140258800826112) start
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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 []
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258800826112 for row 5
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1]
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[6](Folderish:1, State: locally_modified)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 1
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, remote_ref=defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b]
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[7](Folderish:1, State: locally_modified)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 2
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 2.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 2.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [moved] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 2.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Pushing FileInfo[/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, remote_ref=defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5]
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushing QueueItem[8](Folderish:1, State: locally_modified)
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Pushed to _local_folder_queue, now of size: 3
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original File 2.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 2.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/.Original File 1.1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[3](Local: /Nuxeo Drive Test Workspace/Original File 1.txt, Remote: defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f8072b0>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace/Original File 1.txt, Remote: defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Creating local file 'Original File 1.txt' in '/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:46:00 [INFO]      [exec] nxdrive.client.local_client: TRACE: Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f' on u'/tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original File 1.txt'
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/.Original File 1.1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f909f8072b0>> on doc pair StateRow[3](Local: /Nuxeo Drive Test Workspace/Original File 1.txt, Remote: defaultFileSystemItemFactory#default#06512075-f0eb-470c-9ce1-a759bc89b15f, Local state: unknown, Remote state: created, State: remotely_created)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258880993024
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread RemoteFileProcessor(140258880993024) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[5](Local: /Nuxeo Drive Test Workspace/Original Folder 1, Remote: defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Skip as pair is None or in non-processable state: StateRow[5](Local: /Nuxeo Drive Test Workspace/Original Folder 1, Remote: defaultFileSystemItemFactory#default#23705ca5-562a-4ff5-bad4-d8e64b0629f6, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258800826112
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258800826112 for row 6
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[6](Local: /Nuxeo Drive Test Workspace/Original Folder 2, Remote: defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Skip as pair is None or in non-processable state: StateRow[6](Local: /Nuxeo Drive Test Workspace/Original Folder 2, Remote: defaultFileSystemItemFactory#default#96ba6aa3-e49e-4062-a372-25cc587aa1e1, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258800826112
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258800826112 for row 7
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[7](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, Remote: defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Skip as pair is None or in non-processable state: StateRow[7](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, Remote: defaultFileSystemItemFactory#default#404d0d98-6be8-43a9-9e13-d5ec0ec28a8b, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258800826112
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Acquired processor 140258800826112 for row 8
20:46:00 [INFO]      [exec] nxdrive.engine.processor: DEBUG: Executing processor on StateRow[8](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, Remote: defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.processor: TRACE: Skip as pair is None or in non-processable state: StateRow[8](Local: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, Remote: defaultFileSystemItemFactory#default#de14c1a3-254e-4c78-b841-fa0ed3109ec5, Local state: synchronized, Remote state: synchronized, State: synchronized)
20:46:00 [INFO]      [exec] nxdrive.engine.dao.sqlite: TRACE: Released processor 140258800826112
20:46:00 [INFO]      [exec] nxdrive.engine.workers: DEBUG: Thread LocalFolderProcessor(140258800826112) end
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [moved] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/.Original File 1.1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2/.Original File 3.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2/.Original File 3.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [moved] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2/.Original File 3.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [created] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [moved] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/.Original File 1.txt.nxpart
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Handling watchdog event [modified] on /tmp/tmprKlZpj-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Original File 1.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.local_watcher: DEBUG: Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 1.txt
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 4528, 'lastSyncActiveRootDefinitions': u'default:1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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": 4528, "lastSyncActiveRootDefinitions": "default:1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"syncDate":1429209952000,"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:1c1dfc38-9260-4650-a477-58c8ffca380f","upperBound":4548,"fileSystemChanges":[]}'
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: Active: LocalFolder: None, LocalFile: None, RemoteFolder: None, RemoteFile: None, Pool:0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive and overall size = 0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: Active: LocalFolder: None, LocalFile: None, RemoteFolder: None, RemoteFile: None, Pool:0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
20:46:00 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f', 'name': u'Renamed Nuxeo Drive Test Workspace'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f", "name": "Renamed Nuxeo Drive Test Workspace"}}'
20:46:00 [INFO]      [exec] nxdrive.engine.watcher.remote_watcher: DEBUG: Handle remote changes
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 4548, 'lastSyncActiveRootDefinitions': u'default:1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'39e570e0-85e8-4f7d-89f0-6c9bc83e4362', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': 'ca11e358e46811e4910fd067e5f2a1a2', '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": 4548, "lastSyncActiveRootDefinitions": "default:1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename' with cookies []: '{"canCreateChild":true,"creationDate":1429209944796,"creator":"Administrator","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209953605,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","name":"Renamed Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","userName":"nuxeoDriveTestUser_user_1"}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f'}}
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo3OWExZjk='}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f"}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"creationDate":1429209944796,"creator":"Administrator","folder":true,"canRename":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1429209953605,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","name":"Renamed Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#1c1dfc38-9260-4650-a477-58c8ffca380f","userName":"nuxeoDriveTestUser_user_1"}'
20:46:00 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Wait for sync
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:46:00 [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": {}}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"syncDate":1429209956000,"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:1c1dfc38-9260-4650-a477-58c8ffca380f","upperBound":4548,"fileSystemChanges":[]}'
20:46:00 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: Active: LocalFolder: None, LocalFile: None, RemoteFolder: None, RemoteFile: None, Pool:0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Checking sync completed: queue manager is inactive and overall size = 0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: DEBUG: Active: LocalFolder: None, LocalFile: None, RemoteFolder: None, RemoteFile: None, Pool:0
20:46:00 [INFO]      [exec] nxdrive.engine.queue_manager: TRACE: Launching processors
20:46:00 [INFO]      [exec] nxdrive.engine.engine: DEBUG: Emitting syncCompleted
20:46:00 [INFO]      [exec] nxdrive.tests.common_unit_test: DEBUG: Sync completed
20:46:00 [INFO]      [exec] --------------------- >> end captured logging << --------------------

        Attachments

          Issue Links

          is required by

          Task - A task that needs to be done. NXDRIVE-170 Refactor functional test framework to run the ndrive program instead of relying on its implementation

          • Major - Major loss of function.
          • Resolved

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: