Minor See http://qa.nuxeo.org/jenkins/view/Drive/job/FT-nuxeo-drive-master-osx/558/
20:13:42 [INFO] [exec] ====================================================================== 20:13:42 [INFO] [exec] FAIL: test_delete_local_folder_2_clients (nxdrive.tests.test_integration_concurrent_synchronization.TestIntegrationConcurrentSynchronization) 20:13:42 [INFO] [exec] ---------------------------------------------------------------------- 20:13:42 [INFO] [exec] Traceback (most recent call last): 20:13:42 [INFO] [exec] File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_integration_concurrent_synchronization.py", line 162, in test_delete_local_folder_2_clients 20:13:42 [INFO] [exec] '/Nuxeo Drive Test Workspace/Test folder')) 20:13:42 [INFO] [exec] AssertionError: True is not false 20:13:42 [INFO] [exec] -------------------- >> begin captured logging << -------------------- 20:13:42 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive' 20:13:42 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/nuxeo-drive-conf' 20:13:42 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl. 20:13:42 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL. 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed. 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision. 20:13:42 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev 20:13:42 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive' 20:13:42 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/nuxeo-drive-conf' 20:13:42 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl. 20:13:42 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL. 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed. 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6 20:13:42 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision. 20:13:42 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev 20:13:42 [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 [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}} 20:13:42 [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": "/"}}' 20:13:42 [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":"a6a04ecf-2252-4813-8693-4d05941775e3","path":"/","type":"Root","state":null,"parentRef":"/","versionLabel":"","isCheckedOut":true,"title":"a6a04ecf-2252-4813-8693-4d05941775e3","properties":{"dc:creator":null,"dc:source":null,"dc:contributors":[],"dc:nature":null,"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":{}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}} 20:13:42 [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"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] has content-type 'text/plain' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}} 20:13:42 [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"}}' 20:13:42 [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":"835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"d1711f2f-dee1-4e2a-a2ca-fa07766b3403","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-14T19:05:12.40Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-11-14T19:05:12.40Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:12.40Z","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:useCaptcha":null,"webc:welcomeText":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":"1415991912407","contextParameters":{}}' 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"params": {"value": "835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [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":"835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"d1711f2f-dee1-4e2a-a2ca-fa07766b3403","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-14T19:05:12.40Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-11-14T19:05:12.40Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:12.40Z","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:useCaptcha":null,"webc:welcomeText":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":"1415991912407","contextParameters":{}}' 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2NTJiNGM='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2NTJiNGM='}, cookies [] and JSON payload '{"params": {"value": "835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [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":"835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"d1711f2f-dee1-4e2a-a2ca-fa07766b3403","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-14T19:05:12.40Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-11-14T19:05:12.40Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:12.40Z","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:useCaptcha":null,"webc:welcomeText":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":"1415991912407","contextParameters":{}}' 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2NTJiNGM='} and cookies [] 20:13:42 [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'2616316e6c3111e4bca1002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Mac+OSX+Desktop&revoke=false&deviceId=2616316e6c3111e4bca1002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Got token '35637f8a-6d2c-4433-b60e-818a6204493a' with cookies [] 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Binding '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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 [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":false,"canDelete":false,"parentId":null,"lastModificationDate":602,"creationDate":602,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00' 20:13:42 [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-11-14 20:05:13.636231 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.1-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/"}' 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Fetched update info from server: {u'serverVersion': u'7.1-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/'} 20:13:42 [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'262846a66c3111e4b7df002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Mac+OSX+Desktop&revoke=false&deviceId=262846a66c3111e4b7df002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='} and cookies [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Got token 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0' with cookies [] 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Binding '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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 [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":false,"canDelete":false,"parentId":null,"lastModificationDate":896,"creationDate":896,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00' 20:13:42 [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-11-14 20:05:13.904431 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.1-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/"}' 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Fetched update info from server: {u'serverVersion': u'7.1-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/'} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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 [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:835cc0a5-79e6-432c-8a0c-5d208a18d019', 'params': {'enable': True}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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:835cc0a5-79e6-432c-8a0c-5d208a18d019", "params": {"enable": true}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type '' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetRoots 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"params": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetRoots' with cookies []: '{"entity-type":"documents","entries":[{"entity-type":"document","repository":"default","uid":"835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"d1711f2f-dee1-4e2a-a2ca-fa07766b3403","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-14T19:05:14.10Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator","nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-11-14T19:05:12.40Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:14.10Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"drv:subscriptions":[{"enabled":true,"username":"nuxeoDriveTestUser_user_1","lastChangeDate":"2014-11-14T19:05:14.10Z"}],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:useCaptcha":null,"webc:welcomeText":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","DriveSynchronized"],"changeToken":"1415991914104","contextParameters":{}}]}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type '' 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":42,"fileSystemChanges":[],"syncDate":1415991914000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote full scan of /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":false,"canDelete":false,"parentId":null,"lastModificationDate":500,"creationDate":500,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [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' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","canRename":true,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1415991914104,"creationDate":1415991912407,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:14 and updated last_sync_date to 2014-11-14 20:05:14.563707 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [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='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019', 'parentId': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019", "parentId": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","canRename":true,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1415991914104,"creationDate":1415991912407,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-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'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110522d50>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive/' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-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'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.021s, remote: 0.240s sync: 0.131s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110522790>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":47,"fileSystemChanges":[],"syncDate":1415991914000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote full scan of /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":false,"canDelete":false,"parentId":null,"lastModificationDate":837,"creationDate":837,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [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' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","canRename":true,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1415991914104,"creationDate":1415991912407,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:14 and updated last_sync_date to 2014-11-14 20:05:14.894831 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [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='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019', 'parentId': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019", "parentId": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","canRename":true,"canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1415991914104,"creationDate":1415991912407,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state='created', pair_state='remotely_created'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110501750>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive/' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:14', '2014-11-14 20:05:14' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/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'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.020s, remote: 0.164s sync: 0.165s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110607f90>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:835cc0a5-79e6-432c-8a0c-5d208a18d019', 'params': {'type': 'Folder', 'name': 'Test folder', 'properties': 'dc:title=Test folder'}} 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"input": "doc:835cc0a5-79e6-432c-8a0c-5d208a18d019", "params": {"type": "Folder", "name": "Test folder", "properties": "dc:title=Test folder"}}' 20:13:42 [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":"307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder","type":"Folder","state":"project","parentRef":"835cc0a5-79e6-432c-8a0c-5d208a18d019","versionLabel":"","isCheckedOut":true,"title":"Test folder","lastModified":"2014-11-14T19:05:15.17Z","properties":{"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-11-14T19:05:15.17Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:15.17Z","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":"1415991915172","contextParameters":{}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:307007d5-9c0f-406f-a45d-6e0a510c249d', 'params': {'type': 'File', 'name': 'test.odt', 'properties': 'dc:title=test.odt'}} 20:13:42 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"input": "doc:307007d5-9c0f-406f-a45d-6e0a510c249d", "params": {"type": "File", "name": "test.odt", "properties": "dc:title=test.odt"}}' 20:13:42 [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":"9a114e62-60e1-4f21-bc61-c28585618459","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test folder/test.odt","type":"File","state":"project","parentRef":"307007d5-9c0f-406f-a45d-6e0a510c249d","versionLabel":"0.0","isCheckedOut":true,"title":"test.odt","lastModified":"2014-11-14T19:05:15.26Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-11-14T19:05:15.26Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-14T19:05:15.26Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test.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":"1415991915264","contextParameters":{}}' 20:13:42 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'test.odt' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 13, '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': 13, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1415991915.32_835190434', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test.odt'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpd4sciK-nxdrive-uploads/tmpQm2KjX-nxdrive-file-to-upload 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1415991915.32_835190434"}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpd4sciK-nxdrive-uploads/tmpQm2KjX-nxdrive-file-to-upload 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1415991915.32_835190434', 'document': u'9a114e62-60e1-4f21-bc61-c28585618459', 'fileIdx': '0', 'operationId': 'Blob.Attach'}} 20:13:42 [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', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"params": {"batchId": "1415991915.32_835190434", "document": "9a114e62-60e1-4f21-bc61-c28585618459", "fileIdx": "0", "operationId": "Blob.Attach"}}' 20:13:42 [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' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 20:13:42 [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": {}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type '' 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 42, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": 42, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":61,"fileSystemChanges":[{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","eventDate":1415991915636,"repositoryId":"default","fileSystemItem":{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"test.odt","docUuid":"9a114e62-60e1-4f21-bc61-c28585618459"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","eventDate":1415991915264,"repositoryId":"default","fileSystemItem":{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"test.odt","docUuid":"9a114e62-60e1-4f21-bc61-c28585618459"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","eventDate":1415991915172,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","canRename":true,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","lastModificationDate":1415991915172,"creationDate":1415991915172,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"307007d5-9c0f-406f-a45d-6e0a510c249d"}],"syncDate":1415991915000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: 3 remote changes detected on http://localhost:8080/nuxeo/ 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'test.odt', uid=u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', parent_uid=u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', folderish=False, last_modification_time=datetime.datetime(2014, 11, 14, 20, 5, 15), digest=u'b8ab309a6b9a3f448092a136afa8fa25', digest_algorithm=u'md5', download_url=u'nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False) 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'test.odt', uid=u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', parent_uid=u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', folderish=False, last_modification_time=datetime.datetime(2014, 11, 14, 20, 5, 15), digest=u'b8ab309a6b9a3f448092a136afa8fa25', digest_algorithm=u'md5', download_url=u'nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False) 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:15 and updated last_sync_date to 2014-11-14 20:05:16.034105 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [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='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Test folder' as remote creation 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Test folder 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:15 and updated last_sync_date to 2014-11-14 20:05:16.106202 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 2 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', 'parentId': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d", "parentId": "defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","canRename":true,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","lastModificationDate":1415991915172,"creationDate":1415991915172,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-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'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110522d50>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Test folder' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Test folder 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-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'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', 'parentId': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#9a114e62-60e1-4f21-bc61-c28585618459", "parentId": "defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110522d50>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local file 'test.odt' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', 'parentId': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#9a114e62-60e1-4f21-bc61-c28585618459", "parentId": "defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt' with headers: {'X-Authentication-Token': '35637f8a-6d2c-4433-b60e-818a6204493a', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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'} 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/test.odt', remote_name=u'test.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [u'test.odt'] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 2, pending: 2, local: 0.033s, remote: 0.308s sync: 0.410s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110522790>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 47, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": 47, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":68,"fileSystemChanges":[{"eventId":"documentModified","fileSystemItemId":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","eventDate":1415991915636,"repositoryId":"default","fileSystemItem":{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"test.odt","docUuid":"9a114e62-60e1-4f21-bc61-c28585618459"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","eventDate":1415991915264,"repositoryId":"default","fileSystemItem":{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"test.odt","docUuid":"9a114e62-60e1-4f21-bc61-c28585618459"},{"eventId":"documentCreated","fileSystemItemId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","eventDate":1415991915172,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","canRename":true,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","lastModificationDate":1415991915172,"creationDate":1415991915172,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemName":"Test folder","docUuid":"307007d5-9c0f-406f-a45d-6e0a510c249d"}],"syncDate":1415991916000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: 3 remote changes detected on http://localhost:8080/nuxeo/ 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'test.odt', uid=u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', parent_uid=u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', folderish=False, last_modification_time=datetime.datetime(2014, 11, 14, 20, 5, 15), digest=u'b8ab309a6b9a3f448092a136afa8fa25', digest_algorithm=u'md5', download_url=u'nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False) 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'test.odt', uid=u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', parent_uid=u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', folderish=False, last_modification_time=datetime.datetime(2014, 11, 14, 20, 5, 15), digest=u'b8ab309a6b9a3f448092a136afa8fa25', digest_algorithm=u'md5', download_url=u'nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False) 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:15 and updated last_sync_date to 2014-11-14 20:05:16.715758 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [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='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Test folder' as remote creation 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Test folder 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-14 20:05:15 and updated last_sync_date to 2014-11-14 20:05:16.865308 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=None, remote_state='modified', pair_state='unknown'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 2 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', 'parentId': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d", "parentId": "defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","canRename":true,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","lastModificationDate":1415991915172,"creationDate":1415991915172,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state='created', pair_state='remotely_created'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110501750>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test folder', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Test folder' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive/Nuxeo Drive Test Workspace' 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Test folder 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/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'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', 'parentId': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#9a114e62-60e1-4f21-bc61-c28585618459", "parentId": "defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x110501750>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local file 'test.odt' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459', 'parentId': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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#9a114e62-60e1-4f21-bc61-c28585618459", "parentId": "defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","downloadURL":"nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt","digestAlgorithm":"md5","canUpdate":true,"name":"test.odt","id":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d/defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","canRename":true,"canDelete":true,"parentId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","lastModificationDate":1415991915623,"creationDate":1415991915264,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/9a114e62-60e1-4f21-bc61-c28585618459/blobholder:0/test.odt' with headers: {'X-Authentication-Token': 'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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'} 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/test.odt', remote_name=u'test.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [u'test.odt'] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 2, pending: 2, local: 0.060s, remote: 0.306s sync: 0.375s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110607f90>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.client.local_client: TRACE: Send /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test folder to trash 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=60895) 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive: [u'test.odt'] 20:13:42 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [u'test.odt'] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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 [] 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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 [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 61, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": 61, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 68, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": 68, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":75,"fileSystemChanges":[],"syncDate":1415991920000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":75,"fileSystemChanges":[],"syncDate":1415991920000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.044s, remote: 0.333s sync: 0.047s 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Sleeping 0.564s 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Marking u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d' as locally deleted 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Marking u'defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459' as locally deleted 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/test.odt', remote_name=u'test.odt', local_state='deleted', remote_state=u'synchronized', pair_state='locally_deleted'> 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state='deleted', remote_state=u'synchronized', pair_state='locally_deleted'> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 2 pending items 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state=u'deleted', remote_state=u'synchronized', pair_state=u'locally_deleted', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder/test.odt', remote_name=u'test.odt', local_state=u'deleted', remote_state=u'synchronized', pair_state=u'locally_deleted', error_count=0>] 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state=u'deleted', remote_state=u'synchronized', pair_state=u'locally_deleted', error_count=0> 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', 'parentId': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d", "parentId": "defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Test folder","id":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019/defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","canRename":true,"canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019","lastModificationDate":1415991915172,"creationDate":1415991915172,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}' 20:13:42 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-14 20:05:15', '2014-11-14 20:05:15' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_locally_deleted of <nxdrive.synchronizer.Synchronizer object at 0x110522d50>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test folder', remote_name=u'Test folder', local_state=u'deleted', remote_state=u'synchronized', pair_state=u'locally_deleted', error_count=0> 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Deleting or unregistering remote document 'Test folder' (defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d) 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d', 'parentId': u'defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Delete with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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#307007d5-9c0f-406f-a45d-6e0a510c249d", "parentId": "defaultSyncRootFolderItemFactory#default#835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 75, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": 75, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":75,"fileSystemChanges":[],"syncDate":1415991920000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.032s, remote: 0.057s sync: 0.018s 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Sleeping 0.889s 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 75, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'd4b88c89-b60c-4f82-b56c-0c0905acc8f0', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'262846a66c3111e4b7df002500d3a152', '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": 75, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":75,"fileSystemChanges":[],"syncDate":1415991921000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwaWLhr-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.034s, remote: 0.036s sync: 0.018s 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Sleeping 0.908s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 3 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110f788d0>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Delete' with cookies [] has content-type '' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Handling test.odt for deletion: last_local_updated = 2014-11-14 20:05:16, last_sync_date = 2014-11-14 20:05:16 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Handling Test folder for deletion: last_local_updated = 2014-11-14 20:05:16, last_sync_date = 2014-11-14 20:05:16 20:13:42 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive: [] 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 2, local: 0.118s, remote: 0.380s sync: 3.834s 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 75, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": 75, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":80,"fileSystemChanges":[{"eventId":"deleted","fileSystemItemId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","eventDate":1415991920506,"repositoryId":"default","fileSystemItem":null,"fileSystemItemName":"Test folder","docUuid":"307007d5-9c0f-406f-a45d-6e0a510c249d"},{"eventId":"deleted","fileSystemItemId":"defaultFileSystemItemFactory#default#307007d5-9c0f-406f-a45d-6e0a510c249d","eventDate":1415991920486,"repositoryId":"default","fileSystemItem":null,"fileSystemItemName":"Test folder","docUuid":"307007d5-9c0f-406f-a45d-6e0a510c249d"}],"syncDate":1415991924000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: 2 remote changes detected on http://localhost:8080/nuxeo/ 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.029s, remote: 0.112s sync: 0.022s 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Sleeping 0.834s 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 80, 'lastSyncActiveRootDefinitions': u'default:835cc0a5-79e6-432c-8a0c-5d208a18d019'}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': u'35637f8a-6d2c-4433-b60e-818a6204493a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2616316e6c3111e4bca1002500d3a152', '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": 80, "lastSyncActiveRootDefinitions": "default:835cc0a5-79e6-432c-8a0c-5d208a18d019"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":96,"fileSystemChanges":[{"eventId":"deleted","fileSystemItemId":"defaultFileSystemItemFactory#default#9a114e62-60e1-4f21-bc61-c28585618459","eventDate":1415991924175,"repositoryId":"default","fileSystemItem":null,"fileSystemItemName":"test.odt","docUuid":"9a114e62-60e1-4f21-bc61-c28585618459"}],"syncDate":1415991925000,"activeSynchronizationRootDefinitions":"default:835cc0a5-79e6-432c-8a0c-5d208a18d019","hasTooManyChanges":false}' 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: 1 remote changes detected on http://localhost:8080/nuxeo/ 20:13:42 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpOCFNIE-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.025s, remote: 0.078s sync: 0.018s 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Sleeping 0.876s 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 3 loops 20:13:42 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 20:13:42 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x110d7d610>, ending any transaction in progress and releasing underlying connections from the pool 20:13:42 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:uuid = '307007d5-9c0f-406f-a45d-6e0a510c249d' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}} 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMToxMWVjYmY='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:uuid = \'307007d5-9c0f-406f-a45d-6e0a510c249d\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}' 20:13:42 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":0,"pageSize":0,"maxPageSize":1000,"currentPageSize":0,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":0,"pageIndex":0,"pageCount":1,"entries":[]}' 20:13:42 [INFO] [exec] --------------------- >> end captured logging << ---------------------
- is required by
-
NXDRIVE-170 Refactor functional test framework to run the ndrive program instead of relying on its implementation
-
- Resolved
-
