Drive: investigate on randomly failing test_versioning

22:14:13 ======================================================================
22:14:13 FAIL: test_versioning (nxdrive.tests.test_integration_versioning.TestIntegrationVersioning)
22:14:13 ----------------------------------------------------------------------
22:14:13 Traceback (most recent call last):
22:14:13   File "/home/hudson/tmp/workspace/IT-nuxeo-drive-5.6.0-linux/nuxeo-drive-client/nxdrive/tests/test_integration_versioning.py", line 77, in test_versioning
22:14:13     self._assert_version(doc, '0', '1')
22:14:13   File "/home/hudson/tmp/workspace/IT-nuxeo-drive-5.6.0-linux/nuxeo-drive-client/nxdrive/tests/test_integration_versioning.py", line 135, in _assert_version
22:14:13     self.assertEquals(doc['properties']['uid:minor_version'], minor)
22:14:13 AssertionError: u'2' != '1'
22:14:13 -------------------- >> begin captured logging << --------------------
22:14:13 nxdrive.controller: DEBUG: nxdrive installed in '/home/hudson/tmp/workspace/IT-nuxeo-drive-5.6.0-linux/nuxeo-drive-client/nxdrive'
22:14:13 nxdrive.controller: DEBUG: nxdrive configured in '/tmp/tmpBxoTeC-nxdrive-tests-user-1/nuxeo-drive-conf'
22:14:13 nxdrive.model: DEBUG: Set client version to 1.2-dev
22:14:13 nxdrive.controller: DEBUG: nxdrive installed in '/home/hudson/tmp/workspace/IT-nuxeo-drive-5.6.0-linux/nuxeo-drive-client/nxdrive'
22:14:13 nxdrive.controller: DEBUG: nxdrive configured in '/tmp/tmpscOWaS-nxdrive-tests-user-2/nuxeo-drive-conf'
22:14:13 nxdrive.model: DEBUG: Set client version to 1.2-dev
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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": "/"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"5769f5d4-d947-41cd-b242-250e4e6f876b","path":"/","type":"Root","state":null,"versionLabel":"","title":"5769f5d4-d947-41cd-b242-250e4e6f876b","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"],"changeToken":null,"contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] and content-type: 'text/plain'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","title":"Nuxeo Drive Test Workspace","lastModified":"2014-01-09T21:13:42.06Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-01-09T21:13:42.06Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:42.06Z","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":["WebView","SuperSpace","Folderish"],"changeToken":"1389302022063","contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZDY1MmY='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZDY1MmY='}, cookies [] and JSON payload '{"params": {"value": "530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","title":"Nuxeo Drive Test Workspace","lastModified":"2014-01-09T21:13:42.06Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-01-09T21:13:42.06Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:42.06Z","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":["WebView","SuperSpace","Folderish"],"changeToken":"1389302022063","contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='}, cookies [] and JSON payload '{"params": {"value": "530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","title":"Nuxeo Drive Test Workspace","lastModified":"2014-01-09T21:13:42.06Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-01-09T21:13:42.06Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:42.06Z","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":["WebView","SuperSpace","Folderish"],"changeToken":"1389302022063","contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZDY1MmY='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZDY1MmY='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=e8f31f06797211e3b0f1d067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmZDY1MmY='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Got token '19a35d5d-44e5-4960-9671-848be696857c' with cookies []
22:14:13 nxdrive.controller: INFO: Binding '/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1'
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies [] and JSON payload: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":206,"folder":true,"creator":"system","parentId":null,"lastModificationDate":206,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
22:14:13 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-01-09 22:13:42.208744
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=ea84b32a797211e3b0f1d067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '1.2-dev', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Got token '92a7cf9c-79b3-4609-8dac-74898986aeb6' with cookies []
22:14:13 nxdrive.controller: INFO: Binding '/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_2'
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies [] and JSON payload: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":377,"folder":true,"creator":"system","parentId":null,"lastModificationDate":377,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
22:14:13 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-01-09 22:13:42.379346
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'19a35d5d-44e5-4960-9671-848be696857c', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:530b2ae0-c677-4dcd-aa9e-f00caebd34ad', 'params': {'enable': True}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"input": "doc:530b2ae0-c677-4dcd-aa9e-f00caebd34ad", "params": {"enable": true}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] and content-type: ''
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'} and cookies []
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:530b2ae0-c677-4dcd-aa9e-f00caebd34ad', 'params': {'enable': True}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"input": "doc:530b2ae0-c677-4dcd-aa9e-f00caebd34ad", "params": {"enable": true}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] and content-type: ''
22:14:13 nxdrive.synchronizer: INFO: Starting synchronization (pid=25788)
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[],"syncDate":1389302022000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.synchronizer: DEBUG: Remote full scan of /tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":844,"folder":true,"creator":"system","parentId":null,"lastModificationDate":844,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_1"}'
22:14:13 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'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'])
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-01-09 22:13:42'
22:14:13 nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-01-09 22:13:42 and updated last_sync_date to 2014-01-09 22:13:42.869640
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='unknown', pair_state='unknown'>
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([])
22:14:13 nxdrive.model: TRACE: Selecting paths set([])
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-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'>
22:14:13 nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive/'
22:14:13 nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([])
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-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'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.157s, remote: 0.145s sync: 0.187s
22:14:13 nxdrive.synchronizer: INFO: Stopping synchronization after 1 loops
22:14:13 nxdrive.synchronizer: INFO: Starting synchronization (pid=25788)
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[],"syncDate":1389302023000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.synchronizer: DEBUG: Remote full scan of /tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":341,"folder":true,"creator":"system","parentId":null,"lastModificationDate":341,"canRename":false,"canDelete":false,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 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'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'])
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-01-09 22:13:42'
22:14:13 nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-01-09 22:13:42 and updated last_sync_date to 2014-01-09 22:13:43.366303
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='unknown', pair_state='unknown'>
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([])
22:14:13 nxdrive.model: TRACE: Selecting paths set([])
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-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'>
22:14:13 nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive/'
22:14:13 nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([])
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-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'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.086s, remote: 0.183s sync: 0.177s
22:14:13 nxdrive.synchronizer: INFO: Stopping synchronization after 1 loops
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'delay': '3.0'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetVersioningOptions with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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": {"delay": "3.0"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetVersioningOptions' with cookies [] and content-type: ''
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lastSyncDate': 1389302022000L, 'lastSyncActiveRootDefinitions': u'default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"lastSyncDate": 1389302022000, "lastSyncActiveRootDefinitions": "default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[{"eventId":"rootRegistered","eventDate":1389302022815,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","fileSystemItemName":"Nuxeo Drive Test Workspace","docUuid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad"},{"eventId":"rootRegistered","eventDate":1389302022781,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","fileSystemItemName":"Nuxeo Drive Test Workspace","docUuid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad"},{"eventId":"documentCreated","eventDate":1389302022063,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","creationDate":1389302022063,"folder":true,"creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1389302022813,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","fileSystemItemName":"Nuxeo Drive Test Workspace","docUuid":"530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}],"syncDate":1389302023000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.synchronizer: DEBUG: 3 remote changes detected on http://localhost:8080/nuxeo/
22:14:13 nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair 'Nuxeo Drive Test Workspace'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:42', '2014-01-09 22:13:42'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies [] and JSON payload: '[]'
22:14:13 nxdrive.model: TRACE: Selecting refs set([])
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace'])
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace/Test versioning.txt'])
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.synchronizer: DEBUG: Detected a new non-alignable local file at /Nuxeo Drive Test Workspace/Test versioning.txt
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=None, local_state='created', remote_state=u'unknown', pair_state='locally_created'>
22:14:13 nxdrive.synchronizer: DEBUG: Creating remote document 'Test versioning.txt' in folder 'Nuxeo Drive Test Workspace'
22:14:13 nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 17, 'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 17, 'Cache-Control': 'no-cache', 'X-Batch-Id': '1389302027.87_37354016', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Test%20versioning.txt', 'X-Client-Version': '1.2-dev'} and cookies [] for file /tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Test versioning.txt
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies [] and JSON payload: '{"uploaded":"true","batchId":"1389302027.87_37354016"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1389302027.87_37354016', 'operationId': 'NuxeoDrive.CreateFile', 'fileIdx': '0', 'parentId': u'defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"batchId": "1389302027.87_37354016", "operationId": "NuxeoDrive.CreateFile", "fileIdx": "0", "parentId": "defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] and JSON payload: '{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '19a35d5d-44e5-4960-9671-848be696857c', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'e8f31f06797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', '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.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_1"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-01-09 22:13:47'
22:14:13 nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-01-09 22:13:47 and updated last_sync_date to 2014-01-09 22:13:47.896317
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpBxoTeC-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.202s, remote: 0.052s sync: 3.987s
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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/Test versioning.txt"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt","type":"Note","state":"project","versionLabel":"0.0","title":"Test versioning.txt","lastModified":"2014-01-09T21:13:47.88Z","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-01-09T21:13:47.88Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:47.88Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test versioning.txt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/note.gif","common:icon-expanded":null,"common:size":null,"relatedtext:relatedtextresources":[],"note:mime_type":"text/plain","note:note":"This is version 0"},"facets":["Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1389302027883","contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo2ZGI1N2Q='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies [] and JSON payload: '{"entity-type":"documents","entries":[{"entity-type":"document","repository":"default","uid":"37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt","type":"Note","state":"project","versionLabel":"0.0","title":"Test versioning.txt","lastModified":"2014-01-09T21:13:47.88Z","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-01-09T21:13:47.88Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:47.88Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test versioning.txt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/note.gif","common:icon-expanded":null,"common:size":null,"relatedtext:relatedtextresources":[],"note:mime_type":"text/plain","note:note":"This is version 0"},"facets":["Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1389302027883","contextParameters":{}}]}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lastSyncDate': 1389302023000L, 'lastSyncActiveRootDefinitions': u'default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"lastSyncDate": 1389302023000, "lastSyncActiveRootDefinitions": "default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[{"eventId":"documentCreated","eventDate":1389302027883,"repositoryId":"default","fileSystemItem":{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"},"fileSystemItemId":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","fileSystemItemName":"Test versioning.txt","docUuid":"37616c1e-0db4-4dba-9c3a-8afcaef68377"}],"syncDate":1389302029000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.synchronizer: DEBUG: 1 remote changes detected on http://localhost:8080/nuxeo/
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-01-09 22:13:47'
22:14:13 nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-01-09 22:13:47 and updated last_sync_date to 2014-01-09 22:13:49.059969
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Test versioning.txt', local_state=None, remote_state=None, pair_state='unknown'>
22:14:13 nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Test versioning.txt', local_state='unknown', remote_state='unknown', pair_state='unknown'>
22:14:13 nxdrive.synchronizer: DEBUG: Marked doc_pair 'Test versioning.txt' as remote creation
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace'])
22:14:13 nxdrive.model: TRACE: Selecting paths set([])
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:47', '2014-01-09 22:13:47'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=None, remote_name=u'Test versioning.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
22:14:13 nxdrive.synchronizer: DEBUG: Creating local file 'Test versioning.txt' in '/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive/Nuxeo Drive Test Workspace'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt' with headers: {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.223s, remote: 0.031s sync: 0.196s
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lastSyncDate': 1389302029000L, 'lastSyncActiveRootDefinitions': u'default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"lastSyncDate": 1389302029000, "lastSyncActiveRootDefinitions": "default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[],"syncDate":1389302030000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace'])
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace/Test versioning.txt'])
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='modified', remote_state=u'synchronized', pair_state='locally_modified'>
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"7478332418db013987d536800f45c487","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302027883,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:47', '2014-01-09 22:13:47'
22:14:13 nxdrive.synchronizer: DEBUG: Updating remote document 'Test versioning.txt'.
22:14:13 nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 16, 'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'X-File-Size': 16, 'Cache-Control': 'no-cache', 'X-Batch-Id': '1389302033.28_972314353', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Test%20versioning.txt', 'X-Client-Version': '1.2-dev'} and cookies [] for file /tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive/Nuxeo Drive Test Workspace/Test versioning.txt
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies [] and JSON payload: '{"uploaded":"true","batchId":"1389302033.28_972314353"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1389302033.28_972314353', 'fileIdx': '0', 'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377', 'operationId': 'NuxeoDrive.UpdateFile'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"batchId": "1389302033.28_972314353", "fileIdx": "0", "id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377", "operationId": "NuxeoDrive.UpdateFile"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] and JSON payload: '{"digest":"f1be24ba743909ec1cf116526fd3491e","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302033301,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"f1be24ba743909ec1cf116526fd3491e","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302033301,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:47', '2014-01-09 22:13:53'
22:14:13 nxdrive.model: TRACE: Doc Test versioning.txt has been either modified, renamed, moved or restored from the trash, set last_remote_updated to 2014-01-09 22:13:53
22:14:13 nxdrive.model: TRACE: Doc Test versioning.txt is a file that has been renamed, moved, for which the content has been updated or restored from the trash, set remote_state to 'modified'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state=u'modified', remote_state='modified', pair_state='conflicted'>
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 2.752s, remote: 0.016s sync: 0.436s
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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/Test versioning.txt"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt","type":"Note","state":"project","versionLabel":"0.1+","title":"Test versioning.txt","lastModified":"2014-01-09T21:13:53.30Z","properties":{"uid:uid":null,"uid:minor_version":"1","uid:major_version":"0","dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1","nuxeoDriveTestUser_user_2"],"dc:nature":null,"dc:created":"2014-01-09T21:13:47.88Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:53.30Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test versioning.txt","dc:lastContributor":"nuxeoDriveTestUser_user_2","files:files":[],"common:icon":"/icons/note.gif","common:icon-expanded":null,"common:size":null,"relatedtext:relatedtextresources":[],"note:mime_type":"text/plain","note:note":"Modified content"},"facets":["Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1389302033301","contextParameters":{}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lastSyncDate': 1389302030000L, 'lastSyncActiveRootDefinitions': u'default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"lastSyncDate": 1389302030000, "lastSyncActiveRootDefinitions": "default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies [] and JSON payload: '{"fileSystemChanges":[{"eventId":"documentModified","eventDate":1389302033301,"repositoryId":"default","fileSystemItem":{"digest":"f1be24ba743909ec1cf116526fd3491e","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302033301,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"},"fileSystemItemId":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","fileSystemItemName":"Test versioning.txt","docUuid":"37616c1e-0db4-4dba-9c3a-8afcaef68377"},{"eventId":"documentModified","eventDate":1389302033300,"repositoryId":"default","fileSystemItem":{"digest":"f1be24ba743909ec1cf116526fd3491e","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302033301,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"},"fileSystemItemId":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","fileSystemItemName":"Test versioning.txt","docUuid":"37616c1e-0db4-4dba-9c3a-8afcaef68377"}],"syncDate":1389302034000,"activeSynchronizationRootDefinitions":"default:530b2ae0-c677-4dcd-aa9e-f00caebd34ad","hasTooManyChanges":false}'
22:14:13 nxdrive.synchronizer: DEBUG: 2 remote changes detected on http://localhost:8080/nuxeo/
22:14:13 nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair 'Test versioning.txt'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:53', '2014-01-09 22:13:53'
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace'])
22:14:13 nxdrive.model: TRACE: Selecting paths set([u'/Nuxeo Drive Test Workspace/Test versioning.txt'])
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='modified', remote_state=u'synchronized', pair_state='locally_modified'>
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"f1be24ba743909ec1cf116526fd3491e","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302033301,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:53', '2014-01-09 22:13:53'
22:14:13 nxdrive.synchronizer: DEBUG: Updating remote document 'Test versioning.txt'.
22:14:13 nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 22, 'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'X-File-Size': 22, 'Cache-Control': 'no-cache', 'X-Batch-Id': '1389302037.91_958915765', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Test%20versioning.txt', 'X-Client-Version': '1.2-dev'} and cookies [] for file /tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive/Nuxeo Drive Test Workspace/Test versioning.txt
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies [] and JSON payload: '{"uploaded":"true","batchId":"1389302037.91_958915765"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1389302037.91_958915765', 'fileIdx': '0', 'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377', 'operationId': 'NuxeoDrive.UpdateFile'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"batchId": "1389302037.91_958915765", "fileIdx": "0", "id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377", "operationId": "NuxeoDrive.UpdateFile"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] and JSON payload: '{"digest":"69b91bfa1185eafb006f0f4f3787ec18","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302037937,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '92a7cf9c-79b3-4609-8dac-74898986aeb6', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'ea84b32a797211e3b0f1d067e5f2a1a2', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.2-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies [] and JSON payload: '{"digest":"69b91bfa1185eafb006f0f4f3787ec18","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/37616c1e-0db4-4dba-9c3a-8afcaef68377/blobholder:0/Test%20versioning.txt","canUpdate":true,"name":"Test versioning.txt","id":"defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad/defaultFileSystemItemFactory#default#37616c1e-0db4-4dba-9c3a-8afcaef68377","creationDate":1389302027883,"folder":false,"creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#530b2ae0-c677-4dcd-aa9e-f00caebd34ad","lastModificationDate":1389302037937,"canRename":true,"canDelete":true,"userName":"nuxeoDriveTestUser_user_2"}'
22:14:13 nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-01-09 22:13:53', '2014-01-09 22:13:57'
22:14:13 nxdrive.model: TRACE: Doc Test versioning.txt has been either modified, renamed, moved or restored from the trash, set last_remote_updated to 2014-01-09 22:13:57
22:14:13 nxdrive.model: TRACE: Doc Test versioning.txt is a file that has been renamed, moved, for which the content has been updated or restored from the trash, set remote_state to 'modified'
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state=u'modified', remote_state='modified', pair_state='conflicted'>
22:14:13 nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Test versioning.txt', remote_name=u'Test versioning.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
22:14:13 nxdrive.synchronizer: DEBUG: [/tmp/tmpscOWaS-nxdrive-tests-user-2/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 3.161s, remote: 0.033s sync: 0.174s
22:14:13 nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt'}}
22:14:13 nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.2-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', '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/Test versioning.txt"}}'
22:14:13 nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies [] and JSON payload: '{"entity-type":"document","repository":"default","uid":"37616c1e-0db4-4dba-9c3a-8afcaef68377","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Test versioning.txt","type":"Note","state":"project","versionLabel":"0.2+","title":"Test versioning.txt","lastModified":"2014-01-09T21:13:57.93Z","properties":{"uid:uid":null,"uid:minor_version":"2","uid:major_version":"0","dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1","nuxeoDriveTestUser_user_2"],"dc:nature":null,"dc:created":"2014-01-09T21:13:47.88Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-01-09T21:13:57.93Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Test versioning.txt","dc:lastContributor":"nuxeoDriveTestUser_user_2","files:files":[],"common:icon":"/icons/note.gif","common:icon-expanded":null,"common:size":null,"relatedtext:relatedtextresources":[],"note:mime_type":"text/plain","note:note":"Content twice modified"},"facets":["Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1389302037937","contextParameters":{}}'
22:14:13 --------------------- >> end captured logging << ---------------------