[NXDRIVE-87] Random failure at line 175, in test_synchronize_remote_deletion_local_modification. - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 1.3.1107
Fix Version/s: 1.3.1107
Component/s: Synchronizer, Watchdog

Sprint:
Sprint Drive 5.9.6-2

Description

And line 393, in test_synchronize_local_folder_rename_remote_deletion

See https://qa.nuxeo.org/jenkins/job/FT-nuxeo-drive-master-linux/375/consoleFull

14:05:10 [INFO]      [exec] ======================================================================
14:05:10 [INFO]      [exec] FAIL: Test remote deletion with concurrent local modification
14:05:10 [INFO]      [exec] ----------------------------------------------------------------------
14:05:10 [INFO]      [exec] Traceback (most recent call last):
14:05:10 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/test_integration_remote_deletion.py", line 175, in test_synchronize_remote_deletion_local_modification
14:05:10 [INFO]      [exec]     'unsynchronized')
14:05:10 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/test_integration_remote_deletion.py", line 412, in _check_pair_state
14:05:10 [INFO]      [exec]     self.assertEquals(doc_pair.pair_state, pair_state)
14:05:10 [INFO]      [exec] AssertionError: u'locally_created' != 'unsynchronized'
14:05:10 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in '/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive'
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in '/tmp/tmplaItZP-nxdrive-tests-user-1/nuxeo-drive-conf'
14:05:10 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
14:05:10 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
14:05:10 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in '/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive'
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in '/tmp/tmpzYc12j-nxdrive-tests-user-2/nuxeo-drive-conf'
14:05:10 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
14:05:10 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
14:05:10 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
14:05:10 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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": "/"}}'
14:05:10 [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":"d731e0b7-f48a-4798-bc7c-53d57a2928f9","path":"/","type":"Root","state":null,"versionLabel":"","isCheckedOut":true,"title":"d731e0b7-f48a-4798-bc7c-53d57a2928f9","properties":{"dc:creator":null,"dc:source":null,"dc:nature":null,"dc:contributors":[],"dc:created":null,"dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":null,"dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":null,"dc:lastContributor":null,"common:icon":null,"common:icon-expanded":null,"common:size":null},"facets":["Folderish","NotCollectionMember"],"changeToken":null,"contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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"}}'
14:05:10 [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'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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"}}'
14:05:10 [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":"a2462663-87c7-4786-bce3-c7a22345ec67","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-15T11:58:14.00Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-09-15T11:58:14.00Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.00Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410782294008","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"params": {"value": "a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [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":"a2462663-87c7-4786-bce3-c7a22345ec67","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-15T11:58:14.00Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-09-15T11:58:14.00Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.00Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410782294008","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3MzlhMjE='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3MzlhMjE='}, cookies [] and JSON payload '{"params": {"value": "a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [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":"a2462663-87c7-4786-bce3-c7a22345ec67","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-15T11:58:14.00Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-09-15T11:58:14.00Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.00Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410782294008","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3MzlhMjE='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=925262d03ccf11e4832c40408687c0a8&permission=ReadWrite with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token '0e83400e-0ece-4113-9a40-d8a877d70399' with cookies []
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Binding '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":295,"lastModificationDate":295,"parentId":null,"folder":true,"canDelete":false,"creator":"system","canRename":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 1970-01-01 01:00:00 and updated last_sync_date to 2014-09-15 13:58:14.301254
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"updateSiteURL":"http://community.nuxeo.com/static/drive/","serverVersion":"5.9.6-SNAPSHOT"}'
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Fetched update info from server: {u'serverVersion': u'5.9.6-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/'}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:a2462663-87c7-4786-bce3-c7a22345ec67', 'params': {'enable': True}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"input": "doc:a2462663-87c7-4786-bce3-c7a22345ec67", "params": {"enable": true}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/', 'params': {'type': 'Folder', 'name': 'Test folder', 'properties': 'dc:title=Test folder'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "Folder", "name": "Test folder", "properties": "dc:title=Test folder"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"b07ac018-cb9d-4952-8a87-5bde4addf334","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","versionLabel":"","isCheckedOut":true,"title":"Test folder","lastModified":"2014-09-15T11:58:14.41Z","properties":{"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.41Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.41Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test folder","dc:lastContributor":"nuxeoDriveTestUser_user_1","common:icon":"/icons/folder.gif","common:icon-expanded":null,"common:size":null},"facets":["Folderish"],"changeToken":"1410782294418","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'File', 'name': 'joe.odt', 'properties': 'dc:title=joe.odt'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "File", "name": "joe.odt", "properties": "dc:title=joe.odt"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"6e4a8e17-4be9-4e01-8d42-675156acce94","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/joe.odt","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"joe.odt","lastModified":"2014-09-15T11:58:14.44Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.44Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.44Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"joe.odt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/file.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1410782294444","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'joe.odt'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 12, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 12, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410782294.46_346350127', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'joe.odt'} and cookies [] for file /tmp/tmpq6XVPN-nxdrive-uploads/tmpylnrGi-nxdrive-file-to-upload
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410782294.46_346350127"}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410782294.46_346350127', 'document': u'6e4a8e17-4be9-4e01-8d42-675156acce94', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"params": {"batchId": "1410782294.46_346350127", "document": "6e4a8e17-4be9-4e01-8d42-675156acce94", "fileIdx": "0", "operationId": "Blob.Attach"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'File', 'name': 'jack.odt', 'properties': 'dc:title=jack.odt'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "File", "name": "jack.odt", "properties": "dc:title=jack.odt"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"df0d3b36-5005-416b-9d3a-5734412a4140","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/jack.odt","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"jack.odt","lastModified":"2014-09-15T11:58:14.54Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.54Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.54Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"jack.odt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/file.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1410782294543","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'jack.odt'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 12, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 12, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410782294.57_718729260', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'jack.odt'} and cookies [] for file /tmp/tmpq6XVPN-nxdrive-uploads/tmpg0jjBu-nxdrive-file-to-upload
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410782294.57_718729260"}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410782294.57_718729260', 'document': u'df0d3b36-5005-416b-9d3a-5734412a4140', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"params": {"batchId": "1410782294.57_718729260", "document": "df0d3b36-5005-416b-9d3a-5734412a4140", "fileIdx": "0", "operationId": "Blob.Attach"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'type': 'Folder', 'name': 'Sub folder 1', 'properties': 'dc:title=Sub folder 1'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"type": "Folder", "name": "Sub folder 1", "properties": "dc:title=Sub folder 1"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"44bbfc17-f63e-48e2-9aec-6215b23a7690","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1","type":"Folder","state":"project","versionLabel":"","isCheckedOut":true,"title":"Sub folder 1","lastModified":"2014-09-15T11:58:14.62Z","properties":{"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.62Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.62Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Sub folder 1","dc:lastContributor":"nuxeoDriveTestUser_user_1","common:icon":"/icons/folder.gif","common:icon-expanded":null,"common:size":null},"facets":["Folderish"],"changeToken":"1410782294622","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1', 'params': {'type': 'File', 'name': 'sub file 1.txt', 'properties': 'dc:title=sub file 1.txt'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1", "params": {"type": "File", "name": "sub file 1.txt", "properties": "dc:title=sub file 1.txt"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"3d4c00cb-21d5-41f0-a321-69201c4c0732","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/Sub folder 1/sub file 1.txt","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"sub file 1.txt","lastModified":"2014-09-15T11:58:14.65Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.65Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:14.65Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"sub file 1.txt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/file.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1410782294658","contextParameters":{}}'
14:05:10 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'sub file 1.txt'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 7, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 7, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410782294.67_862382187', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'sub%20file%201.txt'} and cookies [] for file /tmp/tmpq6XVPN-nxdrive-uploads/tmpg7CTJ8-nxdrive-file-to-upload
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410782294.67_862382187"}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410782294.67_862382187', 'document': u'3d4c00cb-21d5-41f0-a321-69201c4c0732', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"params": {"batchId": "1410782294.67_862382187", "document": "3d4c00cb-21d5-41f0-a321-69201c4c0732", "fileIdx": "0", "operationId": "Blob.Attach"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'text/plain'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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": {}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=31026)
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"syncDate":1410782295000,"upperBound":3207,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:a2462663-87c7-4786-bce3-c7a22345ec67"}'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote full scan of /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"creationDate":182,"lastModificationDate":182,"parentId":null,"folder":true,"canDelete":false,"creator":"system","canRename":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '1970-01-01 01:00:00', '1970-01-01 01:00:00'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1410782294008,"lastModificationDate":1410782294382,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","folder":true,"canDelete":true,"creator":"Administrator","canRename":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.213972
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1410782294418,"lastModificationDate":1410782294418,"parentId":"defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.241410
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/6e4a8e17-4be9-4e01-8d42-675156acce94/blobholder:0/joe.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294444,"lastModificationDate":1410782294508,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"joe.odt","id":"defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","userName":"nuxeoDriveTestUser_user_1"},{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/df0d3b36-5005-416b-9d3a-5734412a4140/blobholder:0/jack.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294543,"lastModificationDate":1410782294596,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"jack.odt","id":"defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"creationDate":1410782294622,"lastModificationDate":1410782294622,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.280769
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'joe.odt', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'joe.odt', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.289875
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'jack.odt', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'jack.odt', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.294948
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Sub folder 1', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub folder 1', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/3d4c00cb-21d5-41f0-a321-69201c4c0732/blobholder:0/sub%20file%201.txt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1410782294658,"lastModificationDate":1410782294692,"parentId":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690/defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-15 13:58:14 and updated last_sync_date to 2014-09-15 13:58:15.327303
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'sub file 1.txt', local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'sub file 1.txt', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Watching FS modification on : /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"creationDate":1410782294008,"lastModificationDate":1410782294382,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","folder":true,"canDelete":true,"creator":"Administrator","canRename":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1410782294418,"lastModificationDate":1410782294418,"parentId":"defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace', remote_name=u'Nuxeo Drive Test Workspace', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"creationDate":1410782294418,"lastModificationDate":1410782294418,"parentId":"defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Test folder' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Test folder
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334"}}'
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder, wd=2, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Test folder>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/6e4a8e17-4be9-4e01-8d42-675156acce94/blobholder:0/joe.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294444,"lastModificationDate":1410782294508,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"joe.odt","id":"defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","userName":"nuxeoDriveTestUser_user_1"},{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/df0d3b36-5005-416b-9d3a-5734412a4140/blobholder:0/jack.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294543,"lastModificationDate":1410782294596,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"jack.odt","id":"defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"creationDate":1410782294622,"lastModificationDate":1410782294622,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"creationDate":1410782294622,"lastModificationDate":1410782294622,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":true,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"Sub folder 1","id":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Sub folder 1', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Sub folder 1' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Sub folder 1
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690"}}'
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, wd=3, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Sub folder 1>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/3d4c00cb-21d5-41f0-a321-69201c4c0732/blobholder:0/sub%20file%201.txt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1410782294658,"lastModificationDate":1410782294692,"parentId":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690/defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","userName":"nuxeoDriveTestUser_user_1"}]'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', remote_name=u'Sub folder 1', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/df0d3b36-5005-416b-9d3a-5734412a4140/blobholder:0/jack.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294543,"lastModificationDate":1410782294596,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"jack.odt","id":"defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'jack.odt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'jack.odt' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/df0d3b36-5005-416b-9d3a-5734412a4140/blobholder:0/jack.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294543,"lastModificationDate":1410782294596,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"jack.odt","id":"defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/df0d3b36-5005-416b-9d3a-5734412a4140/blobholder:0/jack.odt' with headers: {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part, wd=3, mask=IN_CREATE, cookie=0, name=.jack.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part, wd=3, mask=IN_MODIFY, cookie=0, name=.jack.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part, wd=3, mask=IN_MOVED_FROM, cookie=492043, name=.jack.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt, wd=3, mask=IN_MOVED_TO, cookie=492043, name=jack.odt>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/jack.odt', remote_name=u'jack.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: [u'jack.odt']
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/6e4a8e17-4be9-4e01-8d42-675156acce94/blobholder:0/joe.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294444,"lastModificationDate":1410782294508,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"joe.odt","id":"defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'joe.odt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'joe.odt' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/6e4a8e17-4be9-4e01-8d42-675156acce94/blobholder:0/joe.odt","canUpdate":true,"digest":"b53227da4280f0e18270f21dd77c91d0","creationDate":1410782294444,"lastModificationDate":1410782294508,"parentId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"joe.odt","id":"defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/6e4a8e17-4be9-4e01-8d42-675156acce94/blobholder:0/joe.odt' with headers: {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part, wd=3, mask=IN_CREATE, cookie=0, name=.joe.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part, wd=3, mask=IN_MODIFY, cookie=0, name=.joe.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part, wd=3, mask=IN_MOVED_FROM, cookie=492044, name=.joe.odt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt, wd=3, mask=IN_MOVED_TO, cookie=492044, name=joe.odt>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', remote_name=u'joe.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: [u'joe.odt', u'jack.odt']
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/3d4c00cb-21d5-41f0-a321-69201c4c0732/blobholder:0/sub%20file%201.txt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1410782294658,"lastModificationDate":1410782294692,"parentId":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690/defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-15 13:58:14', '2014-09-15 13:58:14'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'sub file 1.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'sub file 1.txt' in '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digestAlgorithm":"md5","downloadURL":"nxbigfile/default/3d4c00cb-21d5-41f0-a321-69201c4c0732/blobholder:0/sub%20file%201.txt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1410782294658,"lastModificationDate":1410782294692,"parentId":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"name":"sub file 1.txt","id":"defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#a2462663-87c7-4786-bce3-c7a22345ec67/defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334/defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690/defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","userName":"nuxeoDriveTestUser_user_1"}'
14:05:10 [INFO]      [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/3d4c00cb-21d5-41f0-a321-69201c4c0732/blobholder:0/sub%20file%201.txt' with headers: {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part, wd=4, mask=IN_CREATE, cookie=0, name=.sub file 1.txt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part, wd=4, mask=IN_MODIFY, cookie=0, name=.sub file 1.txt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part, wd=4, mask=IN_MOVED_FROM, cookie=492046, name=.sub file 1.txt.part>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, wd=4, mask=IN_MOVED_TO, cookie=492046, name=sub file 1.txt>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt', remote_name=u'sub file 1.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: [u'sub file 1.txt', u'joe.odt', u'jack.odt']
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 6, pending: 6, local: 0.017s, remote: 0.188s sync: 0.449s
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3207, 'lastSyncActiveRootDefinitions': u'default:a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3207, "lastSyncActiveRootDefinitions": "default:a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"syncDate":1410782295000,"upperBound":3227,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:a2462663-87c7-4786-bce3-c7a22345ec67"}'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 1 <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 2 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 3 <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 4 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 5 <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 6 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 7 <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 8 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 9 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 10 <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 11 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 12 <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 13 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 14 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 15 <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 16 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 17 <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 18 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 19 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 20 <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 21 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Sorted events: [<DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive'>, <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>, <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part'>, <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part'>, <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part'>, <FileMovedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part', dest_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>]
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Could not found file '/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part' under '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Unhandle case: <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.jack.odt.part'> /Nuxeo Drive Test Workspace/Test folder/.jack.odt.part .jack.odt.part
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Could not found file '/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part' under '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Unhandle case: <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/.joe.odt.part'> /Nuxeo Drive Test Workspace/Test folder/.joe.odt.part .joe.odt.part
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Could not found file '/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part' under '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Unhandle case: <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part'> /Nuxeo Drive Test Workspace/Test folder/Sub folder 1/.sub file 1.txt.part .sub file 1.txt.part
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 3.089s, remote: 0.021s sync: 0.009s
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 2 loops
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session
14:05:10 [INFO]      [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x7fc478f98e50>, ending any transaction in progress and releasing underlying connections from the pool
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder', 'params': {'value': 'delete'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetLifeCycle with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToyNDAzMmY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder", "params": {"value": "delete"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetLifeCycle' with cookies []: '{"entity-type":"document","repository":"default","uid":"b07ac018-cb9d-4952-8a87-5bde4addf334","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"deleted","versionLabel":"","isCheckedOut":true,"title":"Test folder","lastModified":"2014-09-15T11:58:18.93Z","properties":{"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2014-09-15T11:58:14.41Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-15T11:58:18.93Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test folder","dc:lastContributor":"nuxeoDriveTestUser_user_1","common:icon":"/icons/folder.gif","common:icon-expanded":null,"common:size":null},"facets":["Folderish"],"changeToken":"1410782298930","contextParameters":{}}'
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt, wd=3, mask=IN_CREATE, cookie=0, name=new.odt>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt, wd=3, mask=IN_MODIFY, cookie=0, name=new.odt>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2, wd=3, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Sub folder 2>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt, wd=5, mask=IN_CREATE, cookie=0, name=sub file 2.txt>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt, wd=5, mask=IN_MODIFY, cookie=0, name=sub file 2.txt>
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt, wd=3, mask=IN_MODIFY, cookie=0, name=joe.odt>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt, wd=3, mask=IN_MODIFY, cookie=0, name=joe.odt>
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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": {}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=31026)
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: [u'sub file 1.txt', u'joe.odt', u'jack.odt']
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3227, 'lastSyncActiveRootDefinitions': u'default:a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3227, "lastSyncActiveRootDefinitions": "default:a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"syncDate":1410782300000,"upperBound":3251,"fileSystemChanges":[{"fileSystemItem":null,"eventId":"deleted","eventDate":1410782298973,"repositoryId":"default","docUuid":"df0d3b36-5005-416b-9d3a-5734412a4140","fileSystemItemId":"defaultFileSystemItemFactory#default#df0d3b36-5005-416b-9d3a-5734412a4140","fileSystemItemName":"jack.odt"},{"fileSystemItem":null,"eventId":"deleted","eventDate":1410782298967,"repositoryId":"default","docUuid":"3d4c00cb-21d5-41f0-a321-69201c4c0732","fileSystemItemId":"defaultFileSystemItemFactory#default#3d4c00cb-21d5-41f0-a321-69201c4c0732","fileSystemItemName":"sub file 1.txt"},{"fileSystemItem":null,"eventId":"deleted","eventDate":1410782298959,"repositoryId":"default","docUuid":"44bbfc17-f63e-48e2-9aec-6215b23a7690","fileSystemItemId":"defaultFileSystemItemFactory#default#44bbfc17-f63e-48e2-9aec-6215b23a7690","fileSystemItemName":"Sub folder 1"},{"fileSystemItem":null,"eventId":"deleted","eventDate":1410782298948,"repositoryId":"default","docUuid":"6e4a8e17-4be9-4e01-8d42-675156acce94","fileSystemItemId":"defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94","fileSystemItemName":"joe.odt"},{"fileSystemItem":null,"eventId":"deleted","eventDate":1410782298931,"repositoryId":"default","docUuid":"b07ac018-cb9d-4952-8a87-5bde4addf334","fileSystemItemId":"defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334","fileSystemItemName":"Test folder"}],"activeSynchronizationRootDefinitions":"default:a2462663-87c7-4786-bce3-c7a22345ec67"}'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: 5 remote changes detected on http://localhost:8080/nuxeo/
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'jack.odt' as deleted
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/jack.odt', remote_name=u'jack.odt', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'sub file 1.txt' as deleted
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt', remote_name=u'sub file 1.txt', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'Sub folder 1' as deleted
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 1', remote_name=u'Sub folder 1', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'joe.odt' as deleted
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', remote_name=u'joe.odt', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'Test folder' as deleted
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: WARNING: Scan local as unhandled fs event
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Detected a new non-alignable local file at /Nuxeo Drive Test Workspace/Test folder/Sub folder 2
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Detected a new non-alignable local file at /Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/new.odt', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Detected a new non-alignable local file at /Nuxeo Drive Test Workspace/Test folder/new.odt
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling joe.odt for deletion: last_local_updated = 2014-09-15 13:58:19, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local file '/Nuxeo Drive Test Workspace/Test folder/joe.odt' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling jack.odt for deletion: last_local_updated = 2014-09-15 13:58:15, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Deleting local file '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'
14:05:10 [INFO]      [exec] nxdrive.client.local_client: INFO: Send /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt to trash
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt, wd=3, mask=IN_MOVED_FROM, cookie=492047, name=jack.odt>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling sub file 1.txt for deletion: last_local_updated = 2014-09-15 13:58:15, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Deleting local file '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'
14:05:10 [INFO]      [exec] nxdrive.client.local_client: INFO: Send /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt to trash
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt, wd=4, mask=IN_MOVED_FROM, cookie=492049, name=sub file 1.txt>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling Sub folder 1 for deletion: last_local_updated = 2014-09-15 13:58:15, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Deleting local folder '/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'
14:05:10 [INFO]      [exec] nxdrive.client.local_client: INFO: Send /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1 to trash
14:05:10 [INFO]      [exec] root: DEBUG: worker: in event <InotifyEvent: src_path=/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1, wd=3, mask=IN_ISDIR|IN_MOVED_FROM, cookie=492051, name=Sub folder 1>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling /Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt for deletion: last_local_updated = 2014-09-15 13:58:19, last_sync_date = None
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local file '/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local folder '/Nuxeo Drive Test Workspace/Test folder/Sub folder 2' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling /Nuxeo Drive Test Workspace/Test folder/new.odt for deletion: last_local_updated = 2014-09-15 13:58:19, last_sync_date = None
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local file '/Nuxeo Drive Test Workspace/Test folder/new.odt' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling joe.odt for deletion: last_local_updated = 2014-09-15 13:58:19, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local file '/Nuxeo Drive Test Workspace/Test folder/joe.odt' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local folder '/Nuxeo Drive Test Workspace/Test folder' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 8, local: 0.055s, remote: 0.111s sync: 0.089s
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 3251, 'lastSyncActiveRootDefinitions': u'default:a2462663-87c7-4786-bce3-c7a22345ec67'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 3251, "lastSyncActiveRootDefinitions": "default:a2462663-87c7-4786-bce3-c7a22345ec67"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"syncDate":1410782300000,"upperBound":3251,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:a2462663-87c7-4786-bce3-c7a22345ec67"}'
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 22 <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 23 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 24 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 25 <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 26 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 27 <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 28 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 29 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 30 <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 31 <FileDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 32 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 33 <FileDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 34 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 35 <DirDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: 36 <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Sorted events: [<FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt'>, <DirCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileCreatedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt'>, <FileModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/joe.odt'>, <FileDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/jack.odt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>, <FileDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1/sub file 1.txt'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>, <DirDeletedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'>, <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder'>]
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/new.odt', remote_name=None, local_state=u'unknown', remote_state=u'unknown', pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2', remote_name=None, local_state=u'unknown', remote_state=u'unknown', pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt', remote_name=None, local_state=u'unknown', remote_state=u'unknown', pair_state='unknown'>
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', remote_name=u'joe.odt', local_state=u'modified', remote_state=u'unknown', pair_state='locally_modified'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: INFO: Unhandle case: <DirModifiedEvent: src_path=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/Sub folder 1'> /Nuxeo Drive Test Workspace/Test folder/Sub folder 1 Sub folder 1
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#6e4a8e17-4be9-4e01-8d42-675156acce94"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: 'null'
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/joe.odt', remote_name=u'joe.odt', local_state=u'modified', remote_state='deleted', pair_state='remotely_deleted'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: TRACE: Handling joe.odt for deletion: last_local_updated = 2014-09-15 13:58:19, last_sync_date = 2014-09-15 13:58:15
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marking local file '/Nuxeo Drive Test Workspace/Test folder/joe.odt' as unsynchronized as it has been remotely deleted but locally modified (keeping local changes)
14:05:10 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: []
14:05:10 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2', remote_name=None, local_state='created', remote_state=u'unknown', pair_state='locally_created'>
14:05:10 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating remote folder 'Sub folder 2' in folder 'Test folder'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Sub folder 2', 'parentId': u'defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334'}}
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"name": "Sub folder 2", "parentId": "defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334"}}'
14:05:10 [INFO]      [exec] nxdrive.client.base_automation_client: DEBUG: Failed to invoke operation: NuxeoDrive.CreateFolder
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: DEBUG: {"entity-type":"exception","code":"org.nuxeo.ecm.automation.TraceException","status":500,"message":"Failed to invoke operation: NuxeoDrive.CreateFolder","stacktrace":"org.nuxeo.ecm.webengine.WebException: Failed to invoke operation: NuxeoDrive.CreateFolder\n\tat org.nuxeo.ecm.webengine.WebException.newException(WebException.java:136)\n\tat org.nuxeo.ecm.webengine.WebException.newException(WebException.java:123)\n\tat org.nuxeo.ecm.automation.server.jaxrs.ExecutableResource.doPost(ExecutableResource.java:73)\n\tat sun.reflect.GeneratedMethodAccessor188.invoke(Unknown Source)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:606)\n\tat com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)\n\tat com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ObjectOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:258)\n\tat com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)\n\tat com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)\n\tat com.sun.jersey.server.impl.uri.rules.SubLocatorRule.accept(SubLocatorRule.java:137)\n\tat com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)\n\tat com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)\n\tat com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)\n\tat com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)\n\tat com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)\n\tat com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)\n\tat com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)\n\tat com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)\n\tat com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)\n\tat com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)\n\tat com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)\n\tat org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet.containerService(WebEngineServlet.java:178)\n\tat org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet.service(WebEngineServlet.java:153)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:728)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.webengine.jaxrs.session.SessionCleanupFilter.run(SessionCleanupFilter.java:45)\n\tat org.nuxeo.ecm.webengine.jaxrs.HttpFilter.doFilter(HttpFilter.java:43)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.webengine.app.WebEngineFilter.doFilter(WebEngineFilter.java:92)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.webengine.jaxrs.context.RequestContextFilter.run(RequestContextFilter.java:42)\n\tat org.nuxeo.ecm.webengine.jaxrs.HttpFilter.doFilter(HttpFilter.java:43)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.wss.servlet.BaseWSSFilter.doFilter(BaseWSSFilter.java:137)\n\tat org.nuxeo.wss.servlet.FailSafeWSSFilter.doFilter(FailSafeWSSFilter.java:55)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.core.management.jtajca.internal.Log4jWebFilter.doFilter(Log4jWebFilter.java:67)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.ui.web.rest.FancyURLFilter.doFilter(FancyURLFilter.java:136)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.webdav.service.WIRequestFilter.doFilter(WIRequestFilter.java:60)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter.doFilter(NuxeoRequestControllerFilter.java:145)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter.doFilterInternal(NuxeoAuthenticationFilter.java:616)\n\tat org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain.doFilter(NuxeoAuthFilterChain.java:35)\n\tat org.nuxeo.ecm.platform.ui.web.auth.oauth2.NuxeoOAuth2Filter.doFilter(NuxeoOAuth2Filter.java:68)\n\tat org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain.doFilter(NuxeoAuthFilterChain.java:33)\n\tat org.nuxeo.ecm.platform.ui.web.auth.oauth.NuxeoOAuthFilter.doFilter(NuxeoOAuthFilter.java:119)\n\tat org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain.doFilter(NuxeoAuthFilterChain.java:33)\n\tat org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter.doFilter(NuxeoAuthenticationFilter.java:411)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoCorsFilter.doFilter(NuxeoCorsFilter.java:51)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.web.common.exceptionhandling.NuxeoExceptionFilter.doFilter(NuxeoExceptionFilter.java:79)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.nuxeo.ecm.platform.web.common.encoding.NuxeoEncodingFilter.doFilter(NuxeoEncodingFilter.java:69)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)\n\tat org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)\n\tat org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)\n\tat org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:1810)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:745)\nCaused by: org.nuxeo.ecm.automation.TraceException: \n\n****** chain ******\nName: NuxeoDrive.CreateFolder\nException: OperationException\nCaught error: Failed to invoke operation NuxeoDrive.CreateFolder\nCaused by: org.nuxeo.ecm.core.api.ClientException: Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.\n****** Hierarchy calls ******\n\torg.nuxeo.drive.operations.NuxeoDriveCreateFolder\n\n\tat org.nuxeo.ecm.automation.core.impl.OperationServiceImpl.run(OperationServiceImpl.java:197)\n\tat org.nuxeo.ecm.automation.core.impl.OperationServiceImpl.run(OperationServiceImpl.java:118)\n\tat org.nuxeo.ecm.automation.server.jaxrs.OperationResource.execute(OperationResource.java:51)\n\tat org.nuxeo.ecm.automation.server.jaxrs.ExecutableResource.doPost(ExecutableResource.java:60)\n\t... 82 more\nCaused by: org.nuxeo.ecm.automation.OperationException: Failed to invoke operation NuxeoDrive.CreateFolder\n\tat org.nuxeo.ecm.automation.core.impl.InvokableMethod.invoke(InvokableMethod.java:157)\n\tat org.nuxeo.ecm.automation.core.impl.CompiledChainImpl.doInvoke(CompiledChainImpl.java:124)\n\tat org.nuxeo.ecm.automation.core.impl.CompiledChainImpl.invoke(CompiledChainImpl.java:110)\n\tat org.nuxeo.ecm.automation.core.impl.OperationServiceImpl.run(OperationServiceImpl.java:171)\n\t... 85 more\nCaused by: org.nuxeo.ecm.core.api.ClientException: Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.\n\tat org.nuxeo.drive.service.impl.FileSystemItemManagerImpl.createFolder(FileSystemItemManagerImpl.java:193)\n\tat org.nuxeo.drive.operations.NuxeoDriveCreateFolder.run(NuxeoDriveCreateFolder.java:58)\n\tat sun.reflect.GeneratedMethodAccessor271.invoke(Unknown Source)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:606)\n\tat org.nuxeo.ecm.automation.core.impl.InvokableMethod.doInvoke(InvokableMethod.java:135)\n\tat org.nuxeo.ecm.automation.core.impl.InvokableMethod.invoke(InvokableMethod.java:149)\n\t... 88 more\n","exception":{"className":"org.nuxeo.ecm.automation.TraceException","rollback":true,"cause":{"className":"org.nuxeo.ecm.automation.OperationException","rollback":true,"cause":{"className":"org.nuxeo.ecm.core.api.ClientException","cause":null,"message":"Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.","localizedMessage":"Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.","stackTrace":[{"fileName":"FileSystemItemManagerImpl.java","lineNumber":193,"className":"org.nuxeo.drive.service.impl.FileSystemItemManagerImpl","methodName":"createFolder","nativeMethod":false},{"fileName":"NuxeoDriveCreateFolder.java","lineNumber":58,"className":"org.nuxeo.drive.operations.NuxeoDriveCreateFolder","methodName":"run","nativeMethod":false},{"fileName":null,"lineNumber":-1,"className":"sun.reflect.GeneratedMethodAccessor271","methodName":"invoke","nativeMethod":false},{"fileName":"DelegatingMethodAccessorImpl.java","lineNumber":43,"className":"sun.reflect.DelegatingMethodAccessorImpl","methodName":"invoke","nativeMethod":false},{"fileName":"Method.java","lineNumber":606,"className":"java.lang.reflect.Method","methodName":"invoke","nativeMethod":false},{"fileName":"InvokableMethod.java","lineNumber":135,"className":"org.nuxeo.ecm.automation.core.impl.InvokableMethod","methodName":"doInvoke","nativeMethod":false},{"fileName":"InvokableMethod.java","lineNumber":149,"className":"org.nuxeo.ecm.automation.core.impl.InvokableMethod","methodName":"invoke","nativeMethod":false},{"fileName":"CompiledChainImpl.java","lineNumber":124,"className":"org.nuxeo.ecm.automation.core.impl.CompiledChainImpl","methodName":"doInvoke","nativeMethod":false},{"fileName":"CompiledChainImpl.java","lineNumber":110,"className":"org.nuxeo.ecm.automation.core.impl.CompiledChainImpl","methodName":"invoke","nativeMethod":false},{"fileName":"OperationServiceImpl.java","lineNumber":171,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationServiceImpl.java","lineNumber":118,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationResource.java","lineNumber":51,"className":"org.nuxeo.ecm.automation.server.jaxrs.OperationResource","methodName":"execute","nativeMethod":false},{"fileName":"ExecutableResource.java","lineNumber":60,"className":"org.nuxeo.ecm.automation.server.jaxrs.ExecutableResource","methodName":"doPost","nativeMethod":false},{"fileName":null,"lineNumber":-1,"className":"sun.reflect.GeneratedMethodAccessor188","methodName":"invoke","nativeMethod":false},{"fileName":"DelegatingMethodAccessorImpl.java","lineNumber":43,"className":"sun.reflect.DelegatingMethodAccessorImpl","methodName":"invoke","nativeMethod":false},{"fileName":"Method.java","lineNumber":606,"className":"java.lang.reflect.Method","methodName":"invoke","nativeMethod":false},{"fileName":"JavaMethodInvokerFactory.java","lineNumber":60,"className":"com.sun.jersey.spi.container.JavaMethodInvokerFactory$1","methodName":"invoke","nativeMethod":false},{"fileName":"AbstractResourceMethodDispatchProvider.java","lineNumber":258,"className":"com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ObjectOutInvoker","methodName":"_dispatch","nativeMethod":false},{"fileName":"ResourceJavaMethodDispatcher.java","lineNumber":75,"className":"com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher","methodName":"dispatch","nativeMethod":false},{"fileName":"HttpMethodRule.java","lineNumber":302,"className":"com.sun.jersey.server.impl.uri.rules.HttpMethodRule","methodName":"accept","nativeMethod":false},{"fileName":"SubLocatorRule.java","lineNumber":137,"className":"com.sun.jersey.server.impl.uri.rules.SubLocatorRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"ResourceClassRule.java","lineNumber":108,"className":"com.sun.jersey.server.impl.uri.rules.ResourceClassRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"RootResourceClassesRule.java","lineNumber":84,"className":"com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule","methodName":"accept","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1511,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1442,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1391,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1381,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebComponent.java","lineNumber":416,"className":"com.sun.jersey.spi.container.servlet.WebComponent","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":538,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":716,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":178,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"containerService","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":153,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"service","nativeMethod":false},{"fileName":"HttpServlet.java","lineNumber":728,"className":"javax.servlet.http.HttpServlet","methodName":"service","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":305,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"SessionCleanupFilter.java","lineNumber":45,"className":"org.nuxeo.ecm.webengine.jaxrs.session.SessionCleanupFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WebEngineFilter.java","lineNumber":92,"className":"org.nuxeo.ecm.webengine.app.WebEngineFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"RequestContextFilter.java","lineNumber":42,"className":"org.nuxeo.ecm.webengine.jaxrs.context.RequestContextFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"BaseWSSFilter.java","lineNumber":137,"className":"org.nuxeo.wss.servlet.BaseWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"FailSafeWSSFilter.java","lineNumber":55,"className":"org.nuxeo.wss.servlet.FailSafeWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"Log4jWebFilter.java","lineNumber":67,"className":"org.nuxeo.ecm.core.management.jtajca.internal.Log4jWebFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"FancyURLFilter.java","lineNumber":136,"className":"org.nuxeo.ecm.platform.ui.web.rest.FancyURLFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WIRequestFilter.java","lineNumber":60,"className":"org.nuxeo.ecm.webdav.service.WIRequestFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoRequestControllerFilter.java","lineNumber":145,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":616,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilterInternal","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":35,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuth2Filter.java","lineNumber":68,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth2.NuxeoOAuth2Filter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuthFilter.java","lineNumber":119,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth.NuxeoOAuthFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":411,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoCorsFilter.java","lineNumber":51,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoCorsFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoExceptionFilter.java","lineNumber":79,"className":"org.nuxeo.ecm.platform.web.common.exceptionhandling.NuxeoExceptionFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoEncodingFilter.java","lineNumber":69,"className":"org.nuxeo.ecm.platform.web.common.encoding.NuxeoEncodingFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"StandardWrapperValve.java","lineNumber":222,"className":"org.apache.catalina.core.StandardWrapperValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardContextValve.java","lineNumber":123,"className":"org.apache.catalina.core.StandardContextValve","methodName":"invoke","nativeMethod":false},{"fileName":"AuthenticatorBase.java","lineNumber":502,"className":"org.apache.catalina.authenticator.AuthenticatorBase","methodName":"invoke","nativeMethod":false},{"fileName":"StandardHostValve.java","lineNumber":171,"className":"org.apache.catalina.core.StandardHostValve","methodName":"invoke","nativeMethod":false},{"fileName":"ErrorReportValve.java","lineNumber":99,"className":"org.apache.catalina.valves.ErrorReportValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardEngineValve.java","lineNumber":118,"className":"org.apache.catalina.core.StandardEngineValve","methodName":"invoke","nativeMethod":false},{"fileName":"CoyoteAdapter.java","lineNumber":408,"className":"org.apache.catalina.connector.CoyoteAdapter","methodName":"service","nativeMethod":false},{"fileName":"AbstractHttp11Processor.java","lineNumber":1023,"className":"org.apache.coyote.http11.AbstractHttp11Processor","methodName":"process","nativeMethod":false},{"fileName":"AbstractProtocol.java","lineNumber":589,"className":"org.apache.coyote.AbstractProtocol$AbstractConnectionHandler","methodName":"process","nativeMethod":false},{"fileName":"AprEndpoint.java","lineNumber":1810,"className":"org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor","methodName":"run","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":1145,"className":"java.util.concurrent.ThreadPoolExecutor","methodName":"runWorker","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":615,"className":"java.util.concurrent.ThreadPoolExecutor$Worker","methodName":"run","nativeMethod":false},{"fileName":"Thread.java","lineNumber":745,"className":"java.lang.Thread","methodName":"run","nativeMethod":false}],"suppressed":[]},"message":"Failed to invoke operation NuxeoDrive.CreateFolder","localizedMessage":"Failed to invoke operation NuxeoDrive.CreateFolder","stackTrace":[{"fileName":"InvokableMethod.java","lineNumber":157,"className":"org.nuxeo.ecm.automation.core.impl.InvokableMethod","methodName":"invoke","nativeMethod":false},{"fileName":"CompiledChainImpl.java","lineNumber":124,"className":"org.nuxeo.ecm.automation.core.impl.CompiledChainImpl","methodName":"doInvoke","nativeMethod":false},{"fileName":"CompiledChainImpl.java","lineNumber":110,"className":"org.nuxeo.ecm.automation.core.impl.CompiledChainImpl","methodName":"invoke","nativeMethod":false},{"fileName":"OperationServiceImpl.java","lineNumber":171,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationServiceImpl.java","lineNumber":118,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationResource.java","lineNumber":51,"className":"org.nuxeo.ecm.automation.server.jaxrs.OperationResource","methodName":"execute","nativeMethod":false},{"fileName":"ExecutableResource.java","lineNumber":60,"className":"org.nuxeo.ecm.automation.server.jaxrs.ExecutableResource","methodName":"doPost","nativeMethod":false},{"fileName":null,"lineNumber":-1,"className":"sun.reflect.GeneratedMethodAccessor188","methodName":"invoke","nativeMethod":false},{"fileName":"DelegatingMethodAccessorImpl.java","lineNumber":43,"className":"sun.reflect.DelegatingMethodAccessorImpl","methodName":"invoke","nativeMethod":false},{"fileName":"Method.java","lineNumber":606,"className":"java.lang.reflect.Method","methodName":"invoke","nativeMethod":false},{"fileName":"JavaMethodInvokerFactory.java","lineNumber":60,"className":"com.sun.jersey.spi.container.JavaMethodInvokerFactory$1","methodName":"invoke","nativeMethod":false},{"fileName":"AbstractResourceMethodDispatchProvider.java","lineNumber":258,"className":"com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ObjectOutInvoker","methodName":"_dispatch","nativeMethod":false},{"fileName":"ResourceJavaMethodDispatcher.java","lineNumber":75,"className":"com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher","methodName":"dispatch","nativeMethod":false},{"fileName":"HttpMethodRule.java","lineNumber":302,"className":"com.sun.jersey.server.impl.uri.rules.HttpMethodRule","methodName":"accept","nativeMethod":false},{"fileName":"SubLocatorRule.java","lineNumber":137,"className":"com.sun.jersey.server.impl.uri.rules.SubLocatorRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"ResourceClassRule.java","lineNumber":108,"className":"com.sun.jersey.server.impl.uri.rules.ResourceClassRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"RootResourceClassesRule.java","lineNumber":84,"className":"com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule","methodName":"accept","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1511,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1442,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1391,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1381,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebComponent.java","lineNumber":416,"className":"com.sun.jersey.spi.container.servlet.WebComponent","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":538,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":716,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":178,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"containerService","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":153,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"service","nativeMethod":false},{"fileName":"HttpServlet.java","lineNumber":728,"className":"javax.servlet.http.HttpServlet","methodName":"service","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":305,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"SessionCleanupFilter.java","lineNumber":45,"className":"org.nuxeo.ecm.webengine.jaxrs.session.SessionCleanupFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WebEngineFilter.java","lineNumber":92,"className":"org.nuxeo.ecm.webengine.app.WebEngineFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"RequestContextFilter.java","lineNumber":42,"className":"org.nuxeo.ecm.webengine.jaxrs.context.RequestContextFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"BaseWSSFilter.java","lineNumber":137,"className":"org.nuxeo.wss.servlet.BaseWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"FailSafeWSSFilter.java","lineNumber":55,"className":"org.nuxeo.wss.servlet.FailSafeWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"Log4jWebFilter.java","lineNumber":67,"className":"org.nuxeo.ecm.core.management.jtajca.internal.Log4jWebFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"FancyURLFilter.java","lineNumber":136,"className":"org.nuxeo.ecm.platform.ui.web.rest.FancyURLFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WIRequestFilter.java","lineNumber":60,"className":"org.nuxeo.ecm.webdav.service.WIRequestFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoRequestControllerFilter.java","lineNumber":145,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":616,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilterInternal","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":35,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuth2Filter.java","lineNumber":68,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth2.NuxeoOAuth2Filter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuthFilter.java","lineNumber":119,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth.NuxeoOAuthFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":411,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoCorsFilter.java","lineNumber":51,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoCorsFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoExceptionFilter.java","lineNumber":79,"className":"org.nuxeo.ecm.platform.web.common.exceptionhandling.NuxeoExceptionFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoEncodingFilter.java","lineNumber":69,"className":"org.nuxeo.ecm.platform.web.common.encoding.NuxeoEncodingFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"StandardWrapperValve.java","lineNumber":222,"className":"org.apache.catalina.core.StandardWrapperValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardContextValve.java","lineNumber":123,"className":"org.apache.catalina.core.StandardContextValve","methodName":"invoke","nativeMethod":false},{"fileName":"AuthenticatorBase.java","lineNumber":502,"className":"org.apache.catalina.authenticator.AuthenticatorBase","methodName":"invoke","nativeMethod":false},{"fileName":"StandardHostValve.java","lineNumber":171,"className":"org.apache.catalina.core.StandardHostValve","methodName":"invoke","nativeMethod":false},{"fileName":"ErrorReportValve.java","lineNumber":99,"className":"org.apache.catalina.valves.ErrorReportValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardEngineValve.java","lineNumber":118,"className":"org.apache.catalina.core.StandardEngineValve","methodName":"invoke","nativeMethod":false},{"fileName":"CoyoteAdapter.java","lineNumber":408,"className":"org.apache.catalina.connector.CoyoteAdapter","methodName":"service","nativeMethod":false},{"fileName":"AbstractHttp11Processor.java","lineNumber":1023,"className":"org.apache.coyote.http11.AbstractHttp11Processor","methodName":"process","nativeMethod":false},{"fileName":"AbstractProtocol.java","lineNumber":589,"className":"org.apache.coyote.AbstractProtocol$AbstractConnectionHandler","methodName":"process","nativeMethod":false},{"fileName":"AprEndpoint.java","lineNumber":1810,"className":"org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor","methodName":"run","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":1145,"className":"java.util.concurrent.ThreadPoolExecutor","methodName":"runWorker","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":615,"className":"java.util.concurrent.ThreadPoolExecutor$Worker","methodName":"run","nativeMethod":false},{"fileName":"Thread.java","lineNumber":745,"className":"java.lang.Thread","methodName":"run","nativeMethod":false}],"suppressed":[]},"message":"\n\n****** chain ******\nName: NuxeoDrive.CreateFolder\nException: OperationException\nCaught error: Failed to invoke operation NuxeoDrive.CreateFolder\nCaused by: org.nuxeo.ecm.core.api.ClientException: Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.\n****** Hierarchy calls ******\n\torg.nuxeo.drive.operations.NuxeoDriveCreateFolder\n","localizedMessage":"\n\n****** chain ******\nName: NuxeoDrive.CreateFolder\nException: OperationException\nCaught error: Failed to invoke operation NuxeoDrive.CreateFolder\nCaused by: org.nuxeo.ecm.core.api.ClientException: Cannot create a folder in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.\n****** Hierarchy calls ******\n\torg.nuxeo.drive.operations.NuxeoDriveCreateFolder\n","stackTrace":[{"fileName":"OperationServiceImpl.java","lineNumber":197,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationServiceImpl.java","lineNumber":118,"className":"org.nuxeo.ecm.automation.core.impl.OperationServiceImpl","methodName":"run","nativeMethod":false},{"fileName":"OperationResource.java","lineNumber":51,"className":"org.nuxeo.ecm.automation.server.jaxrs.OperationResource","methodName":"execute","nativeMethod":false},{"fileName":"ExecutableResource.java","lineNumber":60,"className":"org.nuxeo.ecm.automation.server.jaxrs.ExecutableResource","methodName":"doPost","nativeMethod":false},{"fileName":null,"lineNumber":-1,"className":"sun.reflect.GeneratedMethodAccessor188","methodName":"invoke","nativeMethod":false},{"fileName":"DelegatingMethodAccessorImpl.java","lineNumber":43,"className":"sun.reflect.DelegatingMethodAccessorImpl","methodName":"invoke","nativeMethod":false},{"fileName":"Method.java","lineNumber":606,"className":"java.lang.reflect.Method","methodName":"invoke","nativeMethod":false},{"fileName":"JavaMethodInvokerFactory.java","lineNumber":60,"className":"com.sun.jersey.spi.container.JavaMethodInvokerFactory$1","methodName":"invoke","nativeMethod":false},{"fileName":"AbstractResourceMethodDispatchProvider.java","lineNumber":258,"className":"com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ObjectOutInvoker","methodName":"_dispatch","nativeMethod":false},{"fileName":"ResourceJavaMethodDispatcher.java","lineNumber":75,"className":"com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher","methodName":"dispatch","nativeMethod":false},{"fileName":"HttpMethodRule.java","lineNumber":302,"className":"com.sun.jersey.server.impl.uri.rules.HttpMethodRule","methodName":"accept","nativeMethod":false},{"fileName":"SubLocatorRule.java","lineNumber":137,"className":"com.sun.jersey.server.impl.uri.rules.SubLocatorRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"ResourceClassRule.java","lineNumber":108,"className":"com.sun.jersey.server.impl.uri.rules.ResourceClassRule","methodName":"accept","nativeMethod":false},{"fileName":"RightHandPathRule.java","lineNumber":147,"className":"com.sun.jersey.server.impl.uri.rules.RightHandPathRule","methodName":"accept","nativeMethod":false},{"fileName":"RootResourceClassesRule.java","lineNumber":84,"className":"com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule","methodName":"accept","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1511,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1442,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"_handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1391,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebApplicationImpl.java","lineNumber":1381,"className":"com.sun.jersey.server.impl.application.WebApplicationImpl","methodName":"handleRequest","nativeMethod":false},{"fileName":"WebComponent.java","lineNumber":416,"className":"com.sun.jersey.spi.container.servlet.WebComponent","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":538,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"ServletContainer.java","lineNumber":716,"className":"com.sun.jersey.spi.container.servlet.ServletContainer","methodName":"service","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":178,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"containerService","nativeMethod":false},{"fileName":"WebEngineServlet.java","lineNumber":153,"className":"org.nuxeo.ecm.webengine.app.jersey.WebEngineServlet","methodName":"service","nativeMethod":false},{"fileName":"HttpServlet.java","lineNumber":728,"className":"javax.servlet.http.HttpServlet","methodName":"service","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":305,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"SessionCleanupFilter.java","lineNumber":45,"className":"org.nuxeo.ecm.webengine.jaxrs.session.SessionCleanupFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WebEngineFilter.java","lineNumber":92,"className":"org.nuxeo.ecm.webengine.app.WebEngineFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"RequestContextFilter.java","lineNumber":42,"className":"org.nuxeo.ecm.webengine.jaxrs.context.RequestContextFilter","methodName":"run","nativeMethod":false},{"fileName":"HttpFilter.java","lineNumber":43,"className":"org.nuxeo.ecm.webengine.jaxrs.HttpFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"BaseWSSFilter.java","lineNumber":137,"className":"org.nuxeo.wss.servlet.BaseWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"FailSafeWSSFilter.java","lineNumber":55,"className":"org.nuxeo.wss.servlet.FailSafeWSSFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"Log4jWebFilter.java","lineNumber":67,"className":"org.nuxeo.ecm.core.management.jtajca.internal.Log4jWebFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"FancyURLFilter.java","lineNumber":136,"className":"org.nuxeo.ecm.platform.ui.web.rest.FancyURLFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"WIRequestFilter.java","lineNumber":60,"className":"org.nuxeo.ecm.webdav.service.WIRequestFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoRequestControllerFilter.java","lineNumber":145,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":616,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilterInternal","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":35,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuth2Filter.java","lineNumber":68,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth2.NuxeoOAuth2Filter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoOAuthFilter.java","lineNumber":119,"className":"org.nuxeo.ecm.platform.ui.web.auth.oauth.NuxeoOAuthFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthFilterChain.java","lineNumber":33,"className":"org.nuxeo.ecm.platform.ui.web.auth.service.NuxeoAuthFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoAuthenticationFilter.java","lineNumber":411,"className":"org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoCorsFilter.java","lineNumber":51,"className":"org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoCorsFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoExceptionFilter.java","lineNumber":79,"className":"org.nuxeo.ecm.platform.web.common.exceptionhandling.NuxeoExceptionFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"NuxeoEncodingFilter.java","lineNumber":69,"className":"org.nuxeo.ecm.platform.web.common.encoding.NuxeoEncodingFilter","methodName":"doFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":243,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"internalDoFilter","nativeMethod":false},{"fileName":"ApplicationFilterChain.java","lineNumber":210,"className":"org.apache.catalina.core.ApplicationFilterChain","methodName":"doFilter","nativeMethod":false},{"fileName":"StandardWrapperValve.java","lineNumber":222,"className":"org.apache.catalina.core.StandardWrapperValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardContextValve.java","lineNumber":123,"className":"org.apache.catalina.core.StandardContextValve","methodName":"invoke","nativeMethod":false},{"fileName":"AuthenticatorBase.java","lineNumber":502,"className":"org.apache.catalina.authenticator.AuthenticatorBase","methodName":"invoke","nativeMethod":false},{"fileName":"StandardHostValve.java","lineNumber":171,"className":"org.apache.catalina.core.StandardHostValve","methodName":"invoke","nativeMethod":false},{"fileName":"ErrorReportValve.java","lineNumber":99,"className":"org.apache.catalina.valves.ErrorReportValve","methodName":"invoke","nativeMethod":false},{"fileName":"StandardEngineValve.java","lineNumber":118,"className":"org.apache.catalina.core.StandardEngineValve","methodName":"invoke","nativeMethod":false},{"fileName":"CoyoteAdapter.java","lineNumber":408,"className":"org.apache.catalina.connector.CoyoteAdapter","methodName":"service","nativeMethod":false},{"fileName":"AbstractHttp11Processor.java","lineNumber":1023,"className":"org.apache.coyote.http11.AbstractHttp11Processor","methodName":"process","nativeMethod":false},{"fileName":"AbstractProtocol.java","lineNumber":589,"className":"org.apache.coyote.AbstractProtocol$AbstractConnectionHandler","methodName":"process","nativeMethod":false},{"fileName":"AprEndpoint.java","lineNumber":1810,"className":"org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor","methodName":"run","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":1145,"className":"java.util.concurrent.ThreadPoolExecutor","methodName":"runWorker","nativeMethod":false},{"fileName":"ThreadPoolExecutor.java","lineNumber":615,"className":"java.util.concurrent.ThreadPoolExecutor$Worker","methodName":"run","nativeMethod":false},{"fileName":"Thread.java","lineNumber":745,"className":"java.lang.Thread","methodName":"run","nativeMethod":false}],"suppressed":[]}}
14:05:11 [INFO]      [exec] nxdrive.synchronizer: ERROR: Failed to sync LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2', remote_name=None, local_state=u'created', remote_state=u'unknown', pair_state=u'locally_created', error_count=0>, blacklisting doc pair for 300 seconds
14:05:11 [INFO]      [exec] Traceback (most recent call last):
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 1385, in synchronize
14:05:11 [INFO]      [exec]     self.synchronize_one(pair_state, session=session)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 767, in synchronize_one
14:05:11 [INFO]      [exec]     local_info, remote_info)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 915, in _synchronize_locally_created
14:05:11 [INFO]      [exec]     remote_ref = remote_client.make_folder(parent_ref, name)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/remote_file_system_client.py", line 107, in make_folder
14:05:11 [INFO]      [exec]     parentId=parent_id, name=name)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/base_automation_client.py", line 309, in execute
14:05:11 [INFO]      [exec]     resp = self.opener.open(req, timeout=timeout)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 410, in open
14:05:11 [INFO]      [exec]     response = meth(req, response)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 523, in http_response
14:05:11 [INFO]      [exec]     'http', request, response, code, msg, hdrs)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 448, in error
14:05:11 [INFO]      [exec]     return self._call_chain(*args)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 382, in _call_chain
14:05:11 [INFO]      [exec]     result = func(*args)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 531, in http_error_default
14:05:11 [INFO]      [exec]     raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
14:05:11 [INFO]      [exec] HTTPError: HTTP Error 500: Internal Server Error
14:05:11 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt', remote_name=None, local_state='created', remote_state=u'unknown', pair_state='locally_created'>
14:05:11 [INFO]      [exec] nxdrive.synchronizer: WARNING: Won't synchronize file 'sub file 2.txt' created in local folder 'Sub folder 2' since it is readonly
14:05:11 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/Sub folder 2/sub file 2.txt', remote_name=None, local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
14:05:11 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive: [u'sub file 2.txt']
14:05:11 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/new.odt', remote_name=None, local_state='created', remote_state=u'unknown', pair_state='locally_created'>
14:05:11 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating remote document 'new.odt' in folder 'Test folder'
14:05:11 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'new.odt'
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 11, 'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 11, 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410782303.5_600905104', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'new.odt', 'X-Client-Version': '1.3-dev'} and cookies [] for file /tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder/new.odt
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410782303.5_600905104"}'
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410782303.5_600905104', 'operationId': 'NuxeoDrive.CreateFile', 'fileIdx': '0', 'parentId': u'defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334'}}
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Authentication-Token': '0e83400e-0ece-4113-9a40-d8a877d70399', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'925262d03ccf11e4832c40408687c0a8', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-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': '1.3-dev'}, cookies [] and JSON payload '{"params": {"batchId": "1410782303.5_600905104", "operationId": "NuxeoDrive.CreateFile", "fileIdx": "0", "parentId": "defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334"}}'
14:05:11 [INFO]      [exec] nxdrive.client.base_automation_client: DEBUG: {"error" : "
14:05:11 [INFO]      [exec] ****** chain ******
14:05:11 [INFO]      [exec] Name: NuxeoDrive.CreateFile
14:05:11 [INFO]      [exec] Exception: OperationException
14:05:11 [INFO]      [exec] Caught error: Failed to invoke operation NuxeoDrive.CreateFile
14:05:11 [INFO]      [exec] Caused by: org.nuxeo.ecm.core.api.ClientException: Cannot create a file in file system item with id defaultFileSystemItemFactory#default#b07ac018-cb9d-4952-8a87-5bde4addf334 because it doesn't exist.
14:05:11 [INFO]      [exec] ****** Hierarchy calls ******
14:05:11 [INFO]      [exec] 	org.nuxeo.drive.operations.NuxeoDriveCreateFile
14:05:11 [INFO]      [exec] "}
14:05:11 [INFO]      [exec] nxdrive.synchronizer: ERROR: Failed to sync LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/new.odt', remote_name=None, local_state=u'created', remote_state=u'unknown', pair_state=u'locally_created', error_count=0>, blacklisting doc pair for 300 seconds
14:05:11 [INFO]      [exec] Traceback (most recent call last):
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 1385, in synchronize
14:05:11 [INFO]      [exec]     self.synchronize_one(pair_state, session=session)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 767, in synchronize_one
14:05:11 [INFO]      [exec]     local_info, remote_info)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/synchronizer.py", line 920, in _synchronize_locally_created
14:05:11 [INFO]      [exec]     parent_ref, doc_pair.get_local_abspath(), filename=name)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/remote_file_system_client.py", line 124, in stream_file
14:05:11 [INFO]      [exec]     parentId=parent_id)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/base_automation_client.py", line 326, in execute_with_blob_streaming
14:05:11 [INFO]      [exec]     return self.execute_batch(command, batch_id, '0', **params)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/base_automation_client.py", line 392, in execute_batch
14:05:11 [INFO]      [exec]     check_params=False, **params)
14:05:11 [INFO]      [exec]   File "/opt/hudson/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/client/base_automation_client.py", line 309, in execute
14:05:11 [INFO]      [exec]     resp = self.opener.open(req, timeout=timeout)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 410, in open
14:05:11 [INFO]      [exec]     response = meth(req, response)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 523, in http_response
14:05:11 [INFO]      [exec]     'http', request, response, code, msg, hdrs)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 448, in error
14:05:11 [INFO]      [exec]     return self._call_chain(*args)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 382, in _call_chain
14:05:11 [INFO]      [exec]     result = func(*args)
14:05:11 [INFO]      [exec]   File "/usr/lib/python2.7/urllib2.py", line 531, in http_error_default
14:05:11 [INFO]      [exec]     raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
14:05:11 [INFO]      [exec] HTTPError: HTTP Error 500: Internal Server Error
14:05:11 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/tmp/tmplaItZP-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 2, pending: 4, local: 3.059s, remote: 0.020s sync: 0.208s
14:05:11 [INFO]      [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 2 loops
14:05:11 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session
14:05:11 [INFO]      [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x7fc478f98e50>, ending any transaction in progress and releasing underlying connections from the pool
14:05:11 [INFO]      [exec] --------------------- >> end captured logging << ---------------------

Attachments

Issue Links

is required by

NXDRIVE-69 Drive build safety check up

Resolved

Activity

People

Assignee:

Antoine Taillefer

Reporter:

Antoine Taillefer

Participants:

Antoine Taillefer, Jenkins

Votes:

0 Vote for this issue

Watchers:

2 Start watching this issue

Dates

Created:

2014-09-15 13:07

Updated:

2014-09-23 16:29

Resolved:

2014-09-15 14:53